tools/power/pm-graph/analyze_boot.py

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