tools/power/pm-graph/bootgraph.py

   1 #!/usr/bin/python
   2 # SPDX-License-Identifier: GPL-2.0-only
   3 #
   4 # Tool for analyzing boot timing
   5 # Copyright (c) 2013, Intel Corporation.
   6 #
   7 # This program is free software; you can redistribute it and/or modify it
   8 # under the terms and conditions of the GNU General Public License,
   9 # version 2, as published by the Free Software Foundation.
  10 #
  11 # This program is distributed in the hope it will be useful, but WITHOUT
  12 # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  13 # FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
  14 # more details.
  15 #
  16 # Authors:
  17 #        Todd Brandt <todd.e.brandt@linux.intel.com>
  18 #
  19 # Description:
  20 #        This tool is designed to assist kernel and OS developers in optimizing
  21 #        their linux stack's boot time. It creates an html representation of
  22 #        the kernel boot timeline up to the start of the init process.
  23 #
  24
  25 # ----------------- LIBRARIES --------------------
  26
  27 import sys
  28 import time
  29 import os
  30 import string
  31 import re
  32 import platform
  33 import shutil
  34 from datetime import datetime, timedelta
  35 from subprocess import call, Popen, PIPE
  36 import sleepgraph as aslib
  37
  38 def pprint(msg):
  39         print(msg)
  40         sys.stdout.flush()
  41
  42 # ----------------- CLASSES --------------------
  43
  44 # Class: SystemValues
  45 # Description:
  46 #        A global, single-instance container used to
  47 #        store system values and test parameters
  48 class SystemValues(aslib.SystemValues):
  49         title = 'BootGraph'
  50         version = '2.2'
  51         hostname = 'localhost'
  52         testtime = ''
  53         kernel = ''
  54         dmesgfile = ''
  55         ftracefile = ''
  56         htmlfile = 'bootgraph.html'
  57         testdir = ''
  58         kparams = ''
  59         result = ''
  60         useftrace = False
  61         usecallgraph = False
  62         suspendmode = 'boot'
  63         max_graph_depth = 2
  64         graph_filter = 'do_one_initcall'
  65         reboot = False
  66         manual = False
  67         iscronjob = False
  68         timeformat = '%.6f'
  69         bootloader = 'grub'
  70         blexec = []
  71         def __init__(self):
  72                 self.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()
  77                         fp.close()
  78                         self.kernel = self.kernelVersion(val)
  79                 else:
  80                         self.kernel = 'unknown'
  81                 self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')
  82         def kernelVersion(self, msg):
  83                 return msg.split()[2]
  84         def checkFtraceKernelVersion(self):
  85                 val = tuple(map(int, self.kernel.split('-')[0].split('.')))
  86                 if val >= (4, 10, 0):
  87                         return True
  88                 return False
  89         def kernelParams(self):
  90                 cmdline = 'initcall_debug log_buf_len=32M'
  91                 if self.useftrace:
  92                         if self.cpucount > 0:
  93                                 bs = min(self.memtotal // 2, 2*1024*1024) // self.cpucount
  94                         else:
  95                                 bs = 131072
  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)
 104                 return cmdline
 105         def setGraphFilter(self, val):
 106                 master = self.getBootFtraceFilterFunctions()
 107                 fs = ''
 108                 for i in val.split(','):
 109                         func = i.strip()
 110                         if func == '':
 111                                 doError('badly formatted filter function string')
 112                         if '[' in func or ']' in func:
 113                                 doError('loadable module functions not allowed - "%s"' % func)
 114                         if ' ' in 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)
 118                         if not fs:
 119                                 fs = func
 120                         else:
 121                                 fs += ','+func
 122                 if not fs:
 123                         doError('badly formatted filter function string')
 124                 self.graph_filter = fs
 125         def getBootFtraceFilterFunctions(self):
 126                 self.rootCheck(True)
 127                 fp = open(self.tpath+'available_filter_functions')
 128                 fulllist = fp.read().split('\n')
 129                 fp.close()
 130                 list = []
 131                 for i in fulllist:
 132                         if not i or ' ' in i or '[' in i or ']' in i:
 133                                 continue
 134                         list.append(i)
 135                 return list
 136         def myCronJob(self, line):
 137                 if '@reboot' not in line:
 138                         return False
 139                 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:
 140                         return True
 141                 return False
 142         def cronjobCmdString(self):
 143                 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
 144                 args = iter(sys.argv[1:])
 145                 for arg in args:
 146                         if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
 147                                 continue
 148                         elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
 149                                 next(args)
 150                                 continue
 151                         elif arg == '-result':
 152                                 cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args)))
 153                                 continue
 154                         elif arg == '-cgskip':
 155                                 file = self.configFile(next(args))
 156                                 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
 157                                 continue
 158                         cmdline += ' '+arg
 159                 if self.graph_filter != 'do_one_initcall':
 160                         cmdline += ' -func "%s"' % self.graph_filter
 161                 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)
 162                 return cmdline
 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)
 170                 sys.exit()
 171         def blGrub(self):
 172                 blcmd = ''
 173                 for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
 174                         if blcmd:
 175                                 break
 176                         blcmd = self.getExec(cmd)
 177                 if not blcmd:
 178                         doError('[GRUB] missing update command')
 179                 if not os.path.exists('/etc/default/grub'):
 180                         doError('[GRUB] missing /etc/default/grub')
 181                 if 'grub2' in blcmd:
 182                         cfg = '/boot/grub2/grub.cfg'
 183                 else:
 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]
 189                 else:
 190                         self.blexec = [blcmd, '-o', cfg]
 191         def getBootLoader(self):
 192                 if self.bootloader == 'grub':
 193                         self.blGrub()
 194                 else:
 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)
 203                 fp.close()
 204
 205 sysvals = SystemValues()
 206
 207 # Class: Data
 208 # Description:
 209 #        The primary container for test data.
 210 class Data(aslib.Data):
 211         dmesg = {}  # root data structure
 212         start = 0.0 # test start
 213         end = 0.0   # test end
 214         dmesgtext = []   # dmesg text file in memory
 215         testnumber = 0
 216         idstr = ''
 217         html_device_id = 0
 218         valid = False
 219         tUserMode = 0.0
 220         boottime = ''
 221         phases = ['kernel', 'user']
 222         do_one_initcall = False
 223         def __init__(self, num):
 224                 self.testnumber = num
 225                 self.idstr = 'a'
 226                 self.dmesgtext = []
 227                 self.dmesg = {
 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'}
 232                 }
 233         def deviceTopology(self):
 234                 return ''
 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']
 240                 length = -1.0
 241                 if(start >= 0 and end >= 0):
 242                         length = end - start
 243                 i = 2
 244                 origname = name
 245                 while(name in list):
 246                         name = '%s[%d]' % (origname, i)
 247                         i += 1
 248                 list[name] = {'name': name, 'start': start, 'end': end,
 249                         'pid': pid, 'length': length, 'row': 0, 'id': devid,
 250                         'ret': ret, 'ulen': ulen }
 251                 return name
 252         def deviceMatch(self, pid, cg):
 253                 if cg.end - cg.start == 0:
 254                         return ''
 255                 for p in data.phases:
 256                         list = self.dmesg[p]['list']
 257                         for devname in list:
 258                                 dev = list[devname]
 259                                 if pid != dev['pid']:
 260                                         continue
 261                                 if cg.name == 'do_one_initcall':
 262                                         if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
 263                                                 dev['ftrace'] = cg
 264                                                 self.do_one_initcall = True
 265                                                 return devname
 266                                 else:
 267                                         if(cg.start > dev['start'] and cg.end < dev['end']):
 268                                                 if 'ftraces' not in dev:
 269                                                         dev['ftraces'] = []
 270                                                 dev['ftraces'].append(cg)
 271                                                 return devname
 272                 return ''
 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))
 284
 285 # ----------------- FUNCTIONS --------------------
 286
 287 # Function: parseKernelLog
 288 # Description:
 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))
 293         phase = 'kernel'
 294         data = Data(0)
 295         data.dmesg['kernel']['start'] = data.start = ktime = 0.0
 296         sysvals.stamp = {
 297                 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
 298                 'host': sysvals.hostname,
 299                 'mode': 'boot', 'kernel': ''}
 300
 301         tp = aslib.TestProps()
 302         devtemp = dict()
 303         if(sysvals.dmesgfile):
 304                 lf = open(sysvals.dmesgfile, 'rb')
 305         else:
 306                 lf = Popen('dmesg', stdout=PIPE).stdout
 307         for line in lf:
 308                 line = aslib.ascii(line).replace('\r\n', '')
 309                 # grab the stamp and sysinfo
 310                 if re.match(tp.stampfmt, line):
 311                         tp.stamp = line
 312                         continue
 313                 elif re.match(tp.sysinfofmt, line):
 314                         tp.sysinfo = line
 315                         continue
 316                 elif re.match(tp.cmdlinefmt, line):
 317                         tp.cmdline = line
 318                         continue
 319                 elif re.match(tp.kparamsfmt, line):
 320                         tp.kparams = line
 321                         continue
 322                 idx = line.find('[')
 323                 if idx > 1:
 324                         line = line[idx:]
 325                 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
 326                 if(not m):
 327                         continue
 328                 ktime = float(m.group('ktime'))
 329                 if(ktime > 120):
 330                         break
 331                 msg = m.group('msg')
 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)
 336                         continue
 337                 m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg)
 338                 if(m):
 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')
 343                         continue
 344                 m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
 345                 if(m):
 346                         func = m.group('f')
 347                         pid = int(m.group('p'))
 348                         devtemp[func] = (ktime, pid)
 349                         continue
 350                 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
 351                 if(m):
 352                         data.valid = True
 353                         data.end = ktime
 354                         f, r, t = m.group('f', 'r', 't')
 355                         if(f in devtemp):
 356                                 start, pid = devtemp[f]
 357                                 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
 358                                 del devtemp[f]
 359                         continue
 360                 if(re.match('^Freeing unused kernel .*', msg)):
 361                         data.tUserMode = ktime
 362                         data.dmesg['kernel']['end'] = ktime
 363                         data.dmesg['user']['start'] = ktime
 364                         phase = 'user'
 365
 366         if tp.stamp:
 367                 sysvals.stamp = 0
 368                 tp.parseStamp(data, sysvals)
 369         data.dmesg['user']['end'] = data.end
 370         lf.close()
 371         return data
 372
 373 # Function: parseTraceLog
 374 # Description:
 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
 380         cgfilter = []
 381         if len(sysvals.cgfilter) > 0:
 382                 for p in data.phases:
 383                         list = data.dmesg[p]['list']
 384                         for i in sysvals.cgfilter:
 385                                 if i in list:
 386                                         cgfilter.append([list[i]['start']-0.0001,
 387                                                 list[i]['end']+0.0001])
 388         # parse the trace log
 389         ftemp = dict()
 390         tp = aslib.TestProps()
 391         tp.setTracerType('function_graph')
 392         tf = open(sysvals.ftracefile, 'r')
 393         for line in tf:
 394                 if line[0] == '#':
 395                         continue
 396                 m = re.match(tp.ftrace_line_fmt, line.strip())
 397                 if(not m):
 398                         continue
 399                 m_time, m_proc, m_pid, m_msg, m_dur = \
 400                         m.group('time', 'proc', 'pid', 'msg', 'dur')
 401                 t = float(m_time)
 402                 if len(cgfilter) > 0:
 403                         allow = False
 404                         for r in cgfilter:
 405                                 if t >= r[0] and t < r[1]:
 406                                         allow = True
 407                                         break
 408                         if not allow:
 409                                 continue
 410                 if t > data.end:
 411                         break
 412                 if(m_time and m_pid and m_msg):
 413                         t = aslib.FTraceLine(m_time, m_msg, m_dur)
 414                         pid = int(m_pid)
 415                 else:
 416                         continue
 417                 if t.fevent or t.fkprobe:
 418                         continue
 419                 key = (m_proc, pid)
 420                 if(key not in ftemp):
 421                         ftemp[key] = []
 422                         ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
 423                 cg = ftemp[key][-1]
 424                 res = cg.addLine(t)
 425                 if(res != 0):
 426                         ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
 427                 if(res == -1):
 428                         ftemp[key][-1].addLine(t)
 429
 430         tf.close()
 431
 432         # add the callgraph data to the device hierarchy
 433         for key in ftemp:
 434                 proc, pid = key
 435                 for cg in ftemp[key]:
 436                         if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
 437                                 continue
 438                         if(not cg.postProcess()):
 439                                 pprint('Sanity check failed for %s-%d' % (proc, pid))
 440                                 continue
 441                         # match cg data to devices
 442                         devname = data.deviceMatch(pid, cg)
 443                         if not devname:
 444                                 kind = 'Orphan'
 445                                 if cg.partial:
 446                                         kind = 'Partial'
 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)))
 452
 453 # Function: retrieveLogs
 454 # Description:
 455 #        Create copies of dmesg and/or ftrace for later processing
 456 def retrieveLogs():
 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:
 468                 return
 469         # get ftrace
 470         sysvals.writeDatafileHeader(sysvals.ftracefile)
 471         call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)
 472
 473 # Function: colorForName
 474 # Description:
 475 #        Generate a repeatable color from a list for a given name
 476 def colorForName(name):
 477         list = [
 478                 ('c1', '#ec9999'),
 479                 ('c2', '#ffc1a6'),
 480                 ('c3', '#fff0a6'),
 481                 ('c4', '#adf199'),
 482                 ('c5', '#9fadea'),
 483                 ('c6', '#a699c1'),
 484                 ('c7', '#ad99b4'),
 485                 ('c8', '#eaffea'),
 486                 ('c9', '#dcecfb'),
 487                 ('c10', '#ffffea')
 488         ]
 489         i = 0
 490         total = 0
 491         count = len(list)
 492         while i < len(name):
 493                 total += ord(name[i])
 494                 i += 1
 495         return list[total % count]
 496
 497 def cgOverview(cg, minlen):
 498         stats = dict()
 499         large = []
 500         for l in cg.list:
 501                 if l.fcall and l.depth == 1:
 502                         if l.length >= minlen:
 503                                 large.append(l)
 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)
 509
 510 # Function: createBootGraph
 511 # Description:
 512 #        Create the output html file from the resident test data
 513 # Arguments:
 514 #        testruns: array of Data objects from parseKernelLog or parseTraceLog
 515 # Output:
 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>'\
 523                 '</tr>\n</table>\n'
 524
 525         # device timeline
 526         devtl = aslib.Timeline(100, 20)
 527
 528         # write the test title and general info header
 529         devtl.createHeader(sysvals, sysvals.stamp)
 530
 531         # Generate the header for this timeline
 532         t0 = data.start
 533         tMax = data.end
 534         tTotal = tMax - t0
 535         if(tTotal == 0):
 536                 pprint('ERROR: No timeline data')
 537                 return False
 538         user_mode = '%.0f'%(data.tUserMode*1000)
 539         last_init = '%.0f'%(tTotal*1000)
 540         devtl.html += html_timetotal.format(user_mode, last_init)
 541
 542         # determine the maximum number of rows we need to draw
 543         devlist = []
 544         for p in data.phases:
 545                 list = data.dmesg[p]['list']
 546                 for devname in list:
 547                         d = aslib.DevItem(0, p, list[devname])
 548                         devlist.append(d)
 549                 devtl.getPhaseRows(devlist, 0, 'start')
 550         devtl.calcTotalRows()
 551
 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, \
 562                         phase['color'], '')
 563
 564         # draw the device timeline
 565         num = 0
 566         devstats = dict()
 567         for phase in data.phases:
 568                 list = data.dmesg[phase]['list']
 569                 for devname in sorted(list):
 570                         cls, color = colorForName(devname)
 571                         dev = list[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}
 575                         dev['color'] = color
 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):
 589                                         continue
 590                                 cg = dev['ftrace']
 591                                 large, stats = cgOverview(cg, 0.001)
 592                                 devstats[dev['id']]['fstat'] = stats
 593                                 for l in large:
 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)
 599                                         num += 1
 600                                 continue
 601                         if('ftraces' not in dev):
 602                                 continue
 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)
 608                                 cg.id = 'x%d' % num
 609                                 devtl.html += html_srccall.format(cg.name, left,
 610                                         top, height, width, title, dev['id']+cg.id)
 611                                 num += 1
 612
 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'
 616
 617         # timeline is finished
 618         devtl.html += '</div>\n</div>\n'
 619
 620         # draw a legend which describes the phases by color
 621         devtl.html += '<div class="legend">\n'
 622         pdelta = 20.0
 623         pmargin = 36.0
 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'
 629
 630         hf = open(sysvals.htmlfile, 'w')
 631
 632         # add the css
 633         extra = '\
 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)
 651
 652         # write the device timeline
 653         hf.write(devtl.html)
 654
 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:
 663                                         break
 664                                 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
 665                 statinfo += '\t],\n'
 666         statinfo += '};\n'
 667         html = \
 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+\
 676                 '</script>\n'
 677         hf.write(html)
 678
 679         # add the callgraph html
 680         if(sysvals.usecallgraph):
 681                 aslib.addCallgraphs(sysvals, hf, data)
 682
 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
 687         if sysvals.dmesglog:
 688                 hf.write('<div id="dmesglog" style="display:none;">\n')
 689                 for line in data.dmesgtext:
 690                         line = line.replace('<', '&lt').replace('>', '&gt')
 691                         hf.write(line)
 692                 hf.write('</div>\n')
 693
 694         # write the footer and close
 695         aslib.addScriptCode(hf, [data])
 696         hf.write('</body>\n</html>\n')
 697         hf.close()
 698         return True
 699
 700 # Function: updateCron
 701 # Description:
 702 #    (restore=False) Set the tool to run automatically on reboot
 703 #    (restore=True) Restore the original crontab
 704 def updateCron(restore=False):
 705         if not restore:
 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')
 715         if not cmd:
 716                 doError('crontab not found')
 717         # on restore: move the backup cron back into place
 718         if restore:
 719                 if os.path.exists(backfile):
 720                         shutil.move(backfile, cronfile)
 721                         call([cmd, cronfile])
 722                 return
 723         # backup current cron and install new one with reboot
 724         if os.path.exists(cronfile):
 725                 shutil.move(cronfile, backfile)
 726         else:
 727                 fp = open(backfile, 'w')
 728                 fp.close()
 729         res = -1
 730         try:
 731                 fp = open(backfile, 'r')
 732                 op = open(cronfile, 'w')
 733                 for line in fp:
 734                         if not sysvals.myCronJob(line):
 735                                 op.write(line)
 736                                 continue
 737                 fp.close()
 738                 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
 739                 op.close()
 740                 res = call([cmd, cronfile])
 741         except Exception as e:
 742                 pprint('Exception: %s' % str(e))
 743                 shutil.move(backfile, cronfile)
 744                 res = -1
 745         if res != 0:
 746                 doError('crontab failed')
 747
 748 # Function: updateGrub
 749 # Description:
 750 #        update grub.cfg for all kernels with our parameters
 751 def updateGrub(restore=False):
 752         # call update-grub on restore
 753         if restore:
 754                 try:
 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))
 759                 return
 760         # extract the option and create a grub config without it
 761         sysvals.rootUser(True)
 762         tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
 763         cmdline = ''
 764         grubfile = '/etc/default/grub'
 765         tempfile = '/etc/default/grub.analyze_boot'
 766         shutil.move(grubfile, tempfile)
 767         res = -1
 768         try:
 769                 fp = open(tempfile, 'r')
 770                 op = open(grubfile, 'w')
 771                 cont = False
 772                 for line in fp:
 773                         line = line.strip()
 774                         if len(line) == 0 or line[0] == '#':
 775                                 continue
 776                         opt = line.split('=')[0].strip()
 777                         if opt == tgtopt:
 778                                 cmdline = line.split('=', 1)[1].strip('\\')
 779                                 if line[-1] == '\\':
 780                                         cont = True
 781                         elif cont:
 782                                 cmdline += line.strip('\\')
 783                                 if line[-1] != '\\':
 784                                         cont = False
 785                         else:
 786                                 op.write('%s\n' % line)
 787                 fp.close()
 788                 # if the target option value is in quotes, strip them
 789                 sp = '"'
 790                 val = cmdline.strip()
 791                 if val and (val[0] == '\'' or val[0] == '"'):
 792                         sp = val[0]
 793                         val = val.strip(sp)
 794                 cmdline = val
 795                 # append our cmd line options
 796                 if len(cmdline) > 0:
 797                         cmdline += ' '
 798                 cmdline += sysvals.kernelParams()
 799                 # write out the updated target option
 800                 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
 801                 op.close()
 802                 res = call(sysvals.blexec)
 803                 os.remove(grubfile)
 804         except Exception as e:
 805                 pprint('Exception: %s' % str(e))
 806                 res = -1
 807         # cleanup
 808         shutil.move(tempfile, grubfile)
 809         if res != 0:
 810                 doError('update grub failed')
 811
 812 # Function: updateKernelParams
 813 # Description:
 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':
 819                 updateGrub(restore)
 820
 821 # Function: doError Description:
 822 #        generic error function for catastrphic failures
 823 # Arguments:
 824 #        msg: the error message to print
 825 #        help: True if printHelp should be called after, False otherwise
 826 def doError(msg, help=False):
 827         if help == True:
 828                 printHelp()
 829         pprint('ERROR: %s\n' % msg)
 830         sysvals.outputResult({'error':msg})
 831         sys.exit()
 832
 833 # Function: printHelp
 834 # Description:
 835 #        print out the help text
 836 def printHelp():
 837         pprint('\n%s v%s\n'\
 838         'Usage: bootgraph <options> <command>\n'\
 839         '\n'\
 840         'Description:\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'\
 844         '\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'\
 847         '\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'\
 852         '\n'\
 853         'Options:\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'\
 861         ' [advanced]\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'\
 874         '\n'\
 875         'Other commands:\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'\
 879         ' [redo]\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))
 883         return True
 884
 885 # ----------------- MAIN --------------------
 886 # exec start (skipped if script is loaded as library)
 887 if __name__ == '__main__':
 888         # loop through the command line arguments
 889         cmd = ''
 890         testrun = True
 891         switchoff = ['disable', 'off', 'false', '0']
 892         simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
 893         cgskip = ''
 894         if '-f' in sys.argv:
 895                 cgskip = sysvals.configFile('cgskip.txt')
 896         args = iter(sys.argv[1:])
 897         mdset = False
 898         for arg in args:
 899                 if(arg == '-h'):
 900                         printHelp()
 901                         sys.exit()
 902                 elif(arg == '-v'):
 903                         pprint("Version %s" % sysvals.version)
 904                         sys.exit()
 905                 elif(arg == '-verbose'):
 906                         sysvals.verbose = True
 907                 elif(arg in simplecmds):
 908                         cmd = arg[1:]
 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'):
 919                         try:
 920                                 val = next(args)
 921                         except:
 922                                 doError('No callgraph functions supplied', True)
 923                         sysvals.setCallgraphFilter(val)
 924                 elif(arg == '-cgskip'):
 925                         try:
 926                                 val = next(args)
 927                         except:
 928                                 doError('No file supplied', True)
 929                         if val.lower() in switchoff:
 930                                 cgskip = ''
 931                         else:
 932                                 cgskip = sysvals.configFile(val)
 933                                 if(not cgskip):
 934                                         doError('%s does not exist' % cgskip)
 935                 elif(arg == '-bl'):
 936                         try:
 937                                 val = next(args)
 938                         except:
 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'):
 946                         mdset = True
 947                         sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
 948                 elif(arg == '-func'):
 949                         try:
 950                                 val = next(args)
 951                         except:
 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'):
 958                         try:
 959                                 val = next(args)
 960                         except:
 961                                 doError('No ftrace file supplied', True)
 962                         if(os.path.exists(val) == False):
 963                                 doError('%s does not exist' % val)
 964                         testrun = False
 965                         sysvals.ftracefile = val
 966                 elif(arg == '-addlogs'):
 967                         sysvals.dmesglog = True
 968                 elif(arg == '-expandcg'):
 969                         sysvals.cgexp = True
 970                 elif(arg == '-dmesg'):
 971                         try:
 972                                 val = next(args)
 973                         except:
 974                                 doError('No dmesg file supplied', True)
 975                         if(os.path.exists(val) == False):
 976                                 doError('%s does not exist' % val)
 977                         testrun = False
 978                         sysvals.dmesgfile = val
 979                 elif(arg == '-o'):
 980                         try:
 981                                 val = next(args)
 982                         except:
 983                                 doError('No subdirectory name supplied', True)
 984                         sysvals.testdir = sysvals.setOutputFolder(val)
 985                 elif(arg == '-result'):
 986                         try:
 987                                 val = next(args)
 988                         except:
 989                                 doError('No result file supplied', True)
 990                         sysvals.result = val
 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'):
1000                         try:
1001                                 val = next(args)
1002                         except:
1003                                 doError('No executable supplied', True)
1004                         out = sysvals.getExec(val)
1005                         if not out:
1006                                 print('%s not found' % val)
1007                                 sys.exit(1)
1008                         print(out)
1009                         sys.exit(0)
1010                 else:
1011                         doError('Invalid argument: '+arg, True)
1012
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')
1024
1025         # run utility commands
1026         sysvals.cpuInfo()
1027         if cmd != '':
1028                 if cmd == 'kpupdate':
1029                         updateKernelParams()
1030                 elif cmd == 'flistall':
1031                         for f in sysvals.getBootFtraceFilterFunctions():
1032                                 print(f)
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)
1038                 sys.exit()
1039
1040         # reboot: update grub, setup a cronjob, and reboot
1041         if sysvals.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()
1047                         updateCron()
1048                         call('reboot')
1049                 else:
1050                         sysvals.manualRebootRequired()
1051                 sys.exit()
1052
1053         if sysvals.usecallgraph and cgskip:
1054                 sysvals.vprint('Using cgskip file: %s' % cgskip)
1055                 sysvals.setCallgraphBlacklist(cgskip)
1056
1057         # cronjob: remove the cronjob, grub changes, and disable ftrace
1058         if sysvals.iscronjob:
1059                 updateCron(True)
1060                 updateKernelParams(True)
1061                 try:
1062                         sysvals.fsetVal('0', 'tracing_on')
1063                 except:
1064                         pass
1065
1066         # testrun: generate copies of the logs
1067         if testrun:
1068                 retrieveLogs()
1069         else:
1070                 sysvals.setOutputFile()
1071
1072         # process the log data
1073         if sysvals.dmesgfile:
1074                 if not mdset:
1075                         sysvals.max_graph_depth = 0
1076                 data = parseKernelLog()
1077                 if(not data.valid):
1078                         doError('No initcall data found in %s' % sysvals.dmesgfile)
1079                 if sysvals.useftrace and sysvals.ftracefile:
1080                         parseTraceLog(data)
1081                 if sysvals.cgdump:
1082                         data.debugPrint()
1083                         sys.exit()
1084         else:
1085                 doError('dmesg file required')
1086
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)
1090         data.printDetails()
1091         createBootGraph(data)
1092
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)
1098
1099         sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
1100         sysvals.stamp['lastinit'] = data.end * 1000
1101         sysvals.outputResult(sysvals.stamp)