3 # Tool for analyzing boot timing
4 # Copyright (c) 2013, Intel Corporation.
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.
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
16 # Todd Brandt <todd.e.brandt@linux.intel.com>
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.
24 # ----------------- LIBRARIES --------------------
33 from datetime import datetime, timedelta
34 from subprocess import call, Popen, PIPE
35 import sleepgraph as aslib
37 # ----------------- CLASSES --------------------
41 # A global, single-instance container used to
42 # store system values and test parameters
43 class SystemValues(aslib.SystemValues):
46 hostname = 'localhost'
51 htmlfile = 'bootgraph.html'
59 graph_filter = 'do_one_initcall'
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()
73 self.kernel = self.kernelVersion(val)
75 self.kernel = 'unknown'
76 self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')
77 def kernelVersion(self, msg):
79 def checkFtraceKernelVersion(self):
80 val = tuple(map(int, self.kernel.split('-')[0].split('.')))
84 def kernelParams(self):
85 cmdline = 'initcall_debug log_buf_len=32M'
88 bs = min(self.memtotal / 2, 2*1024*1024) / self.cpucount
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)
100 def setGraphFilter(self, val):
101 master = self.getBootFtraceFilterFunctions()
103 for i in val.split(','):
106 doError('badly formatted filter function string')
107 if '[' in func or ']' in func:
108 doError('loadable module functions not allowed - "%s"' % 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)
118 doError('badly formatted filter function string')
119 self.graph_filter = fs
120 def getBootFtraceFilterFunctions(self):
122 fp = open(self.tpath+'available_filter_functions')
123 fulllist = fp.read().split('\n')
127 if not i or ' ' in i or '[' in i or ']' in i:
131 def myCronJob(self, line):
132 if '@reboot' not in line:
134 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:
137 def cronjobCmdString(self):
138 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
139 args = iter(sys.argv[1:])
141 if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
143 elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
146 elif arg == '-result':
147 cmdline += ' %s "%s"' % (arg, os.path.abspath(args.next()))
149 elif arg == '-cgskip':
150 file = self.configFile(args.next())
151 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
154 if self.graph_filter != 'do_one_initcall':
155 cmdline += ' -func "%s"' % self.graph_filter
156 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)
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
168 for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
171 blcmd = self.getExec(cmd)
173 doError('[GRUB] missing update command')
174 if not os.path.exists('/etc/default/grub'):
175 doError('[GRUB] missing /etc/default/grub')
177 cfg = '/boot/grub2/grub.cfg'
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]
185 self.blexec = [blcmd, '-o', cfg]
186 def getBootLoader(self):
187 if self.bootloader == 'grub':
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)
200 sysvals = SystemValues()
204 # The primary container for test data.
205 class Data(aslib.Data):
206 dmesg = {} # root data structure
207 start = 0.0 # test start
209 dmesgtext = [] # dmesg text file in memory
216 phases = ['kernel', 'user']
217 do_one_initcall = False
218 def __init__(self, num):
219 self.testnumber = num
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'}
228 def deviceTopology(self):
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']
236 if(start >= 0 and end >= 0):
241 name = '%s[%d]' % (origname, i)
243 list[name] = {'name': name, 'start': start, 'end': end,
244 'pid': pid, 'length': length, 'row': 0, 'id': devid,
245 'ret': ret, 'ulen': ulen }
247 def deviceMatch(self, pid, cg):
248 if cg.end - cg.start == 0:
250 for p in data.phases:
251 list = self.dmesg[p]['list']
254 if pid != dev['pid']:
256 if cg.name == 'do_one_initcall':
257 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
259 self.do_one_initcall = True
262 if(cg.start > dev['start'] and cg.end < dev['end']):
263 if 'ftraces' not in dev:
265 dev['ftraces'].append(cg)
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))
280 # ----------------- FUNCTIONS --------------------
282 # Function: parseKernelLog
284 # parse a kernel log for boot data
285 def parseKernelLog():
286 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
287 os.path.basename(sysvals.dmesgfile))
290 data.dmesg['kernel']['start'] = data.start = ktime = 0.0
292 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
293 'host': sysvals.hostname,
294 'mode': 'boot', 'kernel': ''}
296 tp = aslib.TestProps()
298 if(sysvals.dmesgfile):
299 lf = open(sysvals.dmesgfile, 'r')
301 lf = Popen('dmesg', stdout=PIPE).stdout
303 line = line.replace('\r\n', '')
304 # grab the stamp and sysinfo
305 if re.match(tp.stampfmt, line):
308 elif re.match(tp.sysinfofmt, line):
311 elif re.match(tp.cmdlinefmt, line):
314 elif re.match(tp.kparamsfmt, line):
320 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
323 ktime = float(m.group('ktime'))
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)
332 m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg)
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')
339 m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
342 pid = int(m.group('p'))
343 devtemp[func] = (ktime, pid)
345 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
349 f, r, t = m.group('f', 'r', 't')
351 start, pid = devtemp[f]
352 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
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
363 tp.parseStamp(data, sysvals)
364 data.dmesg['user']['end'] = data.end
368 # Function: parseTraceLog
370 # Check if trace is available and copy to a temp file
371 def parseTraceLog(data):
372 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
373 os.path.basename(sysvals.ftracefile))
374 # if available, calculate cgfilter allowable ranges
376 if len(sysvals.cgfilter) > 0:
377 for p in data.phases:
378 list = data.dmesg[p]['list']
379 for i in sysvals.cgfilter:
381 cgfilter.append([list[i]['start']-0.0001,
382 list[i]['end']+0.0001])
383 # parse the trace log
385 tp = aslib.TestProps()
386 tp.setTracerType('function_graph')
387 tf = open(sysvals.ftracefile, 'r')
391 m = re.match(tp.ftrace_line_fmt, line.strip())
394 m_time, m_proc, m_pid, m_msg, m_dur = \
395 m.group('time', 'proc', 'pid', 'msg', 'dur')
397 if len(cgfilter) > 0:
400 if t >= r[0] and t < r[1]:
407 if(m_time and m_pid and m_msg):
408 t = aslib.FTraceLine(m_time, m_msg, m_dur)
412 if t.fevent or t.fkprobe:
415 if(key not in ftemp):
417 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
421 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
423 ftemp[key][-1].addLine(t)
427 # add the callgraph data to the device hierarchy
430 for cg in ftemp[key]:
431 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
433 if(not cg.postProcess()):
434 print('Sanity check failed for %s-%d' % (proc, pid))
436 # match cg data to devices
437 devname = data.deviceMatch(pid, cg)
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))
448 # Function: retrieveLogs
450 # Create copies of dmesg and/or ftrace for later processing
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:
465 sysvals.writeDatafileHeader(sysvals.ftracefile)
466 call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)
468 # Function: colorForName
470 # Generate a repeatable color from a list for a given name
471 def colorForName(name):
488 total += ord(name[i])
490 return list[total % count]
492 def cgOverview(cg, minlen):
496 if l.fcall and l.depth == 1:
497 if l.length >= minlen:
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)
505 # Function: createBootGraph
507 # Create the output html file from the resident test data
509 # testruns: array of Data objects from parseKernelLog or parseTraceLog
511 # True if the html file was created, false if it failed
512 def 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>'\
521 devtl = aslib.Timeline(100, 20)
523 # write the test title and general info header
524 devtl.createHeader(sysvals, sysvals.stamp)
526 # Generate the header for this timeline
531 print('ERROR: No timeline data')
533 user_mode = '%.0f'%(data.tUserMode*1000)
534 last_init = '%.0f'%(tTotal*1000)
535 devtl.html += html_timetotal.format(user_mode, last_init)
537 # determine the maximum number of rows we need to draw
539 for p in data.phases:
540 list = data.dmesg[p]['list']
542 d = aslib.DevItem(0, p, list[devname])
544 devtl.getPhaseRows(devlist, 0, 'start')
545 devtl.calcTotalRows()
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, \
559 # draw the device timeline
562 for phase in data.phases:
563 list = data.dmesg[phase]['list']
564 for devname in sorted(list):
565 cls, color = colorForName(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}
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):
586 large, stats = cgOverview(cg, 0.001)
587 devstats[dev['id']]['fstat'] = stats
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)
596 if('ftraces' not in dev):
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)
604 devtl.html += html_srccall.format(cg.name, left,
605 top, height, width, title, dev['id']+cg.id)
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'
612 # timeline is finished
613 devtl.html += '</div>\n</div>\n'
615 # draw a legend which describes the phases by color
616 devtl.html += '<div class="legend">\n'
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'
625 hf = open(sysvals.htmlfile, 'w')
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)
647 # write the device timeline
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:
659 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
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+\
674 # add the callgraph html
675 if(sysvals.usecallgraph):
676 aslib.addCallgraphs(sysvals, hf, data)
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
683 hf.write('<div id="dmesglog" style="display:none;">\n')
684 for line in data.dmesgtext:
685 line = line.replace('<', '<').replace('>', '>')
689 # write the footer and close
690 aslib.addScriptCode(hf, [data])
691 hf.write('</body>\n</html>\n')
695 # Function: updateCron
697 # (restore=False) Set the tool to run automatically on reboot
698 # (restore=True) Restore the original crontab
699 def updateCron(restore=False):
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')
711 doError('crontab not found')
712 # on restore: move the backup cron back into place
714 if os.path.exists(backfile):
715 shutil.move(backfile, cronfile)
716 call([cmd, cronfile])
718 # backup current cron and install new one with reboot
719 if os.path.exists(cronfile):
720 shutil.move(cronfile, backfile)
722 fp = open(backfile, 'w')
726 fp = open(backfile, 'r')
727 op = open(cronfile, 'w')
729 if not sysvals.myCronJob(line):
733 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
735 res = call([cmd, cronfile])
737 print 'Exception: %s' % str(e)
738 shutil.move(backfile, cronfile)
741 doError('crontab failed')
743 # Function: updateGrub
745 # update grub.cfg for all kernels with our parameters
746 def updateGrub(restore=False):
747 # call update-grub on restore
750 call(sysvals.blexec, stderr=PIPE, stdout=PIPE,
751 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'})
753 print 'Exception: %s\n' % str(e)
755 # extract the option and create a grub config without it
756 sysvals.rootUser(True)
757 tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
759 grubfile = '/etc/default/grub'
760 tempfile = '/etc/default/grub.analyze_boot'
761 shutil.move(grubfile, tempfile)
764 fp = open(tempfile, 'r')
765 op = open(grubfile, 'w')
769 if len(line) == 0 or line[0] == '#':
771 opt = line.split('=')[0].strip()
773 cmdline = line.split('=', 1)[1].strip('\\')
777 cmdline += line.strip('\\')
781 op.write('%s\n' % line)
783 # if the target option value is in quotes, strip them
785 val = cmdline.strip()
786 if val and (val[0] == '\'' or val[0] == '"'):
790 # append our cmd line options
793 cmdline += sysvals.kernelParams()
794 # write out the updated target option
795 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
797 res = call(sysvals.blexec)
800 print 'Exception: %s' % str(e)
803 shutil.move(tempfile, grubfile)
805 doError('update grub failed')
807 # Function: updateKernelParams
809 # update boot conf for all kernels with our parameters
810 def updateKernelParams(restore=False):
811 # find the boot loader
812 sysvals.getBootLoader()
813 if sysvals.bootloader == 'grub':
816 # Function: doError Description:
817 # generic error function for catastrphic failures
819 # msg: the error message to print
820 # help: True if printHelp should be called after, False otherwise
821 def doError(msg, help=False):
824 print 'ERROR: %s\n' % msg
825 sysvals.outputResult({'error':msg})
828 # Function: printHelp
830 # print out the help text
833 print('%s v%s' % (sysvals.title, sysvals.version))
834 print('Usage: bootgraph <options> <command>')
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.')
841 print(' If no specific command is given the tool reads the current dmesg')
842 print(' and/or ftrace log and creates a timeline')
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')
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}')
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)')
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')
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)')
880 # ----------------- MAIN --------------------
881 # exec start (skipped if script is loaded as library)
882 if __name__ == '__main__':
883 # loop through the command line arguments
886 switchoff = ['disable', 'off', 'false', '0']
887 simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
890 cgskip = sysvals.configFile('cgskip.txt')
891 args = iter(sys.argv[1:])
898 print("Version %s" % sysvals.version)
900 elif(arg == '-verbose'):
901 sysvals.verbose = True
902 elif(arg in simplecmds):
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'):
917 doError('No callgraph functions supplied', True)
918 sysvals.setCallgraphFilter(val)
919 elif(arg == '-cgskip'):
923 doError('No file supplied', True)
924 if val.lower() in switchoff:
927 cgskip = sysvals.configFile(val)
929 doError('%s does not exist' % cgskip)
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'):
942 sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
943 elif(arg == '-func'):
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'):
956 doError('No ftrace file supplied', True)
957 if(os.path.exists(val) == False):
958 doError('%s does not exist' % val)
960 sysvals.ftracefile = val
961 elif(arg == '-addlogs'):
962 sysvals.dmesglog = True
963 elif(arg == '-expandcg'):
965 elif(arg == '-dmesg'):
969 doError('No dmesg file supplied', True)
970 if(os.path.exists(val) == False):
971 doError('%s does not exist' % val)
973 sysvals.dmesgfile = val
978 doError('No subdirectory name supplied', True)
979 sysvals.testdir = sysvals.setOutputFolder(val)
980 elif(arg == '-result'):
984 doError('No result file supplied', True)
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
995 doError('Invalid argument: '+arg, True)
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')
1009 # run utility commands
1012 if cmd == 'kpupdate':
1013 updateKernelParams()
1014 elif cmd == 'flistall':
1015 for f in sysvals.getBootFtraceFilterFunctions():
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)
1024 # reboot: update grub, setup a cronjob, and 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()
1034 sysvals.manualRebootRequired()
1037 if sysvals.usecallgraph and cgskip:
1038 sysvals.vprint('Using cgskip file: %s' % cgskip)
1039 sysvals.setCallgraphBlacklist(cgskip)
1041 # cronjob: remove the cronjob, grub changes, and disable ftrace
1042 if sysvals.iscronjob:
1044 updateKernelParams(True)
1046 sysvals.fsetVal('0', 'tracing_on')
1050 # testrun: generate copies of the logs
1054 sysvals.setOutputFile()
1056 # process the log data
1057 if sysvals.dmesgfile:
1059 sysvals.max_graph_depth = 0
1060 data = parseKernelLog()
1062 doError('No initcall data found in %s' % sysvals.dmesgfile)
1063 if sysvals.useftrace and sysvals.ftracefile:
1069 doError('dmesg file required')
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)
1075 createBootGraph(data)
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)
1083 sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
1084 sysvals.stamp['lastinit'] = data.end * 1000
1085 sysvals.outputResult(sysvals.stamp)