tools/power/pm-graph/bootgraph.py

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