| #!/usr/bin/env python3 | |
| # SPDX-License-Identifier: GPL-2.0-only | |
| # | |
| # Tool for analyzing boot timing | |
| # Copyright (c) 2013, Intel Corporation. | |
| # | |
| # This program is free software; you can redistribute it and/or modify it | |
| # under the terms and conditions of the GNU General Public License, | |
| # version 2, as published by the Free Software Foundation. | |
| # | |
| # This program is distributed in the hope it will be useful, but WITHOUT | |
| # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or | |
| # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for | |
| # more details. | |
| # | |
| # Authors: | |
| # Todd Brandt <todd.e.brandt@linux.intel.com> | |
| # | |
| # Description: | |
| # This tool is designed to assist kernel and OS developers in optimizing | |
| # their linux stack's boot time. It creates an html representation of | |
| # the kernel boot timeline up to the start of the init process. | |
| # | |
| # ----------------- LIBRARIES -------------------- | |
| import sys | |
| import time | |
| import os | |
| import string | |
| import re | |
| import platform | |
| import shutil | |
| from datetime import datetime, timedelta | |
| from subprocess import call, Popen, PIPE | |
| import sleepgraph as aslib | |
| def pprint(msg): | |
| print(msg) | |
| sys.stdout.flush() | |
| # ----------------- CLASSES -------------------- | |
| # Class: SystemValues | |
| # Description: | |
| # A global, single-instance container used to | |
| # store system values and test parameters | |
| class SystemValues(aslib.SystemValues): | |
| title = 'BootGraph' | |
| version = '2.2' | |
| hostname = 'localhost' | |
| testtime = '' | |
| kernel = '' | |
| dmesgfile = '' | |
| ftracefile = '' | |
| htmlfile = 'bootgraph.html' | |
| testdir = '' | |
| kparams = '' | |
| result = '' | |
| useftrace = False | |
| usecallgraph = False | |
| suspendmode = 'boot' | |
| max_graph_depth = 2 | |
| graph_filter = 'do_one_initcall' | |
| reboot = False | |
| manual = False | |
| iscronjob = False | |
| timeformat = '%.6f' | |
| bootloader = 'grub' | |
| blexec = [] | |
| def __init__(self): | |
| self.hostname = platform.node() | |
| self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S') | |
| if os.path.exists('/proc/version'): | |
| fp = open('/proc/version', 'r') | |
| val = fp.read().strip() | |
| fp.close() | |
| self.kernel = self.kernelVersion(val) | |
| else: | |
| self.kernel = 'unknown' | |
| self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S') | |
| def kernelVersion(self, msg): | |
| return msg.split()[2] | |
| def checkFtraceKernelVersion(self): | |
| val = tuple(map(int, self.kernel.split('-')[0].split('.'))) | |
| if val >= (4, 10, 0): | |
| return True | |
| return False | |
| def kernelParams(self): | |
| cmdline = 'initcall_debug log_buf_len=32M' | |
| if self.useftrace: | |
| if self.cpucount > 0: | |
| bs = min(self.memtotal // 2, 2*1024*1024) // self.cpucount | |
| else: | |
| bs = 131072 | |
| cmdline += ' trace_buf_size=%dK trace_clock=global '\ | |
| 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\ | |
| 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\ | |
| 'nofuncgraph-overhead,context-info,graph-time '\ | |
| 'ftrace=function_graph '\ | |
| 'ftrace_graph_max_depth=%d '\ | |
| 'ftrace_graph_filter=%s' % \ | |
| (bs, self.max_graph_depth, self.graph_filter) | |
| return cmdline | |
| def setGraphFilter(self, val): | |
| master = self.getBootFtraceFilterFunctions() | |
| fs = '' | |
| for i in val.split(','): | |
| func = i.strip() | |
| if func == '': | |
| doError('badly formatted filter function string') | |
| if '[' in func or ']' in func: | |
| doError('loadable module functions not allowed - "%s"' % func) | |
| if ' ' in func: | |
| doError('spaces found in filter functions - "%s"' % func) | |
| if func not in master: | |
| doError('function "%s" not available for ftrace' % func) | |
| if not fs: | |
| fs = func | |
| else: | |
| fs += ','+func | |
| if not fs: | |
| doError('badly formatted filter function string') | |
| self.graph_filter = fs | |
| def getBootFtraceFilterFunctions(self): | |
| self.rootCheck(True) | |
| fp = open(self.tpath+'available_filter_functions') | |
| fulllist = fp.read().split('\n') | |
| fp.close() | |
| list = [] | |
| for i in fulllist: | |
| if not i or ' ' in i or '[' in i or ']' in i: | |
| continue | |
| list.append(i) | |
| return list | |
| def myCronJob(self, line): | |
| if '@reboot' not in line: | |
| return False | |
| if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line: | |
| return True | |
| return False | |
| def cronjobCmdString(self): | |
| cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0]) | |
| args = iter(sys.argv[1:]) | |
| for arg in args: | |
| if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']: | |
| continue | |
| elif arg in ['-o', '-dmesg', '-ftrace', '-func']: | |
| next(args) | |
| continue | |
| elif arg == '-result': | |
| cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args))) | |
| continue | |
| elif arg == '-cgskip': | |
| file = self.configFile(next(args)) | |
| cmdline += ' %s "%s"' % (arg, os.path.abspath(file)) | |
| continue | |
| cmdline += ' '+arg | |
| if self.graph_filter != 'do_one_initcall': | |
| cmdline += ' -func "%s"' % self.graph_filter | |
| cmdline += ' -o "%s"' % os.path.abspath(self.testdir) | |
| return cmdline | |
| def manualRebootRequired(self): | |
| cmdline = self.kernelParams() | |
| pprint('To generate a new timeline manually, follow these steps:\n\n'\ | |
| '1. Add the CMDLINE string to your kernel command line.\n'\ | |
| '2. Reboot the system.\n'\ | |
| '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\ | |
| 'CMDLINE="%s"' % cmdline) | |
| sys.exit() | |
| def blGrub(self): | |
| blcmd = '' | |
| for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']: | |
| if blcmd: | |
| break | |
| blcmd = self.getExec(cmd) | |
| if not blcmd: | |
| doError('[GRUB] missing update command') | |
| if not os.path.exists('/etc/default/grub'): | |
| doError('[GRUB] missing /etc/default/grub') | |
| if 'grub2' in blcmd: | |
| cfg = '/boot/grub2/grub.cfg' | |
| else: | |
| cfg = '/boot/grub/grub.cfg' | |
| if not os.path.exists(cfg): | |
| doError('[GRUB] missing %s' % cfg) | |
| if 'update-grub' in blcmd: | |
| self.blexec = [blcmd] | |
| else: | |
| self.blexec = [blcmd, '-o', cfg] | |
| def getBootLoader(self): | |
| if self.bootloader == 'grub': | |
| self.blGrub() | |
| else: | |
| doError('unknown boot loader: %s' % self.bootloader) | |
| def writeDatafileHeader(self, filename): | |
| self.kparams = open('/proc/cmdline', 'r').read().strip() | |
| fp = open(filename, 'w') | |
| fp.write(self.teststamp+'\n') | |
| fp.write(self.sysstamp+'\n') | |
| fp.write('# command | %s\n' % self.cmdline) | |
| fp.write('# kparams | %s\n' % self.kparams) | |
| fp.close() | |
| sysvals = SystemValues() | |
| # Class: Data | |
| # Description: | |
| # The primary container for test data. | |
| class Data(aslib.Data): | |
| dmesg = {} # root data structure | |
| start = 0.0 # test start | |
| end = 0.0 # test end | |
| dmesgtext = [] # dmesg text file in memory | |
| testnumber = 0 | |
| idstr = '' | |
| html_device_id = 0 | |
| valid = False | |
| tUserMode = 0.0 | |
| boottime = '' | |
| phases = ['kernel', 'user'] | |
| do_one_initcall = False | |
| def __init__(self, num): | |
| self.testnumber = num | |
| self.idstr = 'a' | |
| self.dmesgtext = [] | |
| self.dmesg = { | |
| 'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0, | |
| 'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'}, | |
| 'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0, | |
| 'order': 1, 'color': '#fff'} | |
| } | |
| def deviceTopology(self): | |
| return '' | |
| def newAction(self, phase, name, pid, start, end, ret, ulen): | |
| # new device callback for a specific phase | |
| self.html_device_id += 1 | |
| devid = '%s%d' % (self.idstr, self.html_device_id) | |
| list = self.dmesg[phase]['list'] | |
| length = -1.0 | |
| if(start >= 0 and end >= 0): | |
| length = end - start | |
| i = 2 | |
| origname = name | |
| while(name in list): | |
| name = '%s[%d]' % (origname, i) | |
| i += 1 | |
| list[name] = {'name': name, 'start': start, 'end': end, | |
| 'pid': pid, 'length': length, 'row': 0, 'id': devid, | |
| 'ret': ret, 'ulen': ulen } | |
| return name | |
| def deviceMatch(self, pid, cg): | |
| if cg.end - cg.start == 0: | |
| return '' | |
| for p in data.phases: | |
| list = self.dmesg[p]['list'] | |
| for devname in list: | |
| dev = list[devname] | |
| if pid != dev['pid']: | |
| continue | |
| if cg.name == 'do_one_initcall': | |
| if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0): | |
| dev['ftrace'] = cg | |
| self.do_one_initcall = True | |
| return devname | |
| else: | |
| if(cg.start > dev['start'] and cg.end < dev['end']): | |
| if 'ftraces' not in dev: | |
| dev['ftraces'] = [] | |
| dev['ftraces'].append(cg) | |
| return devname | |
| return '' | |
| def printDetails(self): | |
| sysvals.vprint('Timeline Details:') | |
| sysvals.vprint(' Host: %s' % sysvals.hostname) | |
| sysvals.vprint(' Kernel: %s' % sysvals.kernel) | |
| sysvals.vprint(' Test time: %s' % sysvals.testtime) | |
| sysvals.vprint(' Boot time: %s' % self.boottime) | |
| for phase in self.phases: | |
| dc = len(self.dmesg[phase]['list']) | |
| sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase, | |
| self.dmesg[phase]['start']*1000, | |
| self.dmesg[phase]['end']*1000, dc)) | |
| # ----------------- FUNCTIONS -------------------- | |
| # Function: parseKernelLog | |
| # Description: | |
| # parse a kernel log for boot data | |
| def parseKernelLog(): | |
| sysvals.vprint('Analyzing the dmesg data (%s)...' % \ | |
| os.path.basename(sysvals.dmesgfile)) | |
| phase = 'kernel' | |
| data = Data(0) | |
| data.dmesg['kernel']['start'] = data.start = ktime = 0.0 | |
| sysvals.stamp = { | |
| 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'), | |
| 'host': sysvals.hostname, | |
| 'mode': 'boot', 'kernel': ''} | |
| tp = aslib.TestProps() | |
| devtemp = dict() | |
| if(sysvals.dmesgfile): | |
| lf = open(sysvals.dmesgfile, 'rb') | |
| else: | |
| lf = Popen('dmesg', stdout=PIPE).stdout | |
| for line in lf: | |
| line = aslib.ascii(line).replace('\r\n', '') | |
| # grab the stamp and sysinfo | |
| if re.match(tp.stampfmt, line): | |
| tp.stamp = line | |
| continue | |
| elif re.match(tp.sysinfofmt, line): | |
| tp.sysinfo = line | |
| continue | |
| elif re.match(tp.cmdlinefmt, line): | |
| tp.cmdline = line | |
| continue | |
| elif re.match(tp.kparamsfmt, line): | |
| tp.kparams = line | |
| continue | |
| idx = line.find('[') | |
| if idx > 1: | |
| line = line[idx:] | |
| m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) | |
| if(not m): | |
| continue | |
| ktime = float(m.group('ktime')) | |
| if(ktime > 120): | |
| break | |
| msg = m.group('msg') | |
| data.dmesgtext.append(line) | |
| if(ktime == 0.0 and re.match('^Linux version .*', msg)): | |
| if(not sysvals.stamp['kernel']): | |
| sysvals.stamp['kernel'] = sysvals.kernelVersion(msg) | |
| continue | |
| m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg) | |
| if(m): | |
| bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S') | |
| bt = bt - timedelta(seconds=int(ktime)) | |
| data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S') | |
| sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p') | |
| continue | |
| m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg) | |
| if(m): | |
| func = m.group('f') | |
| pid = int(m.group('p')) | |
| devtemp[func] = (ktime, pid) | |
| continue | |
| m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg) | |
| if(m): | |
| data.valid = True | |
| data.end = ktime | |
| f, r, t = m.group('f', 'r', 't') | |
| if(f in devtemp): | |
| start, pid = devtemp[f] | |
| data.newAction(phase, f, pid, start, ktime, int(r), int(t)) | |
| del devtemp[f] | |
| continue | |
| if(re.match('^Freeing unused kernel .*', msg)): | |
| data.tUserMode = ktime | |
| data.dmesg['kernel']['end'] = ktime | |
| data.dmesg['user']['start'] = ktime | |
| phase = 'user' | |
| if tp.stamp: | |
| sysvals.stamp = 0 | |
| tp.parseStamp(data, sysvals) | |
| data.dmesg['user']['end'] = data.end | |
| lf.close() | |
| return data | |
| # Function: parseTraceLog | |
| # Description: | |
| # Check if trace is available and copy to a temp file | |
| def parseTraceLog(data): | |
| sysvals.vprint('Analyzing the ftrace data (%s)...' % \ | |
| os.path.basename(sysvals.ftracefile)) | |
| # if available, calculate cgfilter allowable ranges | |
| cgfilter = [] | |
| if len(sysvals.cgfilter) > 0: | |
| for p in data.phases: | |
| list = data.dmesg[p]['list'] | |
| for i in sysvals.cgfilter: | |
| if i in list: | |
| cgfilter.append([list[i]['start']-0.0001, | |
| list[i]['end']+0.0001]) | |
| # parse the trace log | |
| ftemp = dict() | |
| tp = aslib.TestProps() | |
| tp.setTracerType('function_graph') | |
| tf = open(sysvals.ftracefile, 'r') | |
| for line in tf: | |
| if line[0] == '#': | |
| continue | |
| m = re.match(tp.ftrace_line_fmt, line.strip()) | |
| if(not m): | |
| continue | |
| m_time, m_proc, m_pid, m_msg, m_dur = \ | |
| m.group('time', 'proc', 'pid', 'msg', 'dur') | |
| t = float(m_time) | |
| if len(cgfilter) > 0: | |
| allow = False | |
| for r in cgfilter: | |
| if t >= r[0] and t < r[1]: | |
| allow = True | |
| break | |
| if not allow: | |
| continue | |
| if t > data.end: | |
| break | |
| if(m_time and m_pid and m_msg): | |
| t = aslib.FTraceLine(m_time, m_msg, m_dur) | |
| pid = int(m_pid) | |
| else: | |
| continue | |
| if t.fevent or t.fkprobe: | |
| continue | |
| key = (m_proc, pid) | |
| if(key not in ftemp): | |
| ftemp[key] = [] | |
| ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals)) | |
| cg = ftemp[key][-1] | |
| res = cg.addLine(t) | |
| if(res != 0): | |
| ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals)) | |
| if(res == -1): | |
| ftemp[key][-1].addLine(t) | |
| tf.close() | |
| # add the callgraph data to the device hierarchy | |
| for key in ftemp: | |
| proc, pid = key | |
| for cg in ftemp[key]: | |
| if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0): | |
| continue | |
| if(not cg.postProcess()): | |
| pprint('Sanity check failed for %s-%d' % (proc, pid)) | |
| continue | |
| # match cg data to devices | |
| devname = data.deviceMatch(pid, cg) | |
| if not devname: | |
| kind = 'Orphan' | |
| if cg.partial: | |
| kind = 'Partial' | |
| sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\ | |
| (kind, cg.name, proc, pid, cg.start, cg.end)) | |
| elif len(cg.list) > 1000000: | |
| pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\ | |
| (devname, len(cg.list))) | |
| # Function: retrieveLogs | |
| # Description: | |
| # Create copies of dmesg and/or ftrace for later processing | |
| def retrieveLogs(): | |
| # check ftrace is configured first | |
| if sysvals.useftrace: | |
| tracer = sysvals.fgetVal('current_tracer').strip() | |
| if tracer != 'function_graph': | |
| doError('ftrace not configured for a boot callgraph') | |
| # create the folder and get dmesg | |
| sysvals.systemInfo(aslib.dmidecode(sysvals.mempath)) | |
| sysvals.initTestOutput('boot') | |
| sysvals.writeDatafileHeader(sysvals.dmesgfile) | |
| call('dmesg >> '+sysvals.dmesgfile, shell=True) | |
| if not sysvals.useftrace: | |
| return | |
| # get ftrace | |
| sysvals.writeDatafileHeader(sysvals.ftracefile) | |
| call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True) | |
| # Function: colorForName | |
| # Description: | |
| # Generate a repeatable color from a list for a given name | |
| def colorForName(name): | |
| list = [ | |
| ('c1', '#ec9999'), | |
| ('c2', '#ffc1a6'), | |
| ('c3', '#fff0a6'), | |
| ('c4', '#adf199'), | |
| ('c5', '#9fadea'), | |
| ('c6', '#a699c1'), | |
| ('c7', '#ad99b4'), | |
| ('c8', '#eaffea'), | |
| ('c9', '#dcecfb'), | |
| ('c10', '#ffffea') | |
| ] | |
| i = 0 | |
| total = 0 | |
| count = len(list) | |
| while i < len(name): | |
| total += ord(name[i]) | |
| i += 1 | |
| return list[total % count] | |
| def cgOverview(cg, minlen): | |
| stats = dict() | |
| large = [] | |
| for l in cg.list: | |
| if l.fcall and l.depth == 1: | |
| if l.length >= minlen: | |
| large.append(l) | |
| if l.name not in stats: | |
| stats[l.name] = [0, 0.0] | |
| stats[l.name][0] += (l.length * 1000.0) | |
| stats[l.name][1] += 1 | |
| return (large, stats) | |
| # Function: createBootGraph | |
| # Description: | |
| # Create the output html file from the resident test data | |
| # Arguments: | |
| # testruns: array of Data objects from parseKernelLog or parseTraceLog | |
| # Output: | |
| # True if the html file was created, false if it failed | |
| def createBootGraph(data): | |
| # html function templates | |
| 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' | |
| html_timetotal = '<table class="time1">\n<tr>'\ | |
| '<td class="blue">Init process starts @ <b>{0} ms</b></td>'\ | |
| '<td class="blue">Last initcall ends @ <b>{1} ms</b></td>'\ | |
| '</tr>\n</table>\n' | |
| # device timeline | |
| devtl = aslib.Timeline(100, 20) | |
| # write the test title and general info header | |
| devtl.createHeader(sysvals, sysvals.stamp) | |
| # Generate the header for this timeline | |
| t0 = data.start | |
| tMax = data.end | |
| tTotal = tMax - t0 | |
| if(tTotal == 0): | |
| pprint('ERROR: No timeline data') | |
| return False | |
| user_mode = '%.0f'%(data.tUserMode*1000) | |
| last_init = '%.0f'%(tTotal*1000) | |
| devtl.html += html_timetotal.format(user_mode, last_init) | |
| # determine the maximum number of rows we need to draw | |
| devlist = [] | |
| for p in data.phases: | |
| list = data.dmesg[p]['list'] | |
| for devname in list: | |
| d = aslib.DevItem(0, p, list[devname]) | |
| devlist.append(d) | |
| devtl.getPhaseRows(devlist, 0, 'start') | |
| devtl.calcTotalRows() | |
| # draw the timeline background | |
| devtl.createZoomBox() | |
| devtl.html += devtl.html_tblock.format('boot', '0', '100', devtl.scaleH) | |
| for p in data.phases: | |
| phase = data.dmesg[p] | |
| length = phase['end']-phase['start'] | |
| left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) | |
| width = '%.3f' % ((length*100.0)/tTotal) | |
| devtl.html += devtl.html_phase.format(left, width, \ | |
| '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ | |
| phase['color'], '') | |
| # draw the device timeline | |
| num = 0 | |
| devstats = dict() | |
| for phase in data.phases: | |
| list = data.dmesg[phase]['list'] | |
| for devname in sorted(list): | |
| cls, color = colorForName(devname) | |
| dev = list[devname] | |
| info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0, | |
| dev['ulen']/1000.0, dev['ret']) | |
| devstats[dev['id']] = {'info':info} | |
| dev['color'] = color | |
| height = devtl.phaseRowHeight(0, phase, dev['row']) | |
| top = '%.6f' % ((dev['row']*height) + devtl.scaleH) | |
| left = '%.6f' % (((dev['start']-t0)*100)/tTotal) | |
| width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal) | |
| length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) | |
| devtl.html += devtl.html_device.format(dev['id'], | |
| devname+length+phase+'_mode', left, top, '%.3f'%height, | |
| width, devname, ' '+cls, '') | |
| rowtop = devtl.phaseRowTop(0, phase, dev['row']) | |
| height = '%.6f' % (devtl.rowH / 2) | |
| top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2)) | |
| if data.do_one_initcall: | |
| if('ftrace' not in dev): | |
| continue | |
| cg = dev['ftrace'] | |
| large, stats = cgOverview(cg, 0.001) | |
| devstats[dev['id']]['fstat'] = stats | |
| for l in large: | |
| left = '%f' % (((l.time-t0)*100)/tTotal) | |
| width = '%f' % (l.length*100/tTotal) | |
| title = '%s (%0.3fms)' % (l.name, l.length * 1000.0) | |
| devtl.html += html_srccall.format(l.name, left, | |
| top, height, width, title, 'x%d'%num) | |
| num += 1 | |
| continue | |
| if('ftraces' not in dev): | |
| continue | |
| for cg in dev['ftraces']: | |
| left = '%f' % (((cg.start-t0)*100)/tTotal) | |
| width = '%f' % ((cg.end-cg.start)*100/tTotal) | |
| cglen = (cg.end - cg.start) * 1000.0 | |
| title = '%s (%0.3fms)' % (cg.name, cglen) | |
| cg.id = 'x%d' % num | |
| devtl.html += html_srccall.format(cg.name, left, | |
| top, height, width, title, dev['id']+cg.id) | |
| num += 1 | |
| # draw the time scale, try to make the number of labels readable | |
| devtl.createTimeScale(t0, tMax, tTotal, 'boot') | |
| devtl.html += '</div>\n' | |
| # timeline is finished | |
| devtl.html += '</div>\n</div>\n' | |
| # draw a legend which describes the phases by color | |
| devtl.html += '<div class="legend">\n' | |
| pdelta = 20.0 | |
| pmargin = 36.0 | |
| for phase in data.phases: | |
| order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) | |
| devtl.html += devtl.html_legend.format(order, \ | |
| data.dmesg[phase]['color'], phase+'_mode', phase[0]) | |
| devtl.html += '</div>\n' | |
| hf = open(sysvals.htmlfile, 'w') | |
| # add the css | |
| extra = '\ | |
| .c1 {background:rgba(209,0,0,0.4);}\n\ | |
| .c2 {background:rgba(255,102,34,0.4);}\n\ | |
| .c3 {background:rgba(255,218,33,0.4);}\n\ | |
| .c4 {background:rgba(51,221,0,0.4);}\n\ | |
| .c5 {background:rgba(17,51,204,0.4);}\n\ | |
| .c6 {background:rgba(34,0,102,0.4);}\n\ | |
| .c7 {background:rgba(51,0,68,0.4);}\n\ | |
| .c8 {background:rgba(204,255,204,0.4);}\n\ | |
| .c9 {background:rgba(169,208,245,0.4);}\n\ | |
| .c10 {background:rgba(255,255,204,0.4);}\n\ | |
| .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\ | |
| table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\ | |
| .fstat th {width:55px;}\n\ | |
| .fstat td {text-align:left;width:35px;}\n\ | |
| .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\ | |
| .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n' | |
| aslib.addCSS(hf, sysvals, 1, False, extra) | |
| # write the device timeline | |
| hf.write(devtl.html) | |
| # add boot specific html | |
| statinfo = 'var devstats = {\n' | |
| for n in sorted(devstats): | |
| statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info']) | |
| if 'fstat' in devstats[n]: | |
| funcs = devstats[n]['fstat'] | |
| for f in sorted(funcs, key=lambda k:(funcs[k], k), reverse=True): | |
| if funcs[f][0] < 0.01 and len(funcs) > 10: | |
| break | |
| statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1]) | |
| statinfo += '\t],\n' | |
| statinfo += '};\n' | |
| html = \ | |
| '<div id="devicedetailtitle"></div>\n'\ | |
| '<div id="devicedetail" style="display:none;">\n'\ | |
| '<div id="devicedetail0">\n' | |
| for p in data.phases: | |
| phase = data.dmesg[p] | |
| html += devtl.html_phaselet.format(p+'_mode', '0', '100', phase['color']) | |
| html += '</div>\n</div>\n'\ | |
| '<script type="text/javascript">\n'+statinfo+\ | |
| '</script>\n' | |
| hf.write(html) | |
| # add the callgraph html | |
| if(sysvals.usecallgraph): | |
| aslib.addCallgraphs(sysvals, hf, data) | |
| # add the test log as a hidden div | |
| if sysvals.testlog and sysvals.logmsg: | |
| hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n') | |
| # add the dmesg log as a hidden div | |
| if sysvals.dmesglog: | |
| hf.write('<div id="dmesglog" style="display:none;">\n') | |
| for line in data.dmesgtext: | |
| line = line.replace('<', '<').replace('>', '>') | |
| hf.write(line) | |
| hf.write('</div>\n') | |
| # write the footer and close | |
| aslib.addScriptCode(hf, [data]) | |
| hf.write('</body>\n</html>\n') | |
| hf.close() | |
| return True | |
| # Function: updateCron | |
| # Description: | |
| # (restore=False) Set the tool to run automatically on reboot | |
| # (restore=True) Restore the original crontab | |
| def updateCron(restore=False): | |
| if not restore: | |
| sysvals.rootUser(True) | |
| crondir = '/var/spool/cron/crontabs/' | |
| if not os.path.exists(crondir): | |
| crondir = '/var/spool/cron/' | |
| if not os.path.exists(crondir): | |
| doError('%s not found' % crondir) | |
| cronfile = crondir+'root' | |
| backfile = crondir+'root-analyze_boot-backup' | |
| cmd = sysvals.getExec('crontab') | |
| if not cmd: | |
| doError('crontab not found') | |
| # on restore: move the backup cron back into place | |
| if restore: | |
| if os.path.exists(backfile): | |
| shutil.move(backfile, cronfile) | |
| call([cmd, cronfile]) | |
| return | |
| # backup current cron and install new one with reboot | |
| if os.path.exists(cronfile): | |
| shutil.move(cronfile, backfile) | |
| else: | |
| fp = open(backfile, 'w') | |
| fp.close() | |
| res = -1 | |
| try: | |
| fp = open(backfile, 'r') | |
| op = open(cronfile, 'w') | |
| for line in fp: | |
| if not sysvals.myCronJob(line): | |
| op.write(line) | |
| continue | |
| fp.close() | |
| op.write('@reboot python %s\n' % sysvals.cronjobCmdString()) | |
| op.close() | |
| res = call([cmd, cronfile]) | |
| except Exception as e: | |
| pprint('Exception: %s' % str(e)) | |
| shutil.move(backfile, cronfile) | |
| res = -1 | |
| if res != 0: | |
| doError('crontab failed') | |
| # Function: updateGrub | |
| # Description: | |
| # update grub.cfg for all kernels with our parameters | |
| def updateGrub(restore=False): | |
| # call update-grub on restore | |
| if restore: | |
| try: | |
| call(sysvals.blexec, stderr=PIPE, stdout=PIPE, | |
| env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'}) | |
| except Exception as e: | |
| pprint('Exception: %s\n' % str(e)) | |
| return | |
| # extract the option and create a grub config without it | |
| sysvals.rootUser(True) | |
| tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT' | |
| cmdline = '' | |
| grubfile = '/etc/default/grub' | |
| tempfile = '/etc/default/grub.analyze_boot' | |
| shutil.move(grubfile, tempfile) | |
| res = -1 | |
| try: | |
| fp = open(tempfile, 'r') | |
| op = open(grubfile, 'w') | |
| cont = False | |
| for line in fp: | |
| line = line.strip() | |
| if len(line) == 0 or line[0] == '#': | |
| continue | |
| opt = line.split('=')[0].strip() | |
| if opt == tgtopt: | |
| cmdline = line.split('=', 1)[1].strip('\\') | |
| if line[-1] == '\\': | |
| cont = True | |
| elif cont: | |
| cmdline += line.strip('\\') | |
| if line[-1] != '\\': | |
| cont = False | |
| else: | |
| op.write('%s\n' % line) | |
| fp.close() | |
| # if the target option value is in quotes, strip them | |
| sp = '"' | |
| val = cmdline.strip() | |
| if val and (val[0] == '\'' or val[0] == '"'): | |
| sp = val[0] | |
| val = val.strip(sp) | |
| cmdline = val | |
| # append our cmd line options | |
| if len(cmdline) > 0: | |
| cmdline += ' ' | |
| cmdline += sysvals.kernelParams() | |
| # write out the updated target option | |
| op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp)) | |
| op.close() | |
| res = call(sysvals.blexec) | |
| os.remove(grubfile) | |
| except Exception as e: | |
| pprint('Exception: %s' % str(e)) | |
| res = -1 | |
| # cleanup | |
| shutil.move(tempfile, grubfile) | |
| if res != 0: | |
| doError('update grub failed') | |
| # Function: updateKernelParams | |
| # Description: | |
| # update boot conf for all kernels with our parameters | |
| def updateKernelParams(restore=False): | |
| # find the boot loader | |
| sysvals.getBootLoader() | |
| if sysvals.bootloader == 'grub': | |
| updateGrub(restore) | |
| # Function: doError Description: | |
| # generic error function for catastrphic failures | |
| # Arguments: | |
| # msg: the error message to print | |
| # help: True if printHelp should be called after, False otherwise | |
| def doError(msg, help=False): | |
| if help == True: | |
| printHelp() | |
| pprint('ERROR: %s\n' % msg) | |
| sysvals.outputResult({'error':msg}) | |
| sys.exit() | |
| # Function: printHelp | |
| # Description: | |
| # print out the help text | |
| def printHelp(): | |
| pprint('\n%s v%s\n'\ | |
| 'Usage: bootgraph <options> <command>\n'\ | |
| '\n'\ | |
| 'Description:\n'\ | |
| ' This tool reads in a dmesg log of linux kernel boot and\n'\ | |
| ' creates an html representation of the boot timeline up to\n'\ | |
| ' the start of the init process.\n'\ | |
| '\n'\ | |
| ' If no specific command is given the tool reads the current dmesg\n'\ | |
| ' and/or ftrace log and creates a timeline\n'\ | |
| '\n'\ | |
| ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\ | |
| ' HTML output: <hostname>_boot.html\n'\ | |
| ' raw dmesg output: <hostname>_boot_dmesg.txt\n'\ | |
| ' raw ftrace output: <hostname>_boot_ftrace.txt\n'\ | |
| '\n'\ | |
| 'Options:\n'\ | |
| ' -h Print this help text\n'\ | |
| ' -v Print the current tool version\n'\ | |
| ' -verbose Print extra information during execution and analysis\n'\ | |
| ' -addlogs Add the dmesg log to the html output\n'\ | |
| ' -result fn Export a results table to a text file for parsing.\n'\ | |
| ' -o name Overrides the output subdirectory name when running a new test\n'\ | |
| ' default: boot-{date}-{time}\n'\ | |
| ' [advanced]\n'\ | |
| ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\ | |
| ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\ | |
| ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\ | |
| ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\ | |
| ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\ | |
| ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\ | |
| ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\ | |
| ' -cgfilter S Filter the callgraph output in the timeline\n'\ | |
| ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\ | |
| ' -bl name Use the following boot loader for kernel params (default: grub)\n'\ | |
| ' -reboot Reboot the machine automatically and generate a new timeline\n'\ | |
| ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\ | |
| '\n'\ | |
| 'Other commands:\n'\ | |
| ' -flistall Print all functions capable of being captured in ftrace\n'\ | |
| ' -sysinfo Print out system info extracted from BIOS\n'\ | |
| ' -which exec Print an executable path, should function even without PATH\n'\ | |
| ' [redo]\n'\ | |
| ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\ | |
| ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\ | |
| '' % (sysvals.title, sysvals.version)) | |
| return True | |
| # ----------------- MAIN -------------------- | |
| # exec start (skipped if script is loaded as library) | |
| if __name__ == '__main__': | |
| # loop through the command line arguments | |
| cmd = '' | |
| testrun = True | |
| switchoff = ['disable', 'off', 'false', '0'] | |
| simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl'] | |
| cgskip = '' | |
| if '-f' in sys.argv: | |
| cgskip = sysvals.configFile('cgskip.txt') | |
| args = iter(sys.argv[1:]) | |
| mdset = False | |
| for arg in args: | |
| if(arg == '-h'): | |
| printHelp() | |
| sys.exit() | |
| elif(arg == '-v'): | |
| pprint("Version %s" % sysvals.version) | |
| sys.exit() | |
| elif(arg == '-verbose'): | |
| sysvals.verbose = True | |
| elif(arg in simplecmds): | |
| cmd = arg[1:] | |
| elif(arg == '-fstat'): | |
| sysvals.useftrace = True | |
| elif(arg == '-callgraph' or arg == '-f'): | |
| sysvals.useftrace = True | |
| sysvals.usecallgraph = True | |
| elif(arg == '-cgdump'): | |
| sysvals.cgdump = True | |
| elif(arg == '-mincg'): | |
| sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0) | |
| elif(arg == '-cgfilter'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No callgraph functions supplied', True) | |
| sysvals.setCallgraphFilter(val) | |
| elif(arg == '-cgskip'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No file supplied', True) | |
| if val.lower() in switchoff: | |
| cgskip = '' | |
| else: | |
| cgskip = sysvals.configFile(val) | |
| if(not cgskip): | |
| doError('%s does not exist' % cgskip) | |
| elif(arg == '-bl'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No boot loader name supplied', True) | |
| if val.lower() not in ['grub']: | |
| doError('Unknown boot loader: %s' % val, True) | |
| sysvals.bootloader = val.lower() | |
| elif(arg == '-timeprec'): | |
| sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6)) | |
| elif(arg == '-maxdepth'): | |
| mdset = True | |
| sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000) | |
| elif(arg == '-func'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No filter functions supplied', True) | |
| sysvals.useftrace = True | |
| sysvals.usecallgraph = True | |
| sysvals.rootCheck(True) | |
| sysvals.setGraphFilter(val) | |
| elif(arg == '-ftrace'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No ftrace file supplied', True) | |
| if(os.path.exists(val) == False): | |
| doError('%s does not exist' % val) | |
| testrun = False | |
| sysvals.ftracefile = val | |
| elif(arg == '-addlogs'): | |
| sysvals.dmesglog = True | |
| elif(arg == '-expandcg'): | |
| sysvals.cgexp = True | |
| elif(arg == '-dmesg'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No dmesg file supplied', True) | |
| if(os.path.exists(val) == False): | |
| doError('%s does not exist' % val) | |
| testrun = False | |
| sysvals.dmesgfile = val | |
| elif(arg == '-o'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No subdirectory name supplied', True) | |
| sysvals.testdir = sysvals.setOutputFolder(val) | |
| elif(arg == '-result'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No result file supplied', True) | |
| sysvals.result = val | |
| elif(arg == '-reboot'): | |
| sysvals.reboot = True | |
| elif(arg == '-manual'): | |
| sysvals.reboot = True | |
| sysvals.manual = True | |
| # remaining options are only for cron job use | |
| elif(arg == '-cronjob'): | |
| sysvals.iscronjob = True | |
| elif(arg == '-which'): | |
| try: | |
| val = next(args) | |
| except: | |
| doError('No executable supplied', True) | |
| out = sysvals.getExec(val) | |
| if not out: | |
| print('%s not found' % val) | |
| sys.exit(1) | |
| print(out) | |
| sys.exit(0) | |
| else: | |
| doError('Invalid argument: '+arg, True) | |
| # compatibility errors and access checks | |
| if(sysvals.iscronjob and (sysvals.reboot or \ | |
| sysvals.dmesgfile or sysvals.ftracefile or cmd)): | |
| doError('-cronjob is meant for batch purposes only') | |
| if(sysvals.reboot and (sysvals.dmesgfile or sysvals.ftracefile)): | |
| doError('-reboot and -dmesg/-ftrace are incompatible') | |
| if cmd or sysvals.reboot or sysvals.iscronjob or testrun: | |
| sysvals.rootCheck(True) | |
| if (testrun and sysvals.useftrace) or cmd == 'flistall': | |
| if not sysvals.verifyFtrace(): | |
| doError('Ftrace is not properly enabled') | |
| # run utility commands | |
| sysvals.cpuInfo() | |
| if cmd != '': | |
| if cmd == 'kpupdate': | |
| updateKernelParams() | |
| elif cmd == 'flistall': | |
| for f in sysvals.getBootFtraceFilterFunctions(): | |
| print(f) | |
| elif cmd == 'checkbl': | |
| sysvals.getBootLoader() | |
| pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)) | |
| elif(cmd == 'sysinfo'): | |
| sysvals.printSystemInfo(True) | |
| sys.exit() | |
| # reboot: update grub, setup a cronjob, and reboot | |
| if sysvals.reboot: | |
| if (sysvals.useftrace or sysvals.usecallgraph) and \ | |
| not sysvals.checkFtraceKernelVersion(): | |
| doError('Ftrace functionality requires kernel v4.10 or newer') | |
| if not sysvals.manual: | |
| updateKernelParams() | |
| updateCron() | |
| call('reboot') | |
| else: | |
| sysvals.manualRebootRequired() | |
| sys.exit() | |
| if sysvals.usecallgraph and cgskip: | |
| sysvals.vprint('Using cgskip file: %s' % cgskip) | |
| sysvals.setCallgraphBlacklist(cgskip) | |
| # cronjob: remove the cronjob, grub changes, and disable ftrace | |
| if sysvals.iscronjob: | |
| updateCron(True) | |
| updateKernelParams(True) | |
| try: | |
| sysvals.fsetVal('0', 'tracing_on') | |
| except: | |
| pass | |
| # testrun: generate copies of the logs | |
| if testrun: | |
| retrieveLogs() | |
| else: | |
| sysvals.setOutputFile() | |
| # process the log data | |
| if sysvals.dmesgfile: | |
| if not mdset: | |
| sysvals.max_graph_depth = 0 | |
| data = parseKernelLog() | |
| if(not data.valid): | |
| doError('No initcall data found in %s' % sysvals.dmesgfile) | |
| if sysvals.useftrace and sysvals.ftracefile: | |
| parseTraceLog(data) | |
| if sysvals.cgdump: | |
| data.debugPrint() | |
| sys.exit() | |
| else: | |
| doError('dmesg file required') | |
| sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) | |
| sysvals.vprint('Command:\n %s' % sysvals.cmdline) | |
| sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams) | |
| data.printDetails() | |
| createBootGraph(data) | |
| # if running as root, change output dir owner to sudo_user | |
| if testrun and os.path.isdir(sysvals.testdir) and \ | |
| os.getuid() == 0 and 'SUDO_USER' in os.environ: | |
| cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' | |
| call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True) | |
| sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000 | |
| sysvals.stamp['lastinit'] = data.end * 1000 | |
| sysvals.outputResult(sysvals.stamp) |