2 # SPDX-License-Identifier: GPL-2.0-only
4 # Tool for analyzing boot timing
5 # Copyright (c) 2013, Intel Corporation.
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.
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
17 # Todd Brandt <todd.e.brandt@linux.intel.com>
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.
25 # ----------------- LIBRARIES --------------------
34 from datetime import datetime, timedelta
35 from subprocess import call, Popen, PIPE
36 import sleepgraph as aslib
42 # ----------------- CLASSES --------------------
46 # A global, single-instance container used to
47 # store system values and test parameters
48 class SystemValues(aslib.SystemValues):
51 hostname = 'localhost'
56 htmlfile = 'bootgraph.html'
64 graph_filter = 'do_one_initcall'
72 self.hostname = 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 val = fp.read().strip()
78 self.kernel = self.kernelVersion(val)
80 self.kernel = 'unknown'
81 self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')
82 def kernelVersion(self, msg):
84 def checkFtraceKernelVersion(self):
85 val = tuple(map(int, self.kernel.split('-')[0].split('.')))
89 def kernelParams(self):
90 cmdline = 'initcall_debug log_buf_len=32M'
93 bs = min(self.memtotal // 2, 2*1024*1024) // self.cpucount
96 cmdline += ' trace_buf_size=%dK trace_clock=global '\
97 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\
98 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\
99 'nofuncgraph-overhead,context-info,graph-time '\
100 'ftrace=function_graph '\
101 'ftrace_graph_max_depth=%d '\
102 'ftrace_graph_filter=%s' % \
103 (bs, self.max_graph_depth, self.graph_filter)
105 def setGraphFilter(self, val):
106 master = self.getBootFtraceFilterFunctions()
108 for i in val.split(','):
111 doError('badly formatted filter function string')
112 if '[' in func or ']' in func:
113 doError('loadable module functions not allowed - "%s"' % func)
115 doError('spaces found in filter functions - "%s"' % func)
116 if func not in master:
117 doError('function "%s" not available for ftrace' % func)
123 doError('badly formatted filter function string')
124 self.graph_filter = fs
125 def getBootFtraceFilterFunctions(self):
127 fp = open(self.tpath+'available_filter_functions')
128 fulllist = fp.read().split('\n')
132 if not i or ' ' in i or '[' in i or ']' in i:
136 def myCronJob(self, line):
137 if '@reboot' not in line:
139 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:
142 def cronjobCmdString(self):
143 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
144 args = iter(sys.argv[1:])
146 if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
148 elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
151 elif arg == '-result':
152 cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args)))
154 elif arg == '-cgskip':
155 file = self.configFile(next(args))
156 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
159 if self.graph_filter != 'do_one_initcall':
160 cmdline += ' -func "%s"' % self.graph_filter
161 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)
163 def manualRebootRequired(self):
164 cmdline = self.kernelParams()
165 pprint('To generate a new timeline manually, follow these steps:\n\n'\
166 '1. Add the CMDLINE string to your kernel command line.\n'\
167 '2. Reboot the system.\n'\
168 '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\
169 'CMDLINE="%s"' % cmdline)
173 for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
176 blcmd = self.getExec(cmd)
178 doError('[GRUB] missing update command')
179 if not os.path.exists('/etc/default/grub'):
180 doError('[GRUB] missing /etc/default/grub')
182 cfg = '/boot/grub2/grub.cfg'
184 cfg = '/boot/grub/grub.cfg'
185 if not os.path.exists(cfg):
186 doError('[GRUB] missing %s' % cfg)
187 if 'update-grub' in blcmd:
188 self.blexec = [blcmd]
190 self.blexec = [blcmd, '-o', cfg]
191 def getBootLoader(self):
192 if self.bootloader == 'grub':
195 doError('unknown boot loader: %s' % self.bootloader)
196 def writeDatafileHeader(self, filename):
197 self.kparams = open('/proc/cmdline', 'r').read().strip()
198 fp = open(filename, 'w')
199 fp.write(self.teststamp+'\n')
200 fp.write(self.sysstamp+'\n')
201 fp.write('# command | %s\n' % self.cmdline)
202 fp.write('# kparams | %s\n' % self.kparams)
205 sysvals = SystemValues()
209 # The primary container for test data.
210 class Data(aslib.Data):
211 dmesg = {} # root data structure
212 start = 0.0 # test start
214 dmesgtext = [] # dmesg text file in memory
221 phases = ['kernel', 'user']
222 do_one_initcall = False
223 def __init__(self, num):
224 self.testnumber = num
228 'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
229 'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'},
230 'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
231 'order': 1, 'color': '#fff'}
233 def deviceTopology(self):
235 def newAction(self, phase, name, pid, start, end, ret, ulen):
236 # new device callback for a specific phase
237 self.html_device_id += 1
238 devid = '%s%d' % (self.idstr, self.html_device_id)
239 list = self.dmesg[phase]['list']
241 if(start >= 0 and end >= 0):
246 name = '%s[%d]' % (origname, i)
248 list[name] = {'name': name, 'start': start, 'end': end,
249 'pid': pid, 'length': length, 'row': 0, 'id': devid,
250 'ret': ret, 'ulen': ulen }
252 def deviceMatch(self, pid, cg):
253 if cg.end - cg.start == 0:
255 for p in data.phases:
256 list = self.dmesg[p]['list']
259 if pid != dev['pid']:
261 if cg.name == 'do_one_initcall':
262 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
264 self.do_one_initcall = True
267 if(cg.start > dev['start'] and cg.end < dev['end']):
268 if 'ftraces' not in dev:
270 dev['ftraces'].append(cg)
273 def printDetails(self):
274 sysvals.vprint('Timeline Details:')
275 sysvals.vprint(' Host: %s' % sysvals.hostname)
276 sysvals.vprint(' Kernel: %s' % sysvals.kernel)
277 sysvals.vprint(' Test time: %s' % sysvals.testtime)
278 sysvals.vprint(' Boot time: %s' % self.boottime)
279 for phase in self.phases:
280 dc = len(self.dmesg[phase]['list'])
281 sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,
282 self.dmesg[phase]['start']*1000,
283 self.dmesg[phase]['end']*1000, dc))
285 # ----------------- FUNCTIONS --------------------
287 # Function: parseKernelLog
289 # parse a kernel log for boot data
290 def parseKernelLog():
291 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
292 os.path.basename(sysvals.dmesgfile))
295 data.dmesg['kernel']['start'] = data.start = ktime = 0.0
297 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
298 'host': sysvals.hostname,
299 'mode': 'boot', 'kernel': ''}
301 tp = aslib.TestProps()
303 if(sysvals.dmesgfile):
304 lf = open(sysvals.dmesgfile, 'rb')
306 lf = Popen('dmesg', stdout=PIPE).stdout
308 line = aslib.ascii(line).replace('\r\n', '')
309 # grab the stamp and sysinfo
310 if re.match(tp.stampfmt, line):
313 elif re.match(tp.sysinfofmt, line):
316 elif re.match(tp.cmdlinefmt, line):
319 elif re.match(tp.kparamsfmt, line):
325 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
328 ktime = float(m.group('ktime'))
332 data.dmesgtext.append(line)
333 if(ktime == 0.0 and re.match('^Linux version .*', msg)):
334 if(not sysvals.stamp['kernel']):
335 sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
337 m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg)
339 bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S')
340 bt = bt - timedelta(seconds=int(ktime))
341 data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
342 sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
344 m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
347 pid = int(m.group('p'))
348 devtemp[func] = (ktime, pid)
350 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
354 f, r, t = m.group('f', 'r', 't')
356 start, pid = devtemp[f]
357 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
360 if(re.match('^Freeing unused kernel .*', msg)):
361 data.tUserMode = ktime
362 data.dmesg['kernel']['end'] = ktime
363 data.dmesg['user']['start'] = ktime
368 tp.parseStamp(data, sysvals)
369 data.dmesg['user']['end'] = data.end
373 # Function: parseTraceLog
375 # Check if trace is available and copy to a temp file
376 def parseTraceLog(data):
377 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
378 os.path.basename(sysvals.ftracefile))
379 # if available, calculate cgfilter allowable ranges
381 if len(sysvals.cgfilter) > 0:
382 for p in data.phases:
383 list = data.dmesg[p]['list']
384 for i in sysvals.cgfilter:
386 cgfilter.append([list[i]['start']-0.0001,
387 list[i]['end']+0.0001])
388 # parse the trace log
390 tp = aslib.TestProps()
391 tp.setTracerType('function_graph')
392 tf = open(sysvals.ftracefile, 'r')
396 m = re.match(tp.ftrace_line_fmt, line.strip())
399 m_time, m_proc, m_pid, m_msg, m_dur = \
400 m.group('time', 'proc', 'pid', 'msg', 'dur')
402 if len(cgfilter) > 0:
405 if t >= r[0] and t < r[1]:
412 if(m_time and m_pid and m_msg):
413 t = aslib.FTraceLine(m_time, m_msg, m_dur)
417 if t.fevent or t.fkprobe:
420 if(key not in ftemp):
422 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
426 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
428 ftemp[key][-1].addLine(t)
432 # add the callgraph data to the device hierarchy
435 for cg in ftemp[key]:
436 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
438 if(not cg.postProcess()):
439 pprint('Sanity check failed for %s-%d' % (proc, pid))
441 # match cg data to devices
442 devname = data.deviceMatch(pid, cg)
447 sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\
448 (kind, cg.name, proc, pid, cg.start, cg.end))
449 elif len(cg.list) > 1000000:
450 pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\
451 (devname, len(cg.list)))
453 # Function: retrieveLogs
455 # Create copies of dmesg and/or ftrace for later processing
457 # check ftrace is configured first
458 if sysvals.useftrace:
459 tracer = sysvals.fgetVal('current_tracer').strip()
460 if tracer != 'function_graph':
461 doError('ftrace not configured for a boot callgraph')
462 # create the folder and get dmesg
463 sysvals.systemInfo(aslib.dmidecode(sysvals.mempath))
464 sysvals.initTestOutput('boot')
465 sysvals.writeDatafileHeader(sysvals.dmesgfile)
466 call('dmesg >> '+sysvals.dmesgfile, shell=True)
467 if not sysvals.useftrace:
470 sysvals.writeDatafileHeader(sysvals.ftracefile)
471 call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)
473 # Function: colorForName
475 # Generate a repeatable color from a list for a given name
476 def colorForName(name):
493 total += ord(name[i])
495 return list[total % count]
497 def cgOverview(cg, minlen):
501 if l.fcall and l.depth == 1:
502 if l.length >= minlen:
504 if l.name not in stats:
505 stats[l.name] = [0, 0.0]
506 stats[l.name][0] += (l.length * 1000.0)
507 stats[l.name][1] += 1
508 return (large, stats)
510 # Function: createBootGraph
512 # Create the output html file from the resident test data
514 # testruns: array of Data objects from parseKernelLog or parseTraceLog
516 # True if the html file was created, false if it failed
517 def createBootGraph(data):
518 # html function templates
519 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'
520 html_timetotal = '<table class="time1">\n<tr>'\
521 '<td class="blue">Init process starts @ <b>{0} ms</b></td>'\
522 '<td class="blue">Last initcall ends @ <b>{1} ms</b></td>'\
526 devtl = aslib.Timeline(100, 20)
528 # write the test title and general info header
529 devtl.createHeader(sysvals, sysvals.stamp)
531 # Generate the header for this timeline
536 pprint('ERROR: No timeline data')
538 user_mode = '%.0f'%(data.tUserMode*1000)
539 last_init = '%.0f'%(tTotal*1000)
540 devtl.html += html_timetotal.format(user_mode, last_init)
542 # determine the maximum number of rows we need to draw
544 for p in data.phases:
545 list = data.dmesg[p]['list']
547 d = aslib.DevItem(0, p, list[devname])
549 devtl.getPhaseRows(devlist, 0, 'start')
550 devtl.calcTotalRows()
552 # draw the timeline background
553 devtl.createZoomBox()
554 devtl.html += devtl.html_tblock.format('boot', '0', '100', devtl.scaleH)
555 for p in data.phases:
556 phase = data.dmesg[p]
557 length = phase['end']-phase['start']
558 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
559 width = '%.3f' % ((length*100.0)/tTotal)
560 devtl.html += devtl.html_phase.format(left, width, \
561 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
564 # draw the device timeline
567 for phase in data.phases:
568 list = data.dmesg[phase]['list']
569 for devname in sorted(list):
570 cls, color = colorForName(devname)
572 info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0,
573 dev['ulen']/1000.0, dev['ret'])
574 devstats[dev['id']] = {'info':info}
576 height = devtl.phaseRowHeight(0, phase, dev['row'])
577 top = '%.6f' % ((dev['row']*height) + devtl.scaleH)
578 left = '%.6f' % (((dev['start']-t0)*100)/tTotal)
579 width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal)
580 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
581 devtl.html += devtl.html_device.format(dev['id'],
582 devname+length+phase+'_mode', left, top, '%.3f'%height,
583 width, devname, ' '+cls, '')
584 rowtop = devtl.phaseRowTop(0, phase, dev['row'])
585 height = '%.6f' % (devtl.rowH / 2)
586 top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2))
587 if data.do_one_initcall:
588 if('ftrace' not in dev):
591 large, stats = cgOverview(cg, 0.001)
592 devstats[dev['id']]['fstat'] = stats
594 left = '%f' % (((l.time-t0)*100)/tTotal)
595 width = '%f' % (l.length*100/tTotal)
596 title = '%s (%0.3fms)' % (l.name, l.length * 1000.0)
597 devtl.html += html_srccall.format(l.name, left,
598 top, height, width, title, 'x%d'%num)
601 if('ftraces' not in dev):
603 for cg in dev['ftraces']:
604 left = '%f' % (((cg.start-t0)*100)/tTotal)
605 width = '%f' % ((cg.end-cg.start)*100/tTotal)
606 cglen = (cg.end - cg.start) * 1000.0
607 title = '%s (%0.3fms)' % (cg.name, cglen)
609 devtl.html += html_srccall.format(cg.name, left,
610 top, height, width, title, dev['id']+cg.id)
613 # draw the time scale, try to make the number of labels readable
614 devtl.createTimeScale(t0, tMax, tTotal, 'boot')
615 devtl.html += '</div>\n'
617 # timeline is finished
618 devtl.html += '</div>\n</div>\n'
620 # draw a legend which describes the phases by color
621 devtl.html += '<div class="legend">\n'
624 for phase in data.phases:
625 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
626 devtl.html += devtl.html_legend.format(order, \
627 data.dmesg[phase]['color'], phase+'_mode', phase[0])
628 devtl.html += '</div>\n'
630 hf = open(sysvals.htmlfile, 'w')
634 .c1 {background:rgba(209,0,0,0.4);}\n\
635 .c2 {background:rgba(255,102,34,0.4);}\n\
636 .c3 {background:rgba(255,218,33,0.4);}\n\
637 .c4 {background:rgba(51,221,0,0.4);}\n\
638 .c5 {background:rgba(17,51,204,0.4);}\n\
639 .c6 {background:rgba(34,0,102,0.4);}\n\
640 .c7 {background:rgba(51,0,68,0.4);}\n\
641 .c8 {background:rgba(204,255,204,0.4);}\n\
642 .c9 {background:rgba(169,208,245,0.4);}\n\
643 .c10 {background:rgba(255,255,204,0.4);}\n\
644 .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\
645 table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\
646 .fstat th {width:55px;}\n\
647 .fstat td {text-align:left;width:35px;}\n\
648 .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\
649 .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
650 aslib.addCSS(hf, sysvals, 1, False, extra)
652 # write the device timeline
655 # add boot specific html
656 statinfo = 'var devstats = {\n'
657 for n in sorted(devstats):
658 statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info'])
659 if 'fstat' in devstats[n]:
660 funcs = devstats[n]['fstat']
661 for f in sorted(funcs, key=lambda k:(funcs[k], k), reverse=True):
662 if funcs[f][0] < 0.01 and len(funcs) > 10:
664 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
668 '<div id="devicedetailtitle"></div>\n'\
669 '<div id="devicedetail" style="display:none;">\n'\
670 '<div id="devicedetail0">\n'
671 for p in data.phases:
672 phase = data.dmesg[p]
673 html += devtl.html_phaselet.format(p+'_mode', '0', '100', phase['color'])
674 html += '</div>\n</div>\n'\
675 '<script type="text/javascript">\n'+statinfo+\
679 # add the callgraph html
680 if(sysvals.usecallgraph):
681 aslib.addCallgraphs(sysvals, hf, data)
683 # add the test log as a hidden div
684 if sysvals.testlog and sysvals.logmsg:
685 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
686 # add the dmesg log as a hidden div
688 hf.write('<div id="dmesglog" style="display:none;">\n')
689 for line in data.dmesgtext:
690 line = line.replace('<', '<').replace('>', '>')
694 # write the footer and close
695 aslib.addScriptCode(hf, [data])
696 hf.write('</body>\n</html>\n')
700 # Function: updateCron
702 # (restore=False) Set the tool to run automatically on reboot
703 # (restore=True) Restore the original crontab
704 def updateCron(restore=False):
706 sysvals.rootUser(True)
707 crondir = '/var/spool/cron/crontabs/'
708 if not os.path.exists(crondir):
709 crondir = '/var/spool/cron/'
710 if not os.path.exists(crondir):
711 doError('%s not found' % crondir)
712 cronfile = crondir+'root'
713 backfile = crondir+'root-analyze_boot-backup'
714 cmd = sysvals.getExec('crontab')
716 doError('crontab not found')
717 # on restore: move the backup cron back into place
719 if os.path.exists(backfile):
720 shutil.move(backfile, cronfile)
721 call([cmd, cronfile])
723 # backup current cron and install new one with reboot
724 if os.path.exists(cronfile):
725 shutil.move(cronfile, backfile)
727 fp = open(backfile, 'w')
731 fp = open(backfile, 'r')
732 op = open(cronfile, 'w')
734 if not sysvals.myCronJob(line):
738 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
740 res = call([cmd, cronfile])
741 except Exception as e:
742 pprint('Exception: %s' % str(e))
743 shutil.move(backfile, cronfile)
746 doError('crontab failed')
748 # Function: updateGrub
750 # update grub.cfg for all kernels with our parameters
751 def updateGrub(restore=False):
752 # call update-grub on restore
755 call(sysvals.blexec, stderr=PIPE, stdout=PIPE,
756 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'})
757 except Exception as e:
758 pprint('Exception: %s\n' % str(e))
760 # extract the option and create a grub config without it
761 sysvals.rootUser(True)
762 tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
764 grubfile = '/etc/default/grub'
765 tempfile = '/etc/default/grub.analyze_boot'
766 shutil.move(grubfile, tempfile)
769 fp = open(tempfile, 'r')
770 op = open(grubfile, 'w')
774 if len(line) == 0 or line[0] == '#':
776 opt = line.split('=')[0].strip()
778 cmdline = line.split('=', 1)[1].strip('\\')
782 cmdline += line.strip('\\')
786 op.write('%s\n' % line)
788 # if the target option value is in quotes, strip them
790 val = cmdline.strip()
791 if val and (val[0] == '\'' or val[0] == '"'):
795 # append our cmd line options
798 cmdline += sysvals.kernelParams()
799 # write out the updated target option
800 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
802 res = call(sysvals.blexec)
804 except Exception as e:
805 pprint('Exception: %s' % str(e))
808 shutil.move(tempfile, grubfile)
810 doError('update grub failed')
812 # Function: updateKernelParams
814 # update boot conf for all kernels with our parameters
815 def updateKernelParams(restore=False):
816 # find the boot loader
817 sysvals.getBootLoader()
818 if sysvals.bootloader == 'grub':
821 # Function: doError Description:
822 # generic error function for catastrphic failures
824 # msg: the error message to print
825 # help: True if printHelp should be called after, False otherwise
826 def doError(msg, help=False):
829 pprint('ERROR: %s\n' % msg)
830 sysvals.outputResult({'error':msg})
833 # Function: printHelp
835 # print out the help text
838 'Usage: bootgraph <options> <command>\n'\
841 ' This tool reads in a dmesg log of linux kernel boot and\n'\
842 ' creates an html representation of the boot timeline up to\n'\
843 ' the start of the init process.\n'\
845 ' If no specific command is given the tool reads the current dmesg\n'\
846 ' and/or ftrace log and creates a timeline\n'\
848 ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\
849 ' HTML output: <hostname>_boot.html\n'\
850 ' raw dmesg output: <hostname>_boot_dmesg.txt\n'\
851 ' raw ftrace output: <hostname>_boot_ftrace.txt\n'\
854 ' -h Print this help text\n'\
855 ' -v Print the current tool version\n'\
856 ' -verbose Print extra information during execution and analysis\n'\
857 ' -addlogs Add the dmesg log to the html output\n'\
858 ' -result fn Export a results table to a text file for parsing.\n'\
859 ' -o name Overrides the output subdirectory name when running a new test\n'\
860 ' default: boot-{date}-{time}\n'\
862 ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\
863 ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\
864 ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\
865 ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\
866 ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\
867 ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\
868 ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\
869 ' -cgfilter S Filter the callgraph output in the timeline\n'\
870 ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\
871 ' -bl name Use the following boot loader for kernel params (default: grub)\n'\
872 ' -reboot Reboot the machine automatically and generate a new timeline\n'\
873 ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\
876 ' -flistall Print all functions capable of being captured in ftrace\n'\
877 ' -sysinfo Print out system info extracted from BIOS\n'\
878 ' -which exec Print an executable path, should function even without PATH\n'\
880 ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\
881 ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\
882 '' % (sysvals.title, sysvals.version))
885 # ----------------- MAIN --------------------
886 # exec start (skipped if script is loaded as library)
887 if __name__ == '__main__':
888 # loop through the command line arguments
891 switchoff = ['disable', 'off', 'false', '0']
892 simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
895 cgskip = sysvals.configFile('cgskip.txt')
896 args = iter(sys.argv[1:])
903 pprint("Version %s" % sysvals.version)
905 elif(arg == '-verbose'):
906 sysvals.verbose = True
907 elif(arg in simplecmds):
909 elif(arg == '-fstat'):
910 sysvals.useftrace = True
911 elif(arg == '-callgraph' or arg == '-f'):
912 sysvals.useftrace = True
913 sysvals.usecallgraph = True
914 elif(arg == '-cgdump'):
915 sysvals.cgdump = True
916 elif(arg == '-mincg'):
917 sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
918 elif(arg == '-cgfilter'):
922 doError('No callgraph functions supplied', True)
923 sysvals.setCallgraphFilter(val)
924 elif(arg == '-cgskip'):
928 doError('No file supplied', True)
929 if val.lower() in switchoff:
932 cgskip = sysvals.configFile(val)
934 doError('%s does not exist' % cgskip)
939 doError('No boot loader name supplied', True)
940 if val.lower() not in ['grub']:
941 doError('Unknown boot loader: %s' % val, True)
942 sysvals.bootloader = val.lower()
943 elif(arg == '-timeprec'):
944 sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
945 elif(arg == '-maxdepth'):
947 sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
948 elif(arg == '-func'):
952 doError('No filter functions supplied', True)
953 sysvals.useftrace = True
954 sysvals.usecallgraph = True
955 sysvals.rootCheck(True)
956 sysvals.setGraphFilter(val)
957 elif(arg == '-ftrace'):
961 doError('No ftrace file supplied', True)
962 if(os.path.exists(val) == False):
963 doError('%s does not exist' % val)
965 sysvals.ftracefile = val
966 elif(arg == '-addlogs'):
967 sysvals.dmesglog = True
968 elif(arg == '-expandcg'):
970 elif(arg == '-dmesg'):
974 doError('No dmesg file supplied', True)
975 if(os.path.exists(val) == False):
976 doError('%s does not exist' % val)
978 sysvals.dmesgfile = val
983 doError('No subdirectory name supplied', True)
984 sysvals.testdir = sysvals.setOutputFolder(val)
985 elif(arg == '-result'):
989 doError('No result file supplied', True)
991 elif(arg == '-reboot'):
992 sysvals.reboot = True
993 elif(arg == '-manual'):
994 sysvals.reboot = True
995 sysvals.manual = True
996 # remaining options are only for cron job use
997 elif(arg == '-cronjob'):
998 sysvals.iscronjob = True
999 elif(arg == '-which'):
1003 doError('No executable supplied', True)
1004 out = sysvals.getExec(val)
1006 print('%s not found' % val)
1011 doError('Invalid argument: '+arg, True)
1013 # compatibility errors and access checks
1014 if(sysvals.iscronjob and (sysvals.reboot or \
1015 sysvals.dmesgfile or sysvals.ftracefile or cmd)):
1016 doError('-cronjob is meant for batch purposes only')
1017 if(sysvals.reboot and (sysvals.dmesgfile or sysvals.ftracefile)):
1018 doError('-reboot and -dmesg/-ftrace are incompatible')
1019 if cmd or sysvals.reboot or sysvals.iscronjob or testrun:
1020 sysvals.rootCheck(True)
1021 if (testrun and sysvals.useftrace) or cmd == 'flistall':
1022 if not sysvals.verifyFtrace():
1023 doError('Ftrace is not properly enabled')
1025 # run utility commands
1028 if cmd == 'kpupdate':
1029 updateKernelParams()
1030 elif cmd == 'flistall':
1031 for f in sysvals.getBootFtraceFilterFunctions():
1033 elif cmd == 'checkbl':
1034 sysvals.getBootLoader()
1035 pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec))
1036 elif(cmd == 'sysinfo'):
1037 sysvals.printSystemInfo(True)
1040 # reboot: update grub, setup a cronjob, and reboot
1042 if (sysvals.useftrace or sysvals.usecallgraph) and \
1043 not sysvals.checkFtraceKernelVersion():
1044 doError('Ftrace functionality requires kernel v4.10 or newer')
1045 if not sysvals.manual:
1046 updateKernelParams()
1050 sysvals.manualRebootRequired()
1053 if sysvals.usecallgraph and cgskip:
1054 sysvals.vprint('Using cgskip file: %s' % cgskip)
1055 sysvals.setCallgraphBlacklist(cgskip)
1057 # cronjob: remove the cronjob, grub changes, and disable ftrace
1058 if sysvals.iscronjob:
1060 updateKernelParams(True)
1062 sysvals.fsetVal('0', 'tracing_on')
1066 # testrun: generate copies of the logs
1070 sysvals.setOutputFile()
1072 # process the log data
1073 if sysvals.dmesgfile:
1075 sysvals.max_graph_depth = 0
1076 data = parseKernelLog()
1078 doError('No initcall data found in %s' % sysvals.dmesgfile)
1079 if sysvals.useftrace and sysvals.ftracefile:
1085 doError('dmesg file required')
1087 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
1088 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
1089 sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams)
1091 createBootGraph(data)
1093 # if running as root, change output dir owner to sudo_user
1094 if testrun and os.path.isdir(sysvals.testdir) and \
1095 os.getuid() == 0 and 'SUDO_USER' in os.environ:
1096 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
1097 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
1099 sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
1100 sysvals.stamp['lastinit'] = data.end * 1000
1101 sysvals.outputResult(sysvals.stamp)