1104 lines · python
1#!/usr/bin/env python32# SPDX-License-Identifier: GPL-2.0-only3#4# Tool for analyzing boot timing5# Copyright (c) 2013, Intel Corporation.6#7# This program is free software; you can redistribute it and/or modify it8# 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 WITHOUT12# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or13# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for14# 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 optimizing21# their linux stack's boot time. It creates an html representation of22# the kernel boot timeline up to the start of the init process.23#24 25# ----------------- LIBRARIES --------------------26 27import sys28import time29import os30import string31import re32import platform33import shutil34from datetime import datetime, timedelta35from subprocess import call, Popen, PIPE36import sleepgraph as aslib37 38def pprint(msg):39 print(msg)40 sys.stdout.flush()41 42# ----------------- CLASSES --------------------43 44# Class: SystemValues45# Description:46# A global, single-instance container used to47# store system values and test parameters48class 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 = False61 usecallgraph = False62 suspendmode = 'boot'63 max_graph_depth = 264 graph_filter = 'do_one_initcall'65 reboot = False66 manual = False67 iscronjob = False68 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(r'^[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(r'^(?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 True90 return False91 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.cpucount96 else:97 bs = 13107298 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 cmdline107 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 = func122 else:123 fs += ','+func124 if not fs:125 doError('badly formatted filter function string')126 self.graph_filter = fs127 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 continue136 list.append(i)137 return list138 def myCronJob(self, line):139 if '@reboot' not in line:140 return False141 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:142 return True143 return False144 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 continue150 elif arg in ['-o', '-dmesg', '-ftrace', '-func']:151 next(args)152 continue153 elif arg == '-result':154 cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args)))155 continue156 elif arg == '-cgskip':157 file = self.configFile(next(args))158 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))159 continue160 cmdline += ' '+arg161 if self.graph_filter != 'do_one_initcall':162 cmdline += ' -func "%s"' % self.graph_filter163 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)164 return cmdline165 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 break178 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: Data210# Description:211# The primary container for test data.212class Data(aslib.Data):213 dmesg = {} # root data structure214 start = 0.0 # test start215 end = 0.0 # test end216 dmesgtext = [] # dmesg text file in memory217 testnumber = 0218 idstr = ''219 html_device_id = 0220 valid = False221 tUserMode = 0.0222 boottime = ''223 phases = ['kernel', 'user']224 do_one_initcall = False225 def __init__(self, num):226 self.testnumber = num227 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 phase239 self.html_device_id += 1240 devid = '%s%d' % (self.idstr, self.html_device_id)241 list = self.dmesg[phase]['list']242 length = -1.0243 if(start >= 0 and end >= 0):244 length = end - start245 i = 2246 origname = name247 while(name in list):248 name = '%s[%d]' % (origname, i)249 i += 1250 list[name] = {'name': name, 'start': start, 'end': end,251 'pid': pid, 'length': length, 'row': 0, 'id': devid,252 'ret': ret, 'ulen': ulen }253 return name254 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 continue263 if cg.name == 'do_one_initcall':264 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):265 dev['ftrace'] = cg266 self.do_one_initcall = True267 return devname268 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 devname274 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: parseKernelLog290# Description:291# parse a kernel log for boot data292def 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.0298 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).stdout309 for line in lf:310 line = aslib.ascii(line).replace('\r\n', '')311 # grab the stamp and sysinfo312 if re.match(tp.stampfmt, line):313 tp.stamp = line314 continue315 elif re.match(tp.sysinfofmt, line):316 tp.sysinfo = line317 continue318 elif re.match(tp.cmdlinefmt, line):319 tp.cmdline = line320 continue321 elif re.match(tp.kparamsfmt, line):322 tp.kparams = line323 continue324 idx = line.find('[')325 if idx > 1:326 line = line[idx:]327 m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)328 if(not m):329 continue330 ktime = float(m.group('ktime'))331 if(ktime > 120):332 break333 msg = m.group('msg')334 data.dmesgtext.append(line)335 if(ktime == 0.0 and re.match(r'^Linux version .*', msg)):336 if(not sysvals.stamp['kernel']):337 sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)338 continue339 m = re.match(r'.* 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 continue346 m = re.match(r'^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 continue352 m = re.match(r'^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)353 if(m):354 data.valid = True355 data.end = ktime356 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 continue362 if(re.match(r'^Freeing unused kernel .*', msg)):363 data.tUserMode = ktime364 data.dmesg['kernel']['end'] = ktime365 data.dmesg['user']['start'] = ktime366 phase = 'user'367 368 if tp.stamp:369 sysvals.stamp = 0370 tp.parseStamp(data, sysvals)371 data.dmesg['user']['end'] = data.end372 lf.close()373 return data374 375# Function: parseTraceLog376# Description:377# Check if trace is available and copy to a temp file378def parseTraceLog(data):379 sysvals.vprint('Analyzing the ftrace data (%s)...' % \380 os.path.basename(sysvals.ftracefile))381 # if available, calculate cgfilter allowable ranges382 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 log391 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 continue398 m = re.match(tp.ftrace_line_fmt, line.strip())399 if(not m):400 continue401 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 = False406 for r in cgfilter:407 if t >= r[0] and t < r[1]:408 allow = True409 break410 if not allow:411 continue412 if t > data.end:413 break414 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 continue419 if t.fevent or t.fkprobe:420 continue421 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 hierarchy435 for key in ftemp:436 proc, pid = key437 for cg in ftemp[key]:438 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):439 continue440 if(not cg.postProcess()):441 pprint('Sanity check failed for %s-%d' % (proc, pid))442 continue443 # match cg data to devices444 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: retrieveLogs456# Description:457# Create copies of dmesg and/or ftrace for later processing458def retrieveLogs():459 # check ftrace is configured first460 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 dmesg465 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 return471 # get ftrace472 sysvals.writeDatafileHeader(sysvals.ftracefile)473 call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)474 475# Function: colorForName476# Description:477# Generate a repeatable color from a list for a given name478def 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 = 0492 total = 0493 count = len(list)494 while i < len(name):495 total += ord(name[i])496 i += 1497 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] += 1510 return (large, stats)511 512# Function: createBootGraph513# Description:514# Create the output html file from the resident test data515# Arguments:516# testruns: array of Data objects from parseKernelLog or parseTraceLog517# Output:518# True if the html file was created, false if it failed519def createBootGraph(data):520 # html function templates521 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 timeline528 devtl = aslib.Timeline(100, 20)529 530 # write the test title and general info header531 devtl.createHeader(sysvals, sysvals.stamp)532 533 # Generate the header for this timeline534 t0 = data.start535 tMax = data.end536 tTotal = tMax - t0537 if(tTotal == 0):538 pprint('ERROR: No timeline data')539 return False540 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 draw545 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 background555 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 timeline567 num = 0568 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'] = color578 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 continue592 cg = dev['ftrace']593 large, stats = cgOverview(cg, 0.001)594 devstats[dev['id']]['fstat'] = stats595 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 += 1602 continue603 if('ftraces' not in dev):604 continue605 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.0609 title = '%s (%0.3fms)' % (cg.name, cglen)610 cg.id = 'x%d' % num611 devtl.html += html_srccall.format(cg.name, left,612 top, height, width, title, dev['id']+cg.id)613 num += 1614 615 # draw the time scale, try to make the number of labels readable616 devtl.createTimeScale(t0, tMax, tTotal, 'boot')617 devtl.html += '</div>\n'618 619 # timeline is finished620 devtl.html += '</div>\n</div>\n'621 622 # draw a legend which describes the phases by color623 devtl.html += '<div class="legend">\n'624 pdelta = 20.0625 pmargin = 36.0626 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 css635 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 timeline655 hf.write(devtl.html)656 657 # add boot specific html658 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 break666 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 html682 if(sysvals.usecallgraph):683 aslib.addCallgraphs(sysvals, hf, data)684 685 # add the test log as a hidden div686 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 div689 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 close697 aslib.addScriptCode(hf, [data])698 hf.write('</body>\n</html>\n')699 hf.close()700 return True701 702# Function: updateCron703# Description:704# (restore=False) Set the tool to run automatically on reboot705# (restore=True) Restore the original crontab706def 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 place720 if restore:721 if os.path.exists(backfile):722 shutil.move(backfile, cronfile)723 call([cmd, cronfile])724 return725 # backup current cron and install new one with reboot726 if os.path.exists(cronfile):727 shutil.move(cronfile, backfile)728 else:729 fp = open(backfile, 'w')730 fp.close()731 res = -1732 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 continue739 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 = -1747 if res != 0:748 doError('crontab failed')749 750# Function: updateGrub751# Description:752# update grub.cfg for all kernels with our parameters753def updateGrub(restore=False):754 # call update-grub on restore755 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 return762 # extract the option and create a grub config without it763 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 = -1770 try:771 fp = open(tempfile, 'r')772 op = open(grubfile, 'w')773 cont = False774 for line in fp:775 line = line.strip()776 if len(line) == 0 or line[0] == '#':777 continue778 opt = line.split('=')[0].strip()779 if opt == tgtopt:780 cmdline = line.split('=', 1)[1].strip('\\')781 if line[-1] == '\\':782 cont = True783 elif cont:784 cmdline += line.strip('\\')785 if line[-1] != '\\':786 cont = False787 else:788 op.write('%s\n' % line)789 fp.close()790 # if the target option value is in quotes, strip them791 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 = val797 # append our cmd line options798 if len(cmdline) > 0:799 cmdline += ' '800 cmdline += sysvals.kernelParams()801 # write out the updated target option802 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 = -1809 # cleanup810 shutil.move(tempfile, grubfile)811 if res != 0:812 doError('update grub failed')813 814# Function: updateKernelParams815# Description:816# update boot conf for all kernels with our parameters817def updateKernelParams(restore=False):818 # find the boot loader819 sysvals.getBootLoader()820 if sysvals.bootloader == 'grub':821 updateGrub(restore)822 823# Function: doError Description:824# generic error function for catastrphic failures825# Arguments:826# msg: the error message to print827# help: True if printHelp should be called after, False otherwise828def 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: printHelp836# Description:837# print out the help text838def 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 True886 887# ----------------- MAIN --------------------888# exec start (skipped if script is loaded as library)889if __name__ == '__main__':890 # loop through the command line arguments891 cmd = ''892 testrun = True893 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 = False900 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 = True909 elif(arg in simplecmds):910 cmd = arg[1:]911 elif(arg == '-fstat'):912 sysvals.useftrace = True913 elif(arg == '-callgraph' or arg == '-f'):914 sysvals.useftrace = True915 sysvals.usecallgraph = True916 elif(arg == '-cgdump'):917 sysvals.cgdump = True918 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 = True949 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 = True956 sysvals.usecallgraph = True957 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 = False967 sysvals.ftracefile = val968 elif(arg == '-addlogs'):969 sysvals.dmesglog = True970 elif(arg == '-expandcg'):971 sysvals.cgexp = True972 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 = False980 sysvals.dmesgfile = val981 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 = val993 elif(arg == '-reboot'):994 sysvals.reboot = True995 elif(arg == '-manual'):996 sysvals.reboot = True997 sysvals.manual = True998 # remaining options are only for cron job use999 elif(arg == '-cronjob'):1000 sysvals.iscronjob = True1001 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 checks1016 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 commands1028 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 reboot1043 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 ftrace1060 if sysvals.iscronjob:1061 updateCron(True)1062 updateKernelParams(True)1063 try:1064 sysvals.fsetVal('0', 'tracing_on')1065 except:1066 pass1067 1068 # testrun: generate copies of the logs1069 if testrun:1070 retrieveLogs()1071 else:1072 sysvals.setOutputFile()1073 1074 # process the log data1075 if sysvals.dmesgfile:1076 if not mdset:1077 sysvals.max_graph_depth = 01078 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_user1096 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) * 10001102 sysvals.stamp['lastinit'] = data.end * 10001103 sysvals.outputResult(sysvals.stamp)1104