tools/power/pm-graph/bootgraph.py

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