tools/power/pm-graph/bootgraph.py

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