Loading...
1#!/usr/bin/env python3
2# SPDX-License-Identifier: GPL-2.0-only
3#
4# Tool for analyzing boot timing
5# Copyright (c) 2013, Intel Corporation.
6#
7# This program is free software; you can redistribute it and/or modify it
8# under the terms and conditions of the GNU General Public License,
9# version 2, as published by the Free Software Foundation.
10#
11# This program is distributed in the hope it will be useful, but WITHOUT
12# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
13# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
14# more details.
15#
16# Authors:
17# Todd Brandt <todd.e.brandt@linux.intel.com>
18#
19# Description:
20# This tool is designed to assist kernel and OS developers in optimizing
21# their linux stack's boot time. It creates an html representation of
22# the kernel boot timeline up to the start of the init process.
23#
24
25# ----------------- LIBRARIES --------------------
26
27import sys
28import time
29import os
30import string
31import re
32import platform
33import shutil
34from datetime import datetime, timedelta
35from subprocess import call, Popen, PIPE
36import sleepgraph as aslib
37
38def pprint(msg):
39 print(msg)
40 sys.stdout.flush()
41
42# ----------------- CLASSES --------------------
43
44# Class: SystemValues
45# Description:
46# A global, single-instance container used to
47# store system values and test parameters
48class SystemValues(aslib.SystemValues):
49 title = 'BootGraph'
50 version = '2.2'
51 hostname = 'localhost'
52 testtime = ''
53 kernel = ''
54 dmesgfile = ''
55 ftracefile = ''
56 htmlfile = 'bootgraph.html'
57 testdir = ''
58 kparams = ''
59 result = ''
60 useftrace = False
61 usecallgraph = False
62 suspendmode = 'boot'
63 max_graph_depth = 2
64 graph_filter = 'do_one_initcall'
65 reboot = False
66 manual = False
67 iscronjob = False
68 timeformat = '%.6f'
69 bootloader = 'grub'
70 blexec = []
71 def __init__(self):
72 self.kernel, self.hostname = 'unknown', platform.node()
73 self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')
74 if os.path.exists('/proc/version'):
75 fp = open('/proc/version', 'r')
76 self.kernel = self.kernelVersion(fp.read().strip())
77 fp.close()
78 self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')
79 def kernelVersion(self, msg):
80 m = re.match('^[Ll]inux *[Vv]ersion *(?P<v>\S*) .*', msg)
81 if m:
82 return m.group('v')
83 return 'unknown'
84 def checkFtraceKernelVersion(self):
85 m = re.match('^(?P<x>[0-9]*)\.(?P<y>[0-9]*)\.(?P<z>[0-9]*).*', self.kernel)
86 if m:
87 val = tuple(map(int, m.groups()))
88 if val >= (4, 10, 0):
89 return True
90 return False
91 def kernelParams(self):
92 cmdline = 'initcall_debug log_buf_len=32M'
93 if self.useftrace:
94 if self.cpucount > 0:
95 bs = min(self.memtotal // 2, 2*1024*1024) // self.cpucount
96 else:
97 bs = 131072
98 cmdline += ' trace_buf_size=%dK trace_clock=global '\
99 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\
100 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\
101 'nofuncgraph-overhead,context-info,graph-time '\
102 'ftrace=function_graph '\
103 'ftrace_graph_max_depth=%d '\
104 'ftrace_graph_filter=%s' % \
105 (bs, self.max_graph_depth, self.graph_filter)
106 return cmdline
107 def setGraphFilter(self, val):
108 master = self.getBootFtraceFilterFunctions()
109 fs = ''
110 for i in val.split(','):
111 func = i.strip()
112 if func == '':
113 doError('badly formatted filter function string')
114 if '[' in func or ']' in func:
115 doError('loadable module functions not allowed - "%s"' % func)
116 if ' ' in func:
117 doError('spaces found in filter functions - "%s"' % func)
118 if func not in master:
119 doError('function "%s" not available for ftrace' % func)
120 if not fs:
121 fs = func
122 else:
123 fs += ','+func
124 if not fs:
125 doError('badly formatted filter function string')
126 self.graph_filter = fs
127 def getBootFtraceFilterFunctions(self):
128 self.rootCheck(True)
129 fp = open(self.tpath+'available_filter_functions')
130 fulllist = fp.read().split('\n')
131 fp.close()
132 list = []
133 for i in fulllist:
134 if not i or ' ' in i or '[' in i or ']' in i:
135 continue
136 list.append(i)
137 return list
138 def myCronJob(self, line):
139 if '@reboot' not in line:
140 return False
141 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:
142 return True
143 return False
144 def cronjobCmdString(self):
145 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
146 args = iter(sys.argv[1:])
147 for arg in args:
148 if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
149 continue
150 elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
151 next(args)
152 continue
153 elif arg == '-result':
154 cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args)))
155 continue
156 elif arg == '-cgskip':
157 file = self.configFile(next(args))
158 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
159 continue
160 cmdline += ' '+arg
161 if self.graph_filter != 'do_one_initcall':
162 cmdline += ' -func "%s"' % self.graph_filter
163 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)
164 return cmdline
165 def manualRebootRequired(self):
166 cmdline = self.kernelParams()
167 pprint('To generate a new timeline manually, follow these steps:\n\n'\
168 '1. Add the CMDLINE string to your kernel command line.\n'\
169 '2. Reboot the system.\n'\
170 '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\
171 'CMDLINE="%s"' % cmdline)
172 sys.exit()
173 def blGrub(self):
174 blcmd = ''
175 for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
176 if blcmd:
177 break
178 blcmd = self.getExec(cmd)
179 if not blcmd:
180 doError('[GRUB] missing update command')
181 if not os.path.exists('/etc/default/grub'):
182 doError('[GRUB] missing /etc/default/grub')
183 if 'grub2' in blcmd:
184 cfg = '/boot/grub2/grub.cfg'
185 else:
186 cfg = '/boot/grub/grub.cfg'
187 if not os.path.exists(cfg):
188 doError('[GRUB] missing %s' % cfg)
189 if 'update-grub' in blcmd:
190 self.blexec = [blcmd]
191 else:
192 self.blexec = [blcmd, '-o', cfg]
193 def getBootLoader(self):
194 if self.bootloader == 'grub':
195 self.blGrub()
196 else:
197 doError('unknown boot loader: %s' % self.bootloader)
198 def writeDatafileHeader(self, filename):
199 self.kparams = open('/proc/cmdline', 'r').read().strip()
200 fp = open(filename, 'w')
201 fp.write(self.teststamp+'\n')
202 fp.write(self.sysstamp+'\n')
203 fp.write('# command | %s\n' % self.cmdline)
204 fp.write('# kparams | %s\n' % self.kparams)
205 fp.close()
206
207sysvals = SystemValues()
208
209# Class: Data
210# Description:
211# The primary container for test data.
212class Data(aslib.Data):
213 dmesg = {} # root data structure
214 start = 0.0 # test start
215 end = 0.0 # test end
216 dmesgtext = [] # dmesg text file in memory
217 testnumber = 0
218 idstr = ''
219 html_device_id = 0
220 valid = False
221 tUserMode = 0.0
222 boottime = ''
223 phases = ['kernel', 'user']
224 do_one_initcall = False
225 def __init__(self, num):
226 self.testnumber = num
227 self.idstr = 'a'
228 self.dmesgtext = []
229 self.dmesg = {
230 'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
231 'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'},
232 'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
233 'order': 1, 'color': '#fff'}
234 }
235 def deviceTopology(self):
236 return ''
237 def newAction(self, phase, name, pid, start, end, ret, ulen):
238 # new device callback for a specific phase
239 self.html_device_id += 1
240 devid = '%s%d' % (self.idstr, self.html_device_id)
241 list = self.dmesg[phase]['list']
242 length = -1.0
243 if(start >= 0 and end >= 0):
244 length = end - start
245 i = 2
246 origname = name
247 while(name in list):
248 name = '%s[%d]' % (origname, i)
249 i += 1
250 list[name] = {'name': name, 'start': start, 'end': end,
251 'pid': pid, 'length': length, 'row': 0, 'id': devid,
252 'ret': ret, 'ulen': ulen }
253 return name
254 def deviceMatch(self, pid, cg):
255 if cg.end - cg.start == 0:
256 return ''
257 for p in data.phases:
258 list = self.dmesg[p]['list']
259 for devname in list:
260 dev = list[devname]
261 if pid != dev['pid']:
262 continue
263 if cg.name == 'do_one_initcall':
264 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
265 dev['ftrace'] = cg
266 self.do_one_initcall = True
267 return devname
268 else:
269 if(cg.start > dev['start'] and cg.end < dev['end']):
270 if 'ftraces' not in dev:
271 dev['ftraces'] = []
272 dev['ftraces'].append(cg)
273 return devname
274 return ''
275 def printDetails(self):
276 sysvals.vprint('Timeline Details:')
277 sysvals.vprint(' Host: %s' % sysvals.hostname)
278 sysvals.vprint(' Kernel: %s' % sysvals.kernel)
279 sysvals.vprint(' Test time: %s' % sysvals.testtime)
280 sysvals.vprint(' Boot time: %s' % self.boottime)
281 for phase in self.phases:
282 dc = len(self.dmesg[phase]['list'])
283 sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,
284 self.dmesg[phase]['start']*1000,
285 self.dmesg[phase]['end']*1000, dc))
286
287# ----------------- FUNCTIONS --------------------
288
289# Function: parseKernelLog
290# Description:
291# parse a kernel log for boot data
292def parseKernelLog():
293 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
294 os.path.basename(sysvals.dmesgfile))
295 phase = 'kernel'
296 data = Data(0)
297 data.dmesg['kernel']['start'] = data.start = ktime = 0.0
298 sysvals.stamp = {
299 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
300 'host': sysvals.hostname,
301 'mode': 'boot', 'kernel': ''}
302
303 tp = aslib.TestProps()
304 devtemp = dict()
305 if(sysvals.dmesgfile):
306 lf = open(sysvals.dmesgfile, 'rb')
307 else:
308 lf = Popen('dmesg', stdout=PIPE).stdout
309 for line in lf:
310 line = aslib.ascii(line).replace('\r\n', '')
311 # grab the stamp and sysinfo
312 if re.match(tp.stampfmt, line):
313 tp.stamp = line
314 continue
315 elif re.match(tp.sysinfofmt, line):
316 tp.sysinfo = line
317 continue
318 elif re.match(tp.cmdlinefmt, line):
319 tp.cmdline = line
320 continue
321 elif re.match(tp.kparamsfmt, line):
322 tp.kparams = line
323 continue
324 idx = line.find('[')
325 if idx > 1:
326 line = line[idx:]
327 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
328 if(not m):
329 continue
330 ktime = float(m.group('ktime'))
331 if(ktime > 120):
332 break
333 msg = m.group('msg')
334 data.dmesgtext.append(line)
335 if(ktime == 0.0 and re.match('^Linux version .*', msg)):
336 if(not sysvals.stamp['kernel']):
337 sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
338 continue
339 m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg)
340 if(m):
341 bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S')
342 bt = bt - timedelta(seconds=int(ktime))
343 data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
344 sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
345 continue
346 m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
347 if(m):
348 func = m.group('f')
349 pid = int(m.group('p'))
350 devtemp[func] = (ktime, pid)
351 continue
352 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
353 if(m):
354 data.valid = True
355 data.end = ktime
356 f, r, t = m.group('f', 'r', 't')
357 if(f in devtemp):
358 start, pid = devtemp[f]
359 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
360 del devtemp[f]
361 continue
362 if(re.match('^Freeing unused kernel .*', msg)):
363 data.tUserMode = ktime
364 data.dmesg['kernel']['end'] = ktime
365 data.dmesg['user']['start'] = ktime
366 phase = 'user'
367
368 if tp.stamp:
369 sysvals.stamp = 0
370 tp.parseStamp(data, sysvals)
371 data.dmesg['user']['end'] = data.end
372 lf.close()
373 return data
374
375# Function: parseTraceLog
376# Description:
377# Check if trace is available and copy to a temp file
378def parseTraceLog(data):
379 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
380 os.path.basename(sysvals.ftracefile))
381 # if available, calculate cgfilter allowable ranges
382 cgfilter = []
383 if len(sysvals.cgfilter) > 0:
384 for p in data.phases:
385 list = data.dmesg[p]['list']
386 for i in sysvals.cgfilter:
387 if i in list:
388 cgfilter.append([list[i]['start']-0.0001,
389 list[i]['end']+0.0001])
390 # parse the trace log
391 ftemp = dict()
392 tp = aslib.TestProps()
393 tp.setTracerType('function_graph')
394 tf = open(sysvals.ftracefile, 'r')
395 for line in tf:
396 if line[0] == '#':
397 continue
398 m = re.match(tp.ftrace_line_fmt, line.strip())
399 if(not m):
400 continue
401 m_time, m_proc, m_pid, m_msg, m_dur = \
402 m.group('time', 'proc', 'pid', 'msg', 'dur')
403 t = float(m_time)
404 if len(cgfilter) > 0:
405 allow = False
406 for r in cgfilter:
407 if t >= r[0] and t < r[1]:
408 allow = True
409 break
410 if not allow:
411 continue
412 if t > data.end:
413 break
414 if(m_time and m_pid and m_msg):
415 t = aslib.FTraceLine(m_time, m_msg, m_dur)
416 pid = int(m_pid)
417 else:
418 continue
419 if t.fevent or t.fkprobe:
420 continue
421 key = (m_proc, pid)
422 if(key not in ftemp):
423 ftemp[key] = []
424 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
425 cg = ftemp[key][-1]
426 res = cg.addLine(t)
427 if(res != 0):
428 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
429 if(res == -1):
430 ftemp[key][-1].addLine(t)
431
432 tf.close()
433
434 # add the callgraph data to the device hierarchy
435 for key in ftemp:
436 proc, pid = key
437 for cg in ftemp[key]:
438 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
439 continue
440 if(not cg.postProcess()):
441 pprint('Sanity check failed for %s-%d' % (proc, pid))
442 continue
443 # match cg data to devices
444 devname = data.deviceMatch(pid, cg)
445 if not devname:
446 kind = 'Orphan'
447 if cg.partial:
448 kind = 'Partial'
449 sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\
450 (kind, cg.name, proc, pid, cg.start, cg.end))
451 elif len(cg.list) > 1000000:
452 pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\
453 (devname, len(cg.list)))
454
455# Function: retrieveLogs
456# Description:
457# Create copies of dmesg and/or ftrace for later processing
458def retrieveLogs():
459 # check ftrace is configured first
460 if sysvals.useftrace:
461 tracer = sysvals.fgetVal('current_tracer').strip()
462 if tracer != 'function_graph':
463 doError('ftrace not configured for a boot callgraph')
464 # create the folder and get dmesg
465 sysvals.systemInfo(aslib.dmidecode(sysvals.mempath))
466 sysvals.initTestOutput('boot')
467 sysvals.writeDatafileHeader(sysvals.dmesgfile)
468 call('dmesg >> '+sysvals.dmesgfile, shell=True)
469 if not sysvals.useftrace:
470 return
471 # get ftrace
472 sysvals.writeDatafileHeader(sysvals.ftracefile)
473 call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)
474
475# Function: colorForName
476# Description:
477# Generate a repeatable color from a list for a given name
478def colorForName(name):
479 list = [
480 ('c1', '#ec9999'),
481 ('c2', '#ffc1a6'),
482 ('c3', '#fff0a6'),
483 ('c4', '#adf199'),
484 ('c5', '#9fadea'),
485 ('c6', '#a699c1'),
486 ('c7', '#ad99b4'),
487 ('c8', '#eaffea'),
488 ('c9', '#dcecfb'),
489 ('c10', '#ffffea')
490 ]
491 i = 0
492 total = 0
493 count = len(list)
494 while i < len(name):
495 total += ord(name[i])
496 i += 1
497 return list[total % count]
498
499def cgOverview(cg, minlen):
500 stats = dict()
501 large = []
502 for l in cg.list:
503 if l.fcall and l.depth == 1:
504 if l.length >= minlen:
505 large.append(l)
506 if l.name not in stats:
507 stats[l.name] = [0, 0.0]
508 stats[l.name][0] += (l.length * 1000.0)
509 stats[l.name][1] += 1
510 return (large, stats)
511
512# Function: createBootGraph
513# Description:
514# Create the output html file from the resident test data
515# Arguments:
516# testruns: array of Data objects from parseKernelLog or parseTraceLog
517# Output:
518# True if the html file was created, false if it failed
519def createBootGraph(data):
520 # html function templates
521 html_srccall = '<div id={6} title="{5}" class="srccall" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{0}</div>\n'
522 html_timetotal = '<table class="time1">\n<tr>'\
523 '<td class="blue">Init process starts @ <b>{0} ms</b></td>'\
524 '<td class="blue">Last initcall ends @ <b>{1} ms</b></td>'\
525 '</tr>\n</table>\n'
526
527 # device timeline
528 devtl = aslib.Timeline(100, 20)
529
530 # write the test title and general info header
531 devtl.createHeader(sysvals, sysvals.stamp)
532
533 # Generate the header for this timeline
534 t0 = data.start
535 tMax = data.end
536 tTotal = tMax - t0
537 if(tTotal == 0):
538 pprint('ERROR: No timeline data')
539 return False
540 user_mode = '%.0f'%(data.tUserMode*1000)
541 last_init = '%.0f'%(tTotal*1000)
542 devtl.html += html_timetotal.format(user_mode, last_init)
543
544 # determine the maximum number of rows we need to draw
545 devlist = []
546 for p in data.phases:
547 list = data.dmesg[p]['list']
548 for devname in list:
549 d = aslib.DevItem(0, p, list[devname])
550 devlist.append(d)
551 devtl.getPhaseRows(devlist, 0, 'start')
552 devtl.calcTotalRows()
553
554 # draw the timeline background
555 devtl.createZoomBox()
556 devtl.html += devtl.html_tblock.format('boot', '0', '100', devtl.scaleH)
557 for p in data.phases:
558 phase = data.dmesg[p]
559 length = phase['end']-phase['start']
560 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
561 width = '%.3f' % ((length*100.0)/tTotal)
562 devtl.html += devtl.html_phase.format(left, width, \
563 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
564 phase['color'], '')
565
566 # draw the device timeline
567 num = 0
568 devstats = dict()
569 for phase in data.phases:
570 list = data.dmesg[phase]['list']
571 for devname in sorted(list):
572 cls, color = colorForName(devname)
573 dev = list[devname]
574 info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0,
575 dev['ulen']/1000.0, dev['ret'])
576 devstats[dev['id']] = {'info':info}
577 dev['color'] = color
578 height = devtl.phaseRowHeight(0, phase, dev['row'])
579 top = '%.6f' % ((dev['row']*height) + devtl.scaleH)
580 left = '%.6f' % (((dev['start']-t0)*100)/tTotal)
581 width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal)
582 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
583 devtl.html += devtl.html_device.format(dev['id'],
584 devname+length+phase+'_mode', left, top, '%.3f'%height,
585 width, devname, ' '+cls, '')
586 rowtop = devtl.phaseRowTop(0, phase, dev['row'])
587 height = '%.6f' % (devtl.rowH / 2)
588 top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2))
589 if data.do_one_initcall:
590 if('ftrace' not in dev):
591 continue
592 cg = dev['ftrace']
593 large, stats = cgOverview(cg, 0.001)
594 devstats[dev['id']]['fstat'] = stats
595 for l in large:
596 left = '%f' % (((l.time-t0)*100)/tTotal)
597 width = '%f' % (l.length*100/tTotal)
598 title = '%s (%0.3fms)' % (l.name, l.length * 1000.0)
599 devtl.html += html_srccall.format(l.name, left,
600 top, height, width, title, 'x%d'%num)
601 num += 1
602 continue
603 if('ftraces' not in dev):
604 continue
605 for cg in dev['ftraces']:
606 left = '%f' % (((cg.start-t0)*100)/tTotal)
607 width = '%f' % ((cg.end-cg.start)*100/tTotal)
608 cglen = (cg.end - cg.start) * 1000.0
609 title = '%s (%0.3fms)' % (cg.name, cglen)
610 cg.id = 'x%d' % num
611 devtl.html += html_srccall.format(cg.name, left,
612 top, height, width, title, dev['id']+cg.id)
613 num += 1
614
615 # draw the time scale, try to make the number of labels readable
616 devtl.createTimeScale(t0, tMax, tTotal, 'boot')
617 devtl.html += '</div>\n'
618
619 # timeline is finished
620 devtl.html += '</div>\n</div>\n'
621
622 # draw a legend which describes the phases by color
623 devtl.html += '<div class="legend">\n'
624 pdelta = 20.0
625 pmargin = 36.0
626 for phase in data.phases:
627 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
628 devtl.html += devtl.html_legend.format(order, \
629 data.dmesg[phase]['color'], phase+'_mode', phase[0])
630 devtl.html += '</div>\n'
631
632 hf = open(sysvals.htmlfile, 'w')
633
634 # add the css
635 extra = '\
636 .c1 {background:rgba(209,0,0,0.4);}\n\
637 .c2 {background:rgba(255,102,34,0.4);}\n\
638 .c3 {background:rgba(255,218,33,0.4);}\n\
639 .c4 {background:rgba(51,221,0,0.4);}\n\
640 .c5 {background:rgba(17,51,204,0.4);}\n\
641 .c6 {background:rgba(34,0,102,0.4);}\n\
642 .c7 {background:rgba(51,0,68,0.4);}\n\
643 .c8 {background:rgba(204,255,204,0.4);}\n\
644 .c9 {background:rgba(169,208,245,0.4);}\n\
645 .c10 {background:rgba(255,255,204,0.4);}\n\
646 .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\
647 table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\
648 .fstat th {width:55px;}\n\
649 .fstat td {text-align:left;width:35px;}\n\
650 .srccall {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
651 .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
652 aslib.addCSS(hf, sysvals, 1, False, extra)
653
654 # write the device timeline
655 hf.write(devtl.html)
656
657 # add boot specific html
658 statinfo = 'var devstats = {\n'
659 for n in sorted(devstats):
660 statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info'])
661 if 'fstat' in devstats[n]:
662 funcs = devstats[n]['fstat']
663 for f in sorted(funcs, key=lambda k:(funcs[k], k), reverse=True):
664 if funcs[f][0] < 0.01 and len(funcs) > 10:
665 break
666 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
667 statinfo += '\t],\n'
668 statinfo += '};\n'
669 html = \
670 '<div id="devicedetailtitle"></div>\n'\
671 '<div id="devicedetail" style="display:none;">\n'\
672 '<div id="devicedetail0">\n'
673 for p in data.phases:
674 phase = data.dmesg[p]
675 html += devtl.html_phaselet.format(p+'_mode', '0', '100', phase['color'])
676 html += '</div>\n</div>\n'\
677 '<script type="text/javascript">\n'+statinfo+\
678 '</script>\n'
679 hf.write(html)
680
681 # add the callgraph html
682 if(sysvals.usecallgraph):
683 aslib.addCallgraphs(sysvals, hf, data)
684
685 # add the test log as a hidden div
686 if sysvals.testlog and sysvals.logmsg:
687 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
688 # add the dmesg log as a hidden div
689 if sysvals.dmesglog:
690 hf.write('<div id="dmesglog" style="display:none;">\n')
691 for line in data.dmesgtext:
692 line = line.replace('<', '<').replace('>', '>')
693 hf.write(line)
694 hf.write('</div>\n')
695
696 # write the footer and close
697 aslib.addScriptCode(hf, [data])
698 hf.write('</body>\n</html>\n')
699 hf.close()
700 return True
701
702# Function: updateCron
703# Description:
704# (restore=False) Set the tool to run automatically on reboot
705# (restore=True) Restore the original crontab
706def updateCron(restore=False):
707 if not restore:
708 sysvals.rootUser(True)
709 crondir = '/var/spool/cron/crontabs/'
710 if not os.path.exists(crondir):
711 crondir = '/var/spool/cron/'
712 if not os.path.exists(crondir):
713 doError('%s not found' % crondir)
714 cronfile = crondir+'root'
715 backfile = crondir+'root-analyze_boot-backup'
716 cmd = sysvals.getExec('crontab')
717 if not cmd:
718 doError('crontab not found')
719 # on restore: move the backup cron back into place
720 if restore:
721 if os.path.exists(backfile):
722 shutil.move(backfile, cronfile)
723 call([cmd, cronfile])
724 return
725 # backup current cron and install new one with reboot
726 if os.path.exists(cronfile):
727 shutil.move(cronfile, backfile)
728 else:
729 fp = open(backfile, 'w')
730 fp.close()
731 res = -1
732 try:
733 fp = open(backfile, 'r')
734 op = open(cronfile, 'w')
735 for line in fp:
736 if not sysvals.myCronJob(line):
737 op.write(line)
738 continue
739 fp.close()
740 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
741 op.close()
742 res = call([cmd, cronfile])
743 except Exception as e:
744 pprint('Exception: %s' % str(e))
745 shutil.move(backfile, cronfile)
746 res = -1
747 if res != 0:
748 doError('crontab failed')
749
750# Function: updateGrub
751# Description:
752# update grub.cfg for all kernels with our parameters
753def updateGrub(restore=False):
754 # call update-grub on restore
755 if restore:
756 try:
757 call(sysvals.blexec, stderr=PIPE, stdout=PIPE,
758 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'})
759 except Exception as e:
760 pprint('Exception: %s\n' % str(e))
761 return
762 # extract the option and create a grub config without it
763 sysvals.rootUser(True)
764 tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
765 cmdline = ''
766 grubfile = '/etc/default/grub'
767 tempfile = '/etc/default/grub.analyze_boot'
768 shutil.move(grubfile, tempfile)
769 res = -1
770 try:
771 fp = open(tempfile, 'r')
772 op = open(grubfile, 'w')
773 cont = False
774 for line in fp:
775 line = line.strip()
776 if len(line) == 0 or line[0] == '#':
777 continue
778 opt = line.split('=')[0].strip()
779 if opt == tgtopt:
780 cmdline = line.split('=', 1)[1].strip('\\')
781 if line[-1] == '\\':
782 cont = True
783 elif cont:
784 cmdline += line.strip('\\')
785 if line[-1] != '\\':
786 cont = False
787 else:
788 op.write('%s\n' % line)
789 fp.close()
790 # if the target option value is in quotes, strip them
791 sp = '"'
792 val = cmdline.strip()
793 if val and (val[0] == '\'' or val[0] == '"'):
794 sp = val[0]
795 val = val.strip(sp)
796 cmdline = val
797 # append our cmd line options
798 if len(cmdline) > 0:
799 cmdline += ' '
800 cmdline += sysvals.kernelParams()
801 # write out the updated target option
802 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
803 op.close()
804 res = call(sysvals.blexec)
805 os.remove(grubfile)
806 except Exception as e:
807 pprint('Exception: %s' % str(e))
808 res = -1
809 # cleanup
810 shutil.move(tempfile, grubfile)
811 if res != 0:
812 doError('update grub failed')
813
814# Function: updateKernelParams
815# Description:
816# update boot conf for all kernels with our parameters
817def updateKernelParams(restore=False):
818 # find the boot loader
819 sysvals.getBootLoader()
820 if sysvals.bootloader == 'grub':
821 updateGrub(restore)
822
823# Function: doError Description:
824# generic error function for catastrphic failures
825# Arguments:
826# msg: the error message to print
827# help: True if printHelp should be called after, False otherwise
828def doError(msg, help=False):
829 if help == True:
830 printHelp()
831 pprint('ERROR: %s\n' % msg)
832 sysvals.outputResult({'error':msg})
833 sys.exit()
834
835# Function: printHelp
836# Description:
837# print out the help text
838def printHelp():
839 pprint('\n%s v%s\n'\
840 'Usage: bootgraph <options> <command>\n'\
841 '\n'\
842 'Description:\n'\
843 ' This tool reads in a dmesg log of linux kernel boot and\n'\
844 ' creates an html representation of the boot timeline up to\n'\
845 ' the start of the init process.\n'\
846 '\n'\
847 ' If no specific command is given the tool reads the current dmesg\n'\
848 ' and/or ftrace log and creates a timeline\n'\
849 '\n'\
850 ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\
851 ' HTML output: <hostname>_boot.html\n'\
852 ' raw dmesg output: <hostname>_boot_dmesg.txt\n'\
853 ' raw ftrace output: <hostname>_boot_ftrace.txt\n'\
854 '\n'\
855 'Options:\n'\
856 ' -h Print this help text\n'\
857 ' -v Print the current tool version\n'\
858 ' -verbose Print extra information during execution and analysis\n'\
859 ' -addlogs Add the dmesg log to the html output\n'\
860 ' -result fn Export a results table to a text file for parsing.\n'\
861 ' -o name Overrides the output subdirectory name when running a new test\n'\
862 ' default: boot-{date}-{time}\n'\
863 ' [advanced]\n'\
864 ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\
865 ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\
866 ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\
867 ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\
868 ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\
869 ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\
870 ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\
871 ' -cgfilter S Filter the callgraph output in the timeline\n'\
872 ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\
873 ' -bl name Use the following boot loader for kernel params (default: grub)\n'\
874 ' -reboot Reboot the machine automatically and generate a new timeline\n'\
875 ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\
876 '\n'\
877 'Other commands:\n'\
878 ' -flistall Print all functions capable of being captured in ftrace\n'\
879 ' -sysinfo Print out system info extracted from BIOS\n'\
880 ' -which exec Print an executable path, should function even without PATH\n'\
881 ' [redo]\n'\
882 ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\
883 ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\
884 '' % (sysvals.title, sysvals.version))
885 return True
886
887# ----------------- MAIN --------------------
888# exec start (skipped if script is loaded as library)
889if __name__ == '__main__':
890 # loop through the command line arguments
891 cmd = ''
892 testrun = True
893 switchoff = ['disable', 'off', 'false', '0']
894 simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
895 cgskip = ''
896 if '-f' in sys.argv:
897 cgskip = sysvals.configFile('cgskip.txt')
898 args = iter(sys.argv[1:])
899 mdset = False
900 for arg in args:
901 if(arg == '-h'):
902 printHelp()
903 sys.exit()
904 elif(arg == '-v'):
905 pprint("Version %s" % sysvals.version)
906 sys.exit()
907 elif(arg == '-verbose'):
908 sysvals.verbose = True
909 elif(arg in simplecmds):
910 cmd = arg[1:]
911 elif(arg == '-fstat'):
912 sysvals.useftrace = True
913 elif(arg == '-callgraph' or arg == '-f'):
914 sysvals.useftrace = True
915 sysvals.usecallgraph = True
916 elif(arg == '-cgdump'):
917 sysvals.cgdump = True
918 elif(arg == '-mincg'):
919 sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
920 elif(arg == '-cgfilter'):
921 try:
922 val = next(args)
923 except:
924 doError('No callgraph functions supplied', True)
925 sysvals.setCallgraphFilter(val)
926 elif(arg == '-cgskip'):
927 try:
928 val = next(args)
929 except:
930 doError('No file supplied', True)
931 if val.lower() in switchoff:
932 cgskip = ''
933 else:
934 cgskip = sysvals.configFile(val)
935 if(not cgskip):
936 doError('%s does not exist' % cgskip)
937 elif(arg == '-bl'):
938 try:
939 val = next(args)
940 except:
941 doError('No boot loader name supplied', True)
942 if val.lower() not in ['grub']:
943 doError('Unknown boot loader: %s' % val, True)
944 sysvals.bootloader = val.lower()
945 elif(arg == '-timeprec'):
946 sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
947 elif(arg == '-maxdepth'):
948 mdset = True
949 sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
950 elif(arg == '-func'):
951 try:
952 val = next(args)
953 except:
954 doError('No filter functions supplied', True)
955 sysvals.useftrace = True
956 sysvals.usecallgraph = True
957 sysvals.rootCheck(True)
958 sysvals.setGraphFilter(val)
959 elif(arg == '-ftrace'):
960 try:
961 val = next(args)
962 except:
963 doError('No ftrace file supplied', True)
964 if(os.path.exists(val) == False):
965 doError('%s does not exist' % val)
966 testrun = False
967 sysvals.ftracefile = val
968 elif(arg == '-addlogs'):
969 sysvals.dmesglog = True
970 elif(arg == '-expandcg'):
971 sysvals.cgexp = True
972 elif(arg == '-dmesg'):
973 try:
974 val = next(args)
975 except:
976 doError('No dmesg file supplied', True)
977 if(os.path.exists(val) == False):
978 doError('%s does not exist' % val)
979 testrun = False
980 sysvals.dmesgfile = val
981 elif(arg == '-o'):
982 try:
983 val = next(args)
984 except:
985 doError('No subdirectory name supplied', True)
986 sysvals.testdir = sysvals.setOutputFolder(val)
987 elif(arg == '-result'):
988 try:
989 val = next(args)
990 except:
991 doError('No result file supplied', True)
992 sysvals.result = val
993 elif(arg == '-reboot'):
994 sysvals.reboot = True
995 elif(arg == '-manual'):
996 sysvals.reboot = True
997 sysvals.manual = True
998 # remaining options are only for cron job use
999 elif(arg == '-cronjob'):
1000 sysvals.iscronjob = True
1001 elif(arg == '-which'):
1002 try:
1003 val = next(args)
1004 except:
1005 doError('No executable supplied', True)
1006 out = sysvals.getExec(val)
1007 if not out:
1008 print('%s not found' % val)
1009 sys.exit(1)
1010 print(out)
1011 sys.exit(0)
1012 else:
1013 doError('Invalid argument: '+arg, True)
1014
1015 # compatibility errors and access checks
1016 if(sysvals.iscronjob and (sysvals.reboot or \
1017 sysvals.dmesgfile or sysvals.ftracefile or cmd)):
1018 doError('-cronjob is meant for batch purposes only')
1019 if(sysvals.reboot and (sysvals.dmesgfile or sysvals.ftracefile)):
1020 doError('-reboot and -dmesg/-ftrace are incompatible')
1021 if cmd or sysvals.reboot or sysvals.iscronjob or testrun:
1022 sysvals.rootCheck(True)
1023 if (testrun and sysvals.useftrace) or cmd == 'flistall':
1024 if not sysvals.verifyFtrace():
1025 doError('Ftrace is not properly enabled')
1026
1027 # run utility commands
1028 sysvals.cpuInfo()
1029 if cmd != '':
1030 if cmd == 'kpupdate':
1031 updateKernelParams()
1032 elif cmd == 'flistall':
1033 for f in sysvals.getBootFtraceFilterFunctions():
1034 print(f)
1035 elif cmd == 'checkbl':
1036 sysvals.getBootLoader()
1037 pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec))
1038 elif(cmd == 'sysinfo'):
1039 sysvals.printSystemInfo(True)
1040 sys.exit()
1041
1042 # reboot: update grub, setup a cronjob, and reboot
1043 if sysvals.reboot:
1044 if (sysvals.useftrace or sysvals.usecallgraph) and \
1045 not sysvals.checkFtraceKernelVersion():
1046 doError('Ftrace functionality requires kernel v4.10 or newer')
1047 if not sysvals.manual:
1048 updateKernelParams()
1049 updateCron()
1050 call('reboot')
1051 else:
1052 sysvals.manualRebootRequired()
1053 sys.exit()
1054
1055 if sysvals.usecallgraph and cgskip:
1056 sysvals.vprint('Using cgskip file: %s' % cgskip)
1057 sysvals.setCallgraphBlacklist(cgskip)
1058
1059 # cronjob: remove the cronjob, grub changes, and disable ftrace
1060 if sysvals.iscronjob:
1061 updateCron(True)
1062 updateKernelParams(True)
1063 try:
1064 sysvals.fsetVal('0', 'tracing_on')
1065 except:
1066 pass
1067
1068 # testrun: generate copies of the logs
1069 if testrun:
1070 retrieveLogs()
1071 else:
1072 sysvals.setOutputFile()
1073
1074 # process the log data
1075 if sysvals.dmesgfile:
1076 if not mdset:
1077 sysvals.max_graph_depth = 0
1078 data = parseKernelLog()
1079 if(not data.valid):
1080 doError('No initcall data found in %s' % sysvals.dmesgfile)
1081 if sysvals.useftrace and sysvals.ftracefile:
1082 parseTraceLog(data)
1083 if sysvals.cgdump:
1084 data.debugPrint()
1085 sys.exit()
1086 else:
1087 doError('dmesg file required')
1088
1089 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
1090 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
1091 sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams)
1092 data.printDetails()
1093 createBootGraph(data)
1094
1095 # if running as root, change output dir owner to sudo_user
1096 if testrun and os.path.isdir(sysvals.testdir) and \
1097 os.getuid() == 0 and 'SUDO_USER' in os.environ:
1098 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
1099 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
1100
1101 sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
1102 sysvals.stamp['lastinit'] = data.end * 1000
1103 sysvals.outputResult(sysvals.stamp)
1#!/usr/bin/python
2#
3# Tool for analyzing boot timing
4# Copyright (c) 2013, Intel Corporation.
5#
6# This program is free software; you can redistribute it and/or modify it
7# under the terms and conditions of the GNU General Public License,
8# version 2, as published by the Free Software Foundation.
9#
10# This program is distributed in the hope it will be useful, but WITHOUT
11# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
13# more details.
14#
15# Authors:
16# Todd Brandt <todd.e.brandt@linux.intel.com>
17#
18# Description:
19# This tool is designed to assist kernel and OS developers in optimizing
20# their linux stack's boot time. It creates an html representation of
21# the kernel boot timeline up to the start of the init process.
22#
23
24# ----------------- LIBRARIES --------------------
25
26import sys
27import time
28import os
29import string
30import re
31import platform
32import shutil
33from datetime import datetime, timedelta
34from subprocess import call, Popen, PIPE
35import sleepgraph as aslib
36
37# ----------------- CLASSES --------------------
38
39# Class: SystemValues
40# Description:
41# A global, single-instance container used to
42# store system values and test parameters
43class SystemValues(aslib.SystemValues):
44 title = 'BootGraph'
45 version = '2.2'
46 hostname = 'localhost'
47 testtime = ''
48 kernel = ''
49 dmesgfile = ''
50 ftracefile = ''
51 htmlfile = 'bootgraph.html'
52 testdir = ''
53 kparams = ''
54 result = ''
55 useftrace = False
56 usecallgraph = False
57 suspendmode = 'boot'
58 max_graph_depth = 2
59 graph_filter = 'do_one_initcall'
60 reboot = False
61 manual = False
62 iscronjob = False
63 timeformat = '%.6f'
64 bootloader = 'grub'
65 blexec = []
66 def __init__(self):
67 self.hostname = platform.node()
68 self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')
69 if os.path.exists('/proc/version'):
70 fp = open('/proc/version', 'r')
71 val = fp.read().strip()
72 fp.close()
73 self.kernel = self.kernelVersion(val)
74 else:
75 self.kernel = 'unknown'
76 self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')
77 def kernelVersion(self, msg):
78 return msg.split()[2]
79 def checkFtraceKernelVersion(self):
80 val = tuple(map(int, self.kernel.split('-')[0].split('.')))
81 if val >= (4, 10, 0):
82 return True
83 return False
84 def kernelParams(self):
85 cmdline = 'initcall_debug log_buf_len=32M'
86 if self.useftrace:
87 if self.cpucount > 0:
88 bs = min(self.memtotal / 2, 2*1024*1024) / self.cpucount
89 else:
90 bs = 131072
91 cmdline += ' trace_buf_size=%dK trace_clock=global '\
92 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\
93 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\
94 'nofuncgraph-overhead,context-info,graph-time '\
95 'ftrace=function_graph '\
96 'ftrace_graph_max_depth=%d '\
97 'ftrace_graph_filter=%s' % \
98 (bs, self.max_graph_depth, self.graph_filter)
99 return cmdline
100 def setGraphFilter(self, val):
101 master = self.getBootFtraceFilterFunctions()
102 fs = ''
103 for i in val.split(','):
104 func = i.strip()
105 if func == '':
106 doError('badly formatted filter function string')
107 if '[' in func or ']' in func:
108 doError('loadable module functions not allowed - "%s"' % func)
109 if ' ' in func:
110 doError('spaces found in filter functions - "%s"' % func)
111 if func not in master:
112 doError('function "%s" not available for ftrace' % func)
113 if not fs:
114 fs = func
115 else:
116 fs += ','+func
117 if not fs:
118 doError('badly formatted filter function string')
119 self.graph_filter = fs
120 def getBootFtraceFilterFunctions(self):
121 self.rootCheck(True)
122 fp = open(self.tpath+'available_filter_functions')
123 fulllist = fp.read().split('\n')
124 fp.close()
125 list = []
126 for i in fulllist:
127 if not i or ' ' in i or '[' in i or ']' in i:
128 continue
129 list.append(i)
130 return list
131 def myCronJob(self, line):
132 if '@reboot' not in line:
133 return False
134 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:
135 return True
136 return False
137 def cronjobCmdString(self):
138 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
139 args = iter(sys.argv[1:])
140 for arg in args:
141 if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
142 continue
143 elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
144 args.next()
145 continue
146 elif arg == '-result':
147 cmdline += ' %s "%s"' % (arg, os.path.abspath(args.next()))
148 continue
149 elif arg == '-cgskip':
150 file = self.configFile(args.next())
151 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
152 continue
153 cmdline += ' '+arg
154 if self.graph_filter != 'do_one_initcall':
155 cmdline += ' -func "%s"' % self.graph_filter
156 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)
157 return cmdline
158 def manualRebootRequired(self):
159 cmdline = self.kernelParams()
160 print 'To generate a new timeline manually, follow these steps:\n'
161 print '1. Add the CMDLINE string to your kernel command line.'
162 print '2. Reboot the system.'
163 print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n'
164 print 'CMDLINE="%s"' % cmdline
165 sys.exit()
166 def blGrub(self):
167 blcmd = ''
168 for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
169 if blcmd:
170 break
171 blcmd = self.getExec(cmd)
172 if not blcmd:
173 doError('[GRUB] missing update command')
174 if not os.path.exists('/etc/default/grub'):
175 doError('[GRUB] missing /etc/default/grub')
176 if 'grub2' in blcmd:
177 cfg = '/boot/grub2/grub.cfg'
178 else:
179 cfg = '/boot/grub/grub.cfg'
180 if not os.path.exists(cfg):
181 doError('[GRUB] missing %s' % cfg)
182 if 'update-grub' in blcmd:
183 self.blexec = [blcmd]
184 else:
185 self.blexec = [blcmd, '-o', cfg]
186 def getBootLoader(self):
187 if self.bootloader == 'grub':
188 self.blGrub()
189 else:
190 doError('unknown boot loader: %s' % self.bootloader)
191 def writeDatafileHeader(self, filename):
192 self.kparams = open('/proc/cmdline', 'r').read().strip()
193 fp = open(filename, 'w')
194 fp.write(self.teststamp+'\n')
195 fp.write(self.sysstamp+'\n')
196 fp.write('# command | %s\n' % self.cmdline)
197 fp.write('# kparams | %s\n' % self.kparams)
198 fp.close()
199
200sysvals = SystemValues()
201
202# Class: Data
203# Description:
204# The primary container for test data.
205class Data(aslib.Data):
206 dmesg = {} # root data structure
207 start = 0.0 # test start
208 end = 0.0 # test end
209 dmesgtext = [] # dmesg text file in memory
210 testnumber = 0
211 idstr = ''
212 html_device_id = 0
213 valid = False
214 tUserMode = 0.0
215 boottime = ''
216 phases = ['kernel', 'user']
217 do_one_initcall = False
218 def __init__(self, num):
219 self.testnumber = num
220 self.idstr = 'a'
221 self.dmesgtext = []
222 self.dmesg = {
223 'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
224 'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'},
225 'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
226 'order': 1, 'color': '#fff'}
227 }
228 def deviceTopology(self):
229 return ''
230 def newAction(self, phase, name, pid, start, end, ret, ulen):
231 # new device callback for a specific phase
232 self.html_device_id += 1
233 devid = '%s%d' % (self.idstr, self.html_device_id)
234 list = self.dmesg[phase]['list']
235 length = -1.0
236 if(start >= 0 and end >= 0):
237 length = end - start
238 i = 2
239 origname = name
240 while(name in list):
241 name = '%s[%d]' % (origname, i)
242 i += 1
243 list[name] = {'name': name, 'start': start, 'end': end,
244 'pid': pid, 'length': length, 'row': 0, 'id': devid,
245 'ret': ret, 'ulen': ulen }
246 return name
247 def deviceMatch(self, pid, cg):
248 if cg.end - cg.start == 0:
249 return ''
250 for p in data.phases:
251 list = self.dmesg[p]['list']
252 for devname in list:
253 dev = list[devname]
254 if pid != dev['pid']:
255 continue
256 if cg.name == 'do_one_initcall':
257 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
258 dev['ftrace'] = cg
259 self.do_one_initcall = True
260 return devname
261 else:
262 if(cg.start > dev['start'] and cg.end < dev['end']):
263 if 'ftraces' not in dev:
264 dev['ftraces'] = []
265 dev['ftraces'].append(cg)
266 return devname
267 return ''
268 def printDetails(self):
269 sysvals.vprint('Timeline Details:')
270 sysvals.vprint(' Host: %s' % sysvals.hostname)
271 sysvals.vprint(' Kernel: %s' % sysvals.kernel)
272 sysvals.vprint(' Test time: %s' % sysvals.testtime)
273 sysvals.vprint(' Boot time: %s' % self.boottime)
274 for phase in self.phases:
275 dc = len(self.dmesg[phase]['list'])
276 sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,
277 self.dmesg[phase]['start']*1000,
278 self.dmesg[phase]['end']*1000, dc))
279
280# ----------------- FUNCTIONS --------------------
281
282# Function: parseKernelLog
283# Description:
284# parse a kernel log for boot data
285def parseKernelLog():
286 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
287 os.path.basename(sysvals.dmesgfile))
288 phase = 'kernel'
289 data = Data(0)
290 data.dmesg['kernel']['start'] = data.start = ktime = 0.0
291 sysvals.stamp = {
292 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
293 'host': sysvals.hostname,
294 'mode': 'boot', 'kernel': ''}
295
296 tp = aslib.TestProps()
297 devtemp = dict()
298 if(sysvals.dmesgfile):
299 lf = open(sysvals.dmesgfile, 'r')
300 else:
301 lf = Popen('dmesg', stdout=PIPE).stdout
302 for line in lf:
303 line = line.replace('\r\n', '')
304 # grab the stamp and sysinfo
305 if re.match(tp.stampfmt, line):
306 tp.stamp = line
307 continue
308 elif re.match(tp.sysinfofmt, line):
309 tp.sysinfo = line
310 continue
311 elif re.match(tp.cmdlinefmt, line):
312 tp.cmdline = line
313 continue
314 elif re.match(tp.kparamsfmt, line):
315 tp.kparams = line
316 continue
317 idx = line.find('[')
318 if idx > 1:
319 line = line[idx:]
320 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
321 if(not m):
322 continue
323 ktime = float(m.group('ktime'))
324 if(ktime > 120):
325 break
326 msg = m.group('msg')
327 data.dmesgtext.append(line)
328 if(ktime == 0.0 and re.match('^Linux version .*', msg)):
329 if(not sysvals.stamp['kernel']):
330 sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
331 continue
332 m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg)
333 if(m):
334 bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S')
335 bt = bt - timedelta(seconds=int(ktime))
336 data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
337 sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
338 continue
339 m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
340 if(m):
341 func = m.group('f')
342 pid = int(m.group('p'))
343 devtemp[func] = (ktime, pid)
344 continue
345 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
346 if(m):
347 data.valid = True
348 data.end = ktime
349 f, r, t = m.group('f', 'r', 't')
350 if(f in devtemp):
351 start, pid = devtemp[f]
352 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
353 del devtemp[f]
354 continue
355 if(re.match('^Freeing unused kernel memory.*', msg)):
356 data.tUserMode = ktime
357 data.dmesg['kernel']['end'] = ktime
358 data.dmesg['user']['start'] = ktime
359 phase = 'user'
360
361 if tp.stamp:
362 sysvals.stamp = 0
363 tp.parseStamp(data, sysvals)
364 data.dmesg['user']['end'] = data.end
365 lf.close()
366 return data
367
368# Function: parseTraceLog
369# Description:
370# Check if trace is available and copy to a temp file
371def parseTraceLog(data):
372 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
373 os.path.basename(sysvals.ftracefile))
374 # if available, calculate cgfilter allowable ranges
375 cgfilter = []
376 if len(sysvals.cgfilter) > 0:
377 for p in data.phases:
378 list = data.dmesg[p]['list']
379 for i in sysvals.cgfilter:
380 if i in list:
381 cgfilter.append([list[i]['start']-0.0001,
382 list[i]['end']+0.0001])
383 # parse the trace log
384 ftemp = dict()
385 tp = aslib.TestProps()
386 tp.setTracerType('function_graph')
387 tf = open(sysvals.ftracefile, 'r')
388 for line in tf:
389 if line[0] == '#':
390 continue
391 m = re.match(tp.ftrace_line_fmt, line.strip())
392 if(not m):
393 continue
394 m_time, m_proc, m_pid, m_msg, m_dur = \
395 m.group('time', 'proc', 'pid', 'msg', 'dur')
396 t = float(m_time)
397 if len(cgfilter) > 0:
398 allow = False
399 for r in cgfilter:
400 if t >= r[0] and t < r[1]:
401 allow = True
402 break
403 if not allow:
404 continue
405 if t > data.end:
406 break
407 if(m_time and m_pid and m_msg):
408 t = aslib.FTraceLine(m_time, m_msg, m_dur)
409 pid = int(m_pid)
410 else:
411 continue
412 if t.fevent or t.fkprobe:
413 continue
414 key = (m_proc, pid)
415 if(key not in ftemp):
416 ftemp[key] = []
417 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
418 cg = ftemp[key][-1]
419 res = cg.addLine(t)
420 if(res != 0):
421 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
422 if(res == -1):
423 ftemp[key][-1].addLine(t)
424
425 tf.close()
426
427 # add the callgraph data to the device hierarchy
428 for key in ftemp:
429 proc, pid = key
430 for cg in ftemp[key]:
431 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
432 continue
433 if(not cg.postProcess()):
434 print('Sanity check failed for %s-%d' % (proc, pid))
435 continue
436 # match cg data to devices
437 devname = data.deviceMatch(pid, cg)
438 if not devname:
439 kind = 'Orphan'
440 if cg.partial:
441 kind = 'Partial'
442 sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\
443 (kind, cg.name, proc, pid, cg.start, cg.end))
444 elif len(cg.list) > 1000000:
445 print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\
446 (devname, len(cg.list))
447
448# Function: retrieveLogs
449# Description:
450# Create copies of dmesg and/or ftrace for later processing
451def retrieveLogs():
452 # check ftrace is configured first
453 if sysvals.useftrace:
454 tracer = sysvals.fgetVal('current_tracer').strip()
455 if tracer != 'function_graph':
456 doError('ftrace not configured for a boot callgraph')
457 # create the folder and get dmesg
458 sysvals.systemInfo(aslib.dmidecode(sysvals.mempath))
459 sysvals.initTestOutput('boot')
460 sysvals.writeDatafileHeader(sysvals.dmesgfile)
461 call('dmesg >> '+sysvals.dmesgfile, shell=True)
462 if not sysvals.useftrace:
463 return
464 # get ftrace
465 sysvals.writeDatafileHeader(sysvals.ftracefile)
466 call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)
467
468# Function: colorForName
469# Description:
470# Generate a repeatable color from a list for a given name
471def colorForName(name):
472 list = [
473 ('c1', '#ec9999'),
474 ('c2', '#ffc1a6'),
475 ('c3', '#fff0a6'),
476 ('c4', '#adf199'),
477 ('c5', '#9fadea'),
478 ('c6', '#a699c1'),
479 ('c7', '#ad99b4'),
480 ('c8', '#eaffea'),
481 ('c9', '#dcecfb'),
482 ('c10', '#ffffea')
483 ]
484 i = 0
485 total = 0
486 count = len(list)
487 while i < len(name):
488 total += ord(name[i])
489 i += 1
490 return list[total % count]
491
492def cgOverview(cg, minlen):
493 stats = dict()
494 large = []
495 for l in cg.list:
496 if l.fcall and l.depth == 1:
497 if l.length >= minlen:
498 large.append(l)
499 if l.name not in stats:
500 stats[l.name] = [0, 0.0]
501 stats[l.name][0] += (l.length * 1000.0)
502 stats[l.name][1] += 1
503 return (large, stats)
504
505# Function: createBootGraph
506# Description:
507# Create the output html file from the resident test data
508# Arguments:
509# testruns: array of Data objects from parseKernelLog or parseTraceLog
510# Output:
511# True if the html file was created, false if it failed
512def createBootGraph(data):
513 # html function templates
514 html_srccall = '<div id={6} title="{5}" class="srccall" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{0}</div>\n'
515 html_timetotal = '<table class="time1">\n<tr>'\
516 '<td class="blue">Init process starts @ <b>{0} ms</b></td>'\
517 '<td class="blue">Last initcall ends @ <b>{1} ms</b></td>'\
518 '</tr>\n</table>\n'
519
520 # device timeline
521 devtl = aslib.Timeline(100, 20)
522
523 # write the test title and general info header
524 devtl.createHeader(sysvals, sysvals.stamp)
525
526 # Generate the header for this timeline
527 t0 = data.start
528 tMax = data.end
529 tTotal = tMax - t0
530 if(tTotal == 0):
531 print('ERROR: No timeline data')
532 return False
533 user_mode = '%.0f'%(data.tUserMode*1000)
534 last_init = '%.0f'%(tTotal*1000)
535 devtl.html += html_timetotal.format(user_mode, last_init)
536
537 # determine the maximum number of rows we need to draw
538 devlist = []
539 for p in data.phases:
540 list = data.dmesg[p]['list']
541 for devname in list:
542 d = aslib.DevItem(0, p, list[devname])
543 devlist.append(d)
544 devtl.getPhaseRows(devlist, 0, 'start')
545 devtl.calcTotalRows()
546
547 # draw the timeline background
548 devtl.createZoomBox()
549 devtl.html += devtl.html_tblock.format('boot', '0', '100', devtl.scaleH)
550 for p in data.phases:
551 phase = data.dmesg[p]
552 length = phase['end']-phase['start']
553 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
554 width = '%.3f' % ((length*100.0)/tTotal)
555 devtl.html += devtl.html_phase.format(left, width, \
556 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
557 phase['color'], '')
558
559 # draw the device timeline
560 num = 0
561 devstats = dict()
562 for phase in data.phases:
563 list = data.dmesg[phase]['list']
564 for devname in sorted(list):
565 cls, color = colorForName(devname)
566 dev = list[devname]
567 info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0,
568 dev['ulen']/1000.0, dev['ret'])
569 devstats[dev['id']] = {'info':info}
570 dev['color'] = color
571 height = devtl.phaseRowHeight(0, phase, dev['row'])
572 top = '%.6f' % ((dev['row']*height) + devtl.scaleH)
573 left = '%.6f' % (((dev['start']-t0)*100)/tTotal)
574 width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal)
575 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
576 devtl.html += devtl.html_device.format(dev['id'],
577 devname+length+phase+'_mode', left, top, '%.3f'%height,
578 width, devname, ' '+cls, '')
579 rowtop = devtl.phaseRowTop(0, phase, dev['row'])
580 height = '%.6f' % (devtl.rowH / 2)
581 top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2))
582 if data.do_one_initcall:
583 if('ftrace' not in dev):
584 continue
585 cg = dev['ftrace']
586 large, stats = cgOverview(cg, 0.001)
587 devstats[dev['id']]['fstat'] = stats
588 for l in large:
589 left = '%f' % (((l.time-t0)*100)/tTotal)
590 width = '%f' % (l.length*100/tTotal)
591 title = '%s (%0.3fms)' % (l.name, l.length * 1000.0)
592 devtl.html += html_srccall.format(l.name, left,
593 top, height, width, title, 'x%d'%num)
594 num += 1
595 continue
596 if('ftraces' not in dev):
597 continue
598 for cg in dev['ftraces']:
599 left = '%f' % (((cg.start-t0)*100)/tTotal)
600 width = '%f' % ((cg.end-cg.start)*100/tTotal)
601 cglen = (cg.end - cg.start) * 1000.0
602 title = '%s (%0.3fms)' % (cg.name, cglen)
603 cg.id = 'x%d' % num
604 devtl.html += html_srccall.format(cg.name, left,
605 top, height, width, title, dev['id']+cg.id)
606 num += 1
607
608 # draw the time scale, try to make the number of labels readable
609 devtl.createTimeScale(t0, tMax, tTotal, 'boot')
610 devtl.html += '</div>\n'
611
612 # timeline is finished
613 devtl.html += '</div>\n</div>\n'
614
615 # draw a legend which describes the phases by color
616 devtl.html += '<div class="legend">\n'
617 pdelta = 20.0
618 pmargin = 36.0
619 for phase in data.phases:
620 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
621 devtl.html += devtl.html_legend.format(order, \
622 data.dmesg[phase]['color'], phase+'_mode', phase[0])
623 devtl.html += '</div>\n'
624
625 hf = open(sysvals.htmlfile, 'w')
626
627 # add the css
628 extra = '\
629 .c1 {background:rgba(209,0,0,0.4);}\n\
630 .c2 {background:rgba(255,102,34,0.4);}\n\
631 .c3 {background:rgba(255,218,33,0.4);}\n\
632 .c4 {background:rgba(51,221,0,0.4);}\n\
633 .c5 {background:rgba(17,51,204,0.4);}\n\
634 .c6 {background:rgba(34,0,102,0.4);}\n\
635 .c7 {background:rgba(51,0,68,0.4);}\n\
636 .c8 {background:rgba(204,255,204,0.4);}\n\
637 .c9 {background:rgba(169,208,245,0.4);}\n\
638 .c10 {background:rgba(255,255,204,0.4);}\n\
639 .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\
640 table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\
641 .fstat th {width:55px;}\n\
642 .fstat td {text-align:left;width:35px;}\n\
643 .srccall {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
644 .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
645 aslib.addCSS(hf, sysvals, 1, False, extra)
646
647 # write the device timeline
648 hf.write(devtl.html)
649
650 # add boot specific html
651 statinfo = 'var devstats = {\n'
652 for n in sorted(devstats):
653 statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info'])
654 if 'fstat' in devstats[n]:
655 funcs = devstats[n]['fstat']
656 for f in sorted(funcs, key=funcs.get, reverse=True):
657 if funcs[f][0] < 0.01 and len(funcs) > 10:
658 break
659 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
660 statinfo += '\t],\n'
661 statinfo += '};\n'
662 html = \
663 '<div id="devicedetailtitle"></div>\n'\
664 '<div id="devicedetail" style="display:none;">\n'\
665 '<div id="devicedetail0">\n'
666 for p in data.phases:
667 phase = data.dmesg[p]
668 html += devtl.html_phaselet.format(p+'_mode', '0', '100', phase['color'])
669 html += '</div>\n</div>\n'\
670 '<script type="text/javascript">\n'+statinfo+\
671 '</script>\n'
672 hf.write(html)
673
674 # add the callgraph html
675 if(sysvals.usecallgraph):
676 aslib.addCallgraphs(sysvals, hf, data)
677
678 # add the test log as a hidden div
679 if sysvals.testlog and sysvals.logmsg:
680 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
681 # add the dmesg log as a hidden div
682 if sysvals.dmesglog:
683 hf.write('<div id="dmesglog" style="display:none;">\n')
684 for line in data.dmesgtext:
685 line = line.replace('<', '<').replace('>', '>')
686 hf.write(line)
687 hf.write('</div>\n')
688
689 # write the footer and close
690 aslib.addScriptCode(hf, [data])
691 hf.write('</body>\n</html>\n')
692 hf.close()
693 return True
694
695# Function: updateCron
696# Description:
697# (restore=False) Set the tool to run automatically on reboot
698# (restore=True) Restore the original crontab
699def updateCron(restore=False):
700 if not restore:
701 sysvals.rootUser(True)
702 crondir = '/var/spool/cron/crontabs/'
703 if not os.path.exists(crondir):
704 crondir = '/var/spool/cron/'
705 if not os.path.exists(crondir):
706 doError('%s not found' % crondir)
707 cronfile = crondir+'root'
708 backfile = crondir+'root-analyze_boot-backup'
709 cmd = sysvals.getExec('crontab')
710 if not cmd:
711 doError('crontab not found')
712 # on restore: move the backup cron back into place
713 if restore:
714 if os.path.exists(backfile):
715 shutil.move(backfile, cronfile)
716 call([cmd, cronfile])
717 return
718 # backup current cron and install new one with reboot
719 if os.path.exists(cronfile):
720 shutil.move(cronfile, backfile)
721 else:
722 fp = open(backfile, 'w')
723 fp.close()
724 res = -1
725 try:
726 fp = open(backfile, 'r')
727 op = open(cronfile, 'w')
728 for line in fp:
729 if not sysvals.myCronJob(line):
730 op.write(line)
731 continue
732 fp.close()
733 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
734 op.close()
735 res = call([cmd, cronfile])
736 except Exception, e:
737 print 'Exception: %s' % str(e)
738 shutil.move(backfile, cronfile)
739 res = -1
740 if res != 0:
741 doError('crontab failed')
742
743# Function: updateGrub
744# Description:
745# update grub.cfg for all kernels with our parameters
746def updateGrub(restore=False):
747 # call update-grub on restore
748 if restore:
749 try:
750 call(sysvals.blexec, stderr=PIPE, stdout=PIPE,
751 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'})
752 except Exception, e:
753 print 'Exception: %s\n' % str(e)
754 return
755 # extract the option and create a grub config without it
756 sysvals.rootUser(True)
757 tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
758 cmdline = ''
759 grubfile = '/etc/default/grub'
760 tempfile = '/etc/default/grub.analyze_boot'
761 shutil.move(grubfile, tempfile)
762 res = -1
763 try:
764 fp = open(tempfile, 'r')
765 op = open(grubfile, 'w')
766 cont = False
767 for line in fp:
768 line = line.strip()
769 if len(line) == 0 or line[0] == '#':
770 continue
771 opt = line.split('=')[0].strip()
772 if opt == tgtopt:
773 cmdline = line.split('=', 1)[1].strip('\\')
774 if line[-1] == '\\':
775 cont = True
776 elif cont:
777 cmdline += line.strip('\\')
778 if line[-1] != '\\':
779 cont = False
780 else:
781 op.write('%s\n' % line)
782 fp.close()
783 # if the target option value is in quotes, strip them
784 sp = '"'
785 val = cmdline.strip()
786 if val and (val[0] == '\'' or val[0] == '"'):
787 sp = val[0]
788 val = val.strip(sp)
789 cmdline = val
790 # append our cmd line options
791 if len(cmdline) > 0:
792 cmdline += ' '
793 cmdline += sysvals.kernelParams()
794 # write out the updated target option
795 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
796 op.close()
797 res = call(sysvals.blexec)
798 os.remove(grubfile)
799 except Exception, e:
800 print 'Exception: %s' % str(e)
801 res = -1
802 # cleanup
803 shutil.move(tempfile, grubfile)
804 if res != 0:
805 doError('update grub failed')
806
807# Function: updateKernelParams
808# Description:
809# update boot conf for all kernels with our parameters
810def updateKernelParams(restore=False):
811 # find the boot loader
812 sysvals.getBootLoader()
813 if sysvals.bootloader == 'grub':
814 updateGrub(restore)
815
816# Function: doError Description:
817# generic error function for catastrphic failures
818# Arguments:
819# msg: the error message to print
820# help: True if printHelp should be called after, False otherwise
821def doError(msg, help=False):
822 if help == True:
823 printHelp()
824 print 'ERROR: %s\n' % msg
825 sysvals.outputResult({'error':msg})
826 sys.exit()
827
828# Function: printHelp
829# Description:
830# print out the help text
831def printHelp():
832 print('')
833 print('%s v%s' % (sysvals.title, sysvals.version))
834 print('Usage: bootgraph <options> <command>')
835 print('')
836 print('Description:')
837 print(' This tool reads in a dmesg log of linux kernel boot and')
838 print(' creates an html representation of the boot timeline up to')
839 print(' the start of the init process.')
840 print('')
841 print(' If no specific command is given the tool reads the current dmesg')
842 print(' and/or ftrace log and creates a timeline')
843 print('')
844 print(' Generates output files in subdirectory: boot-yymmdd-HHMMSS')
845 print(' HTML output: <hostname>_boot.html')
846 print(' raw dmesg output: <hostname>_boot_dmesg.txt')
847 print(' raw ftrace output: <hostname>_boot_ftrace.txt')
848 print('')
849 print('Options:')
850 print(' -h Print this help text')
851 print(' -v Print the current tool version')
852 print(' -verbose Print extra information during execution and analysis')
853 print(' -addlogs Add the dmesg log to the html output')
854 print(' -result fn Export a results table to a text file for parsing.')
855 print(' -o name Overrides the output subdirectory name when running a new test')
856 print(' default: boot-{date}-{time}')
857 print(' [advanced]')
858 print(' -fstat Use ftrace to add function detail and statistics (default: disabled)')
859 print(' -f/-callgraph Add callgraph detail, can be very large (default: disabled)')
860 print(' -maxdepth N limit the callgraph data to N call levels (default: 2)')
861 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
862 print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])')
863 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
864 print(' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)')
865 print(' -cgfilter S Filter the callgraph output in the timeline')
866 print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)')
867 print(' -bl name Use the following boot loader for kernel params (default: grub)')
868 print(' -reboot Reboot the machine automatically and generate a new timeline')
869 print(' -manual Show the steps to generate a new timeline manually (used with -reboot)')
870 print('')
871 print('Other commands:')
872 print(' -flistall Print all functions capable of being captured in ftrace')
873 print(' -sysinfo Print out system info extracted from BIOS')
874 print(' [redo]')
875 print(' -dmesg file Create HTML output using dmesg input (used with -ftrace)')
876 print(' -ftrace file Create HTML output using ftrace input (used with -dmesg)')
877 print('')
878 return True
879
880# ----------------- MAIN --------------------
881# exec start (skipped if script is loaded as library)
882if __name__ == '__main__':
883 # loop through the command line arguments
884 cmd = ''
885 testrun = True
886 switchoff = ['disable', 'off', 'false', '0']
887 simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
888 cgskip = ''
889 if '-f' in sys.argv:
890 cgskip = sysvals.configFile('cgskip.txt')
891 args = iter(sys.argv[1:])
892 mdset = False
893 for arg in args:
894 if(arg == '-h'):
895 printHelp()
896 sys.exit()
897 elif(arg == '-v'):
898 print("Version %s" % sysvals.version)
899 sys.exit()
900 elif(arg == '-verbose'):
901 sysvals.verbose = True
902 elif(arg in simplecmds):
903 cmd = arg[1:]
904 elif(arg == '-fstat'):
905 sysvals.useftrace = True
906 elif(arg == '-callgraph' or arg == '-f'):
907 sysvals.useftrace = True
908 sysvals.usecallgraph = True
909 elif(arg == '-cgdump'):
910 sysvals.cgdump = True
911 elif(arg == '-mincg'):
912 sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
913 elif(arg == '-cgfilter'):
914 try:
915 val = args.next()
916 except:
917 doError('No callgraph functions supplied', True)
918 sysvals.setCallgraphFilter(val)
919 elif(arg == '-cgskip'):
920 try:
921 val = args.next()
922 except:
923 doError('No file supplied', True)
924 if val.lower() in switchoff:
925 cgskip = ''
926 else:
927 cgskip = sysvals.configFile(val)
928 if(not cgskip):
929 doError('%s does not exist' % cgskip)
930 elif(arg == '-bl'):
931 try:
932 val = args.next()
933 except:
934 doError('No boot loader name supplied', True)
935 if val.lower() not in ['grub']:
936 doError('Unknown boot loader: %s' % val, True)
937 sysvals.bootloader = val.lower()
938 elif(arg == '-timeprec'):
939 sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
940 elif(arg == '-maxdepth'):
941 mdset = True
942 sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
943 elif(arg == '-func'):
944 try:
945 val = args.next()
946 except:
947 doError('No filter functions supplied', True)
948 sysvals.useftrace = True
949 sysvals.usecallgraph = True
950 sysvals.rootCheck(True)
951 sysvals.setGraphFilter(val)
952 elif(arg == '-ftrace'):
953 try:
954 val = args.next()
955 except:
956 doError('No ftrace file supplied', True)
957 if(os.path.exists(val) == False):
958 doError('%s does not exist' % val)
959 testrun = False
960 sysvals.ftracefile = val
961 elif(arg == '-addlogs'):
962 sysvals.dmesglog = True
963 elif(arg == '-expandcg'):
964 sysvals.cgexp = True
965 elif(arg == '-dmesg'):
966 try:
967 val = args.next()
968 except:
969 doError('No dmesg file supplied', True)
970 if(os.path.exists(val) == False):
971 doError('%s does not exist' % val)
972 testrun = False
973 sysvals.dmesgfile = val
974 elif(arg == '-o'):
975 try:
976 val = args.next()
977 except:
978 doError('No subdirectory name supplied', True)
979 sysvals.testdir = sysvals.setOutputFolder(val)
980 elif(arg == '-result'):
981 try:
982 val = args.next()
983 except:
984 doError('No result file supplied', True)
985 sysvals.result = val
986 elif(arg == '-reboot'):
987 sysvals.reboot = True
988 elif(arg == '-manual'):
989 sysvals.reboot = True
990 sysvals.manual = True
991 # remaining options are only for cron job use
992 elif(arg == '-cronjob'):
993 sysvals.iscronjob = True
994 else:
995 doError('Invalid argument: '+arg, True)
996
997 # compatibility errors and access checks
998 if(sysvals.iscronjob and (sysvals.reboot or \
999 sysvals.dmesgfile or sysvals.ftracefile or cmd)):
1000 doError('-cronjob is meant for batch purposes only')
1001 if(sysvals.reboot and (sysvals.dmesgfile or sysvals.ftracefile)):
1002 doError('-reboot and -dmesg/-ftrace are incompatible')
1003 if cmd or sysvals.reboot or sysvals.iscronjob or testrun:
1004 sysvals.rootCheck(True)
1005 if (testrun and sysvals.useftrace) or cmd == 'flistall':
1006 if not sysvals.verifyFtrace():
1007 doError('Ftrace is not properly enabled')
1008
1009 # run utility commands
1010 sysvals.cpuInfo()
1011 if cmd != '':
1012 if cmd == 'kpupdate':
1013 updateKernelParams()
1014 elif cmd == 'flistall':
1015 for f in sysvals.getBootFtraceFilterFunctions():
1016 print f
1017 elif cmd == 'checkbl':
1018 sysvals.getBootLoader()
1019 print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)
1020 elif(cmd == 'sysinfo'):
1021 sysvals.printSystemInfo(True)
1022 sys.exit()
1023
1024 # reboot: update grub, setup a cronjob, and reboot
1025 if sysvals.reboot:
1026 if (sysvals.useftrace or sysvals.usecallgraph) and \
1027 not sysvals.checkFtraceKernelVersion():
1028 doError('Ftrace functionality requires kernel v4.10 or newer')
1029 if not sysvals.manual:
1030 updateKernelParams()
1031 updateCron()
1032 call('reboot')
1033 else:
1034 sysvals.manualRebootRequired()
1035 sys.exit()
1036
1037 if sysvals.usecallgraph and cgskip:
1038 sysvals.vprint('Using cgskip file: %s' % cgskip)
1039 sysvals.setCallgraphBlacklist(cgskip)
1040
1041 # cronjob: remove the cronjob, grub changes, and disable ftrace
1042 if sysvals.iscronjob:
1043 updateCron(True)
1044 updateKernelParams(True)
1045 try:
1046 sysvals.fsetVal('0', 'tracing_on')
1047 except:
1048 pass
1049
1050 # testrun: generate copies of the logs
1051 if testrun:
1052 retrieveLogs()
1053 else:
1054 sysvals.setOutputFile()
1055
1056 # process the log data
1057 if sysvals.dmesgfile:
1058 if not mdset:
1059 sysvals.max_graph_depth = 0
1060 data = parseKernelLog()
1061 if(not data.valid):
1062 doError('No initcall data found in %s' % sysvals.dmesgfile)
1063 if sysvals.useftrace and sysvals.ftracefile:
1064 parseTraceLog(data)
1065 if sysvals.cgdump:
1066 data.debugPrint()
1067 sys.exit()
1068 else:
1069 doError('dmesg file required')
1070
1071 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
1072 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
1073 sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams)
1074 data.printDetails()
1075 createBootGraph(data)
1076
1077 # if running as root, change output dir owner to sudo_user
1078 if testrun and os.path.isdir(sysvals.testdir) and \
1079 os.getuid() == 0 and 'SUDO_USER' in os.environ:
1080 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
1081 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
1082
1083 sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
1084 sysvals.stamp['lastinit'] = data.end * 1000
1085 sysvals.outputResult(sysvals.stamp)