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