0001
0002
0003
0004
0005
0006
0007
0008
0009
0010
0011
0012
0013
0014
0015
0016
0017
0018
0019
0020
0021
0022
0023
0024
0025
0026
0027 import sys
0028 import time
0029 import os
0030 import string
0031 import re
0032 import platform
0033 import shutil
0034 from datetime import datetime, timedelta
0035 from subprocess import call, Popen, PIPE
0036 import sleepgraph as aslib
0037
0038 def pprint(msg):
0039 print(msg)
0040 sys.stdout.flush()
0041
0042
0043
0044
0045
0046
0047
0048 class SystemValues(aslib.SystemValues):
0049 title = 'BootGraph'
0050 version = '2.2'
0051 hostname = 'localhost'
0052 testtime = ''
0053 kernel = ''
0054 dmesgfile = ''
0055 ftracefile = ''
0056 htmlfile = 'bootgraph.html'
0057 testdir = ''
0058 kparams = ''
0059 result = ''
0060 useftrace = False
0061 usecallgraph = False
0062 suspendmode = 'boot'
0063 max_graph_depth = 2
0064 graph_filter = 'do_one_initcall'
0065 reboot = False
0066 manual = False
0067 iscronjob = False
0068 timeformat = '%.6f'
0069 bootloader = 'grub'
0070 blexec = []
0071 def __init__(self):
0072 self.kernel, self.hostname = 'unknown', platform.node()
0073 self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')
0074 if os.path.exists('/proc/version'):
0075 fp = open('/proc/version', 'r')
0076 self.kernel = self.kernelVersion(fp.read().strip())
0077 fp.close()
0078 self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')
0079 def kernelVersion(self, msg):
0080 m = re.match('^[Ll]inux *[Vv]ersion *(?P<v>\S*) .*', msg)
0081 if m:
0082 return m.group('v')
0083 return 'unknown'
0084 def checkFtraceKernelVersion(self):
0085 m = re.match('^(?P<x>[0-9]*)\.(?P<y>[0-9]*)\.(?P<z>[0-9]*).*', self.kernel)
0086 if m:
0087 val = tuple(map(int, m.groups()))
0088 if val >= (4, 10, 0):
0089 return True
0090 return False
0091 def kernelParams(self):
0092 cmdline = 'initcall_debug log_buf_len=32M'
0093 if self.useftrace:
0094 if self.cpucount > 0:
0095 bs = min(self.memtotal // 2, 2*1024*1024) // self.cpucount
0096 else:
0097 bs = 131072
0098 cmdline += ' trace_buf_size=%dK trace_clock=global '\
0099 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\
0100 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\
0101 'nofuncgraph-overhead,context-info,graph-time '\
0102 'ftrace=function_graph '\
0103 'ftrace_graph_max_depth=%d '\
0104 'ftrace_graph_filter=%s' % \
0105 (bs, self.max_graph_depth, self.graph_filter)
0106 return cmdline
0107 def setGraphFilter(self, val):
0108 master = self.getBootFtraceFilterFunctions()
0109 fs = ''
0110 for i in val.split(','):
0111 func = i.strip()
0112 if func == '':
0113 doError('badly formatted filter function string')
0114 if '[' in func or ']' in func:
0115 doError('loadable module functions not allowed - "%s"' % func)
0116 if ' ' in func:
0117 doError('spaces found in filter functions - "%s"' % func)
0118 if func not in master:
0119 doError('function "%s" not available for ftrace' % func)
0120 if not fs:
0121 fs = func
0122 else:
0123 fs += ','+func
0124 if not fs:
0125 doError('badly formatted filter function string')
0126 self.graph_filter = fs
0127 def getBootFtraceFilterFunctions(self):
0128 self.rootCheck(True)
0129 fp = open(self.tpath+'available_filter_functions')
0130 fulllist = fp.read().split('\n')
0131 fp.close()
0132 list = []
0133 for i in fulllist:
0134 if not i or ' ' in i or '[' in i or ']' in i:
0135 continue
0136 list.append(i)
0137 return list
0138 def myCronJob(self, line):
0139 if '@reboot' not in line:
0140 return False
0141 if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:
0142 return True
0143 return False
0144 def cronjobCmdString(self):
0145 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
0146 args = iter(sys.argv[1:])
0147 for arg in args:
0148 if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
0149 continue
0150 elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
0151 next(args)
0152 continue
0153 elif arg == '-result':
0154 cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args)))
0155 continue
0156 elif arg == '-cgskip':
0157 file = self.configFile(next(args))
0158 cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
0159 continue
0160 cmdline += ' '+arg
0161 if self.graph_filter != 'do_one_initcall':
0162 cmdline += ' -func "%s"' % self.graph_filter
0163 cmdline += ' -o "%s"' % os.path.abspath(self.testdir)
0164 return cmdline
0165 def manualRebootRequired(self):
0166 cmdline = self.kernelParams()
0167 pprint('To generate a new timeline manually, follow these steps:\n\n'\
0168 '1. Add the CMDLINE string to your kernel command line.\n'\
0169 '2. Reboot the system.\n'\
0170 '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\
0171 'CMDLINE="%s"' % cmdline)
0172 sys.exit()
0173 def blGrub(self):
0174 blcmd = ''
0175 for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
0176 if blcmd:
0177 break
0178 blcmd = self.getExec(cmd)
0179 if not blcmd:
0180 doError('[GRUB] missing update command')
0181 if not os.path.exists('/etc/default/grub'):
0182 doError('[GRUB] missing /etc/default/grub')
0183 if 'grub2' in blcmd:
0184 cfg = '/boot/grub2/grub.cfg'
0185 else:
0186 cfg = '/boot/grub/grub.cfg'
0187 if not os.path.exists(cfg):
0188 doError('[GRUB] missing %s' % cfg)
0189 if 'update-grub' in blcmd:
0190 self.blexec = [blcmd]
0191 else:
0192 self.blexec = [blcmd, '-o', cfg]
0193 def getBootLoader(self):
0194 if self.bootloader == 'grub':
0195 self.blGrub()
0196 else:
0197 doError('unknown boot loader: %s' % self.bootloader)
0198 def writeDatafileHeader(self, filename):
0199 self.kparams = open('/proc/cmdline', 'r').read().strip()
0200 fp = open(filename, 'w')
0201 fp.write(self.teststamp+'\n')
0202 fp.write(self.sysstamp+'\n')
0203 fp.write('# command | %s\n' % self.cmdline)
0204 fp.write('# kparams | %s\n' % self.kparams)
0205 fp.close()
0206
0207 sysvals = SystemValues()
0208
0209
0210
0211
0212 class Data(aslib.Data):
0213 dmesg = {}
0214 start = 0.0
0215 end = 0.0
0216 dmesgtext = []
0217 testnumber = 0
0218 idstr = ''
0219 html_device_id = 0
0220 valid = False
0221 tUserMode = 0.0
0222 boottime = ''
0223 phases = ['kernel', 'user']
0224 do_one_initcall = False
0225 def __init__(self, num):
0226 self.testnumber = num
0227 self.idstr = 'a'
0228 self.dmesgtext = []
0229 self.dmesg = {
0230 'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
0231 'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'},
0232 'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
0233 'order': 1, 'color': '#fff'}
0234 }
0235 def deviceTopology(self):
0236 return ''
0237 def newAction(self, phase, name, pid, start, end, ret, ulen):
0238
0239 self.html_device_id += 1
0240 devid = '%s%d' % (self.idstr, self.html_device_id)
0241 list = self.dmesg[phase]['list']
0242 length = -1.0
0243 if(start >= 0 and end >= 0):
0244 length = end - start
0245 i = 2
0246 origname = name
0247 while(name in list):
0248 name = '%s[%d]' % (origname, i)
0249 i += 1
0250 list[name] = {'name': name, 'start': start, 'end': end,
0251 'pid': pid, 'length': length, 'row': 0, 'id': devid,
0252 'ret': ret, 'ulen': ulen }
0253 return name
0254 def deviceMatch(self, pid, cg):
0255 if cg.end - cg.start == 0:
0256 return ''
0257 for p in data.phases:
0258 list = self.dmesg[p]['list']
0259 for devname in list:
0260 dev = list[devname]
0261 if pid != dev['pid']:
0262 continue
0263 if cg.name == 'do_one_initcall':
0264 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
0265 dev['ftrace'] = cg
0266 self.do_one_initcall = True
0267 return devname
0268 else:
0269 if(cg.start > dev['start'] and cg.end < dev['end']):
0270 if 'ftraces' not in dev:
0271 dev['ftraces'] = []
0272 dev['ftraces'].append(cg)
0273 return devname
0274 return ''
0275 def printDetails(self):
0276 sysvals.vprint('Timeline Details:')
0277 sysvals.vprint(' Host: %s' % sysvals.hostname)
0278 sysvals.vprint(' Kernel: %s' % sysvals.kernel)
0279 sysvals.vprint(' Test time: %s' % sysvals.testtime)
0280 sysvals.vprint(' Boot time: %s' % self.boottime)
0281 for phase in self.phases:
0282 dc = len(self.dmesg[phase]['list'])
0283 sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,
0284 self.dmesg[phase]['start']*1000,
0285 self.dmesg[phase]['end']*1000, dc))
0286
0287
0288
0289
0290
0291
0292 def parseKernelLog():
0293 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
0294 os.path.basename(sysvals.dmesgfile))
0295 phase = 'kernel'
0296 data = Data(0)
0297 data.dmesg['kernel']['start'] = data.start = ktime = 0.0
0298 sysvals.stamp = {
0299 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
0300 'host': sysvals.hostname,
0301 'mode': 'boot', 'kernel': ''}
0302
0303 tp = aslib.TestProps()
0304 devtemp = dict()
0305 if(sysvals.dmesgfile):
0306 lf = open(sysvals.dmesgfile, 'rb')
0307 else:
0308 lf = Popen('dmesg', stdout=PIPE).stdout
0309 for line in lf:
0310 line = aslib.ascii(line).replace('\r\n', '')
0311
0312 if re.match(tp.stampfmt, line):
0313 tp.stamp = line
0314 continue
0315 elif re.match(tp.sysinfofmt, line):
0316 tp.sysinfo = line
0317 continue
0318 elif re.match(tp.cmdlinefmt, line):
0319 tp.cmdline = line
0320 continue
0321 elif re.match(tp.kparamsfmt, line):
0322 tp.kparams = line
0323 continue
0324 idx = line.find('[')
0325 if idx > 1:
0326 line = line[idx:]
0327 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
0328 if(not m):
0329 continue
0330 ktime = float(m.group('ktime'))
0331 if(ktime > 120):
0332 break
0333 msg = m.group('msg')
0334 data.dmesgtext.append(line)
0335 if(ktime == 0.0 and re.match('^Linux version .*', msg)):
0336 if(not sysvals.stamp['kernel']):
0337 sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
0338 continue
0339 m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg)
0340 if(m):
0341 bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S')
0342 bt = bt - timedelta(seconds=int(ktime))
0343 data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
0344 sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
0345 continue
0346 m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
0347 if(m):
0348 func = m.group('f')
0349 pid = int(m.group('p'))
0350 devtemp[func] = (ktime, pid)
0351 continue
0352 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
0353 if(m):
0354 data.valid = True
0355 data.end = ktime
0356 f, r, t = m.group('f', 'r', 't')
0357 if(f in devtemp):
0358 start, pid = devtemp[f]
0359 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
0360 del devtemp[f]
0361 continue
0362 if(re.match('^Freeing unused kernel .*', msg)):
0363 data.tUserMode = ktime
0364 data.dmesg['kernel']['end'] = ktime
0365 data.dmesg['user']['start'] = ktime
0366 phase = 'user'
0367
0368 if tp.stamp:
0369 sysvals.stamp = 0
0370 tp.parseStamp(data, sysvals)
0371 data.dmesg['user']['end'] = data.end
0372 lf.close()
0373 return data
0374
0375
0376
0377
0378 def parseTraceLog(data):
0379 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
0380 os.path.basename(sysvals.ftracefile))
0381
0382 cgfilter = []
0383 if len(sysvals.cgfilter) > 0:
0384 for p in data.phases:
0385 list = data.dmesg[p]['list']
0386 for i in sysvals.cgfilter:
0387 if i in list:
0388 cgfilter.append([list[i]['start']-0.0001,
0389 list[i]['end']+0.0001])
0390
0391 ftemp = dict()
0392 tp = aslib.TestProps()
0393 tp.setTracerType('function_graph')
0394 tf = open(sysvals.ftracefile, 'r')
0395 for line in tf:
0396 if line[0] == '#':
0397 continue
0398 m = re.match(tp.ftrace_line_fmt, line.strip())
0399 if(not m):
0400 continue
0401 m_time, m_proc, m_pid, m_msg, m_dur = \
0402 m.group('time', 'proc', 'pid', 'msg', 'dur')
0403 t = float(m_time)
0404 if len(cgfilter) > 0:
0405 allow = False
0406 for r in cgfilter:
0407 if t >= r[0] and t < r[1]:
0408 allow = True
0409 break
0410 if not allow:
0411 continue
0412 if t > data.end:
0413 break
0414 if(m_time and m_pid and m_msg):
0415 t = aslib.FTraceLine(m_time, m_msg, m_dur)
0416 pid = int(m_pid)
0417 else:
0418 continue
0419 if t.fevent or t.fkprobe:
0420 continue
0421 key = (m_proc, pid)
0422 if(key not in ftemp):
0423 ftemp[key] = []
0424 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
0425 cg = ftemp[key][-1]
0426 res = cg.addLine(t)
0427 if(res != 0):
0428 ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
0429 if(res == -1):
0430 ftemp[key][-1].addLine(t)
0431
0432 tf.close()
0433
0434
0435 for key in ftemp:
0436 proc, pid = key
0437 for cg in ftemp[key]:
0438 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
0439 continue
0440 if(not cg.postProcess()):
0441 pprint('Sanity check failed for %s-%d' % (proc, pid))
0442 continue
0443
0444 devname = data.deviceMatch(pid, cg)
0445 if not devname:
0446 kind = 'Orphan'
0447 if cg.partial:
0448 kind = 'Partial'
0449 sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\
0450 (kind, cg.name, proc, pid, cg.start, cg.end))
0451 elif len(cg.list) > 1000000:
0452 pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\
0453 (devname, len(cg.list)))
0454
0455
0456
0457
0458 def retrieveLogs():
0459
0460 if sysvals.useftrace:
0461 tracer = sysvals.fgetVal('current_tracer').strip()
0462 if tracer != 'function_graph':
0463 doError('ftrace not configured for a boot callgraph')
0464
0465 sysvals.systemInfo(aslib.dmidecode(sysvals.mempath))
0466 sysvals.initTestOutput('boot')
0467 sysvals.writeDatafileHeader(sysvals.dmesgfile)
0468 call('dmesg >> '+sysvals.dmesgfile, shell=True)
0469 if not sysvals.useftrace:
0470 return
0471
0472 sysvals.writeDatafileHeader(sysvals.ftracefile)
0473 call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True)
0474
0475
0476
0477
0478 def colorForName(name):
0479 list = [
0480 ('c1', '#ec9999'),
0481 ('c2', '#ffc1a6'),
0482 ('c3', '#fff0a6'),
0483 ('c4', '#adf199'),
0484 ('c5', '#9fadea'),
0485 ('c6', '#a699c1'),
0486 ('c7', '#ad99b4'),
0487 ('c8', '#eaffea'),
0488 ('c9', '#dcecfb'),
0489 ('c10', '#ffffea')
0490 ]
0491 i = 0
0492 total = 0
0493 count = len(list)
0494 while i < len(name):
0495 total += ord(name[i])
0496 i += 1
0497 return list[total % count]
0498
0499 def cgOverview(cg, minlen):
0500 stats = dict()
0501 large = []
0502 for l in cg.list:
0503 if l.fcall and l.depth == 1:
0504 if l.length >= minlen:
0505 large.append(l)
0506 if l.name not in stats:
0507 stats[l.name] = [0, 0.0]
0508 stats[l.name][0] += (l.length * 1000.0)
0509 stats[l.name][1] += 1
0510 return (large, stats)
0511
0512
0513
0514
0515
0516
0517
0518
0519 def createBootGraph(data):
0520
0521 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'
0522 html_timetotal = '<table class="time1">\n<tr>'\
0523 '<td class="blue">Init process starts @ <b>{0} ms</b></td>'\
0524 '<td class="blue">Last initcall ends @ <b>{1} ms</b></td>'\
0525 '</tr>\n</table>\n'
0526
0527
0528 devtl = aslib.Timeline(100, 20)
0529
0530
0531 devtl.createHeader(sysvals, sysvals.stamp)
0532
0533
0534 t0 = data.start
0535 tMax = data.end
0536 tTotal = tMax - t0
0537 if(tTotal == 0):
0538 pprint('ERROR: No timeline data')
0539 return False
0540 user_mode = '%.0f'%(data.tUserMode*1000)
0541 last_init = '%.0f'%(tTotal*1000)
0542 devtl.html += html_timetotal.format(user_mode, last_init)
0543
0544
0545 devlist = []
0546 for p in data.phases:
0547 list = data.dmesg[p]['list']
0548 for devname in list:
0549 d = aslib.DevItem(0, p, list[devname])
0550 devlist.append(d)
0551 devtl.getPhaseRows(devlist, 0, 'start')
0552 devtl.calcTotalRows()
0553
0554
0555 devtl.createZoomBox()
0556 devtl.html += devtl.html_tblock.format('boot', '0', '100', devtl.scaleH)
0557 for p in data.phases:
0558 phase = data.dmesg[p]
0559 length = phase['end']-phase['start']
0560 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
0561 width = '%.3f' % ((length*100.0)/tTotal)
0562 devtl.html += devtl.html_phase.format(left, width, \
0563 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
0564 phase['color'], '')
0565
0566
0567 num = 0
0568 devstats = dict()
0569 for phase in data.phases:
0570 list = data.dmesg[phase]['list']
0571 for devname in sorted(list):
0572 cls, color = colorForName(devname)
0573 dev = list[devname]
0574 info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0,
0575 dev['ulen']/1000.0, dev['ret'])
0576 devstats[dev['id']] = {'info':info}
0577 dev['color'] = color
0578 height = devtl.phaseRowHeight(0, phase, dev['row'])
0579 top = '%.6f' % ((dev['row']*height) + devtl.scaleH)
0580 left = '%.6f' % (((dev['start']-t0)*100)/tTotal)
0581 width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal)
0582 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
0583 devtl.html += devtl.html_device.format(dev['id'],
0584 devname+length+phase+'_mode', left, top, '%.3f'%height,
0585 width, devname, ' '+cls, '')
0586 rowtop = devtl.phaseRowTop(0, phase, dev['row'])
0587 height = '%.6f' % (devtl.rowH / 2)
0588 top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2))
0589 if data.do_one_initcall:
0590 if('ftrace' not in dev):
0591 continue
0592 cg = dev['ftrace']
0593 large, stats = cgOverview(cg, 0.001)
0594 devstats[dev['id']]['fstat'] = stats
0595 for l in large:
0596 left = '%f' % (((l.time-t0)*100)/tTotal)
0597 width = '%f' % (l.length*100/tTotal)
0598 title = '%s (%0.3fms)' % (l.name, l.length * 1000.0)
0599 devtl.html += html_srccall.format(l.name, left,
0600 top, height, width, title, 'x%d'%num)
0601 num += 1
0602 continue
0603 if('ftraces' not in dev):
0604 continue
0605 for cg in dev['ftraces']:
0606 left = '%f' % (((cg.start-t0)*100)/tTotal)
0607 width = '%f' % ((cg.end-cg.start)*100/tTotal)
0608 cglen = (cg.end - cg.start) * 1000.0
0609 title = '%s (%0.3fms)' % (cg.name, cglen)
0610 cg.id = 'x%d' % num
0611 devtl.html += html_srccall.format(cg.name, left,
0612 top, height, width, title, dev['id']+cg.id)
0613 num += 1
0614
0615
0616 devtl.createTimeScale(t0, tMax, tTotal, 'boot')
0617 devtl.html += '</div>\n'
0618
0619
0620 devtl.html += '</div>\n</div>\n'
0621
0622
0623 devtl.html += '<div class="legend">\n'
0624 pdelta = 20.0
0625 pmargin = 36.0
0626 for phase in data.phases:
0627 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
0628 devtl.html += devtl.html_legend.format(order, \
0629 data.dmesg[phase]['color'], phase+'_mode', phase[0])
0630 devtl.html += '</div>\n'
0631
0632 hf = open(sysvals.htmlfile, 'w')
0633
0634
0635 extra = '\
0636 .c1 {background:rgba(209,0,0,0.4);}\n\
0637 .c2 {background:rgba(255,102,34,0.4);}\n\
0638 .c3 {background:rgba(255,218,33,0.4);}\n\
0639 .c4 {background:rgba(51,221,0,0.4);}\n\
0640 .c5 {background:rgba(17,51,204,0.4);}\n\
0641 .c6 {background:rgba(34,0,102,0.4);}\n\
0642 .c7 {background:rgba(51,0,68,0.4);}\n\
0643 .c8 {background:rgba(204,255,204,0.4);}\n\
0644 .c9 {background:rgba(169,208,245,0.4);}\n\
0645 .c10 {background:rgba(255,255,204,0.4);}\n\
0646 .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\
0647 table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\
0648 .fstat th {width:55px;}\n\
0649 .fstat td {text-align:left;width:35px;}\n\
0650 .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\
0651 .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
0652 aslib.addCSS(hf, sysvals, 1, False, extra)
0653
0654
0655 hf.write(devtl.html)
0656
0657
0658 statinfo = 'var devstats = {\n'
0659 for n in sorted(devstats):
0660 statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info'])
0661 if 'fstat' in devstats[n]:
0662 funcs = devstats[n]['fstat']
0663 for f in sorted(funcs, key=lambda k:(funcs[k], k), reverse=True):
0664 if funcs[f][0] < 0.01 and len(funcs) > 10:
0665 break
0666 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
0667 statinfo += '\t],\n'
0668 statinfo += '};\n'
0669 html = \
0670 '<div id="devicedetailtitle"></div>\n'\
0671 '<div id="devicedetail" style="display:none;">\n'\
0672 '<div id="devicedetail0">\n'
0673 for p in data.phases:
0674 phase = data.dmesg[p]
0675 html += devtl.html_phaselet.format(p+'_mode', '0', '100', phase['color'])
0676 html += '</div>\n</div>\n'\
0677 '<script type="text/javascript">\n'+statinfo+\
0678 '</script>\n'
0679 hf.write(html)
0680
0681
0682 if(sysvals.usecallgraph):
0683 aslib.addCallgraphs(sysvals, hf, data)
0684
0685
0686 if sysvals.testlog and sysvals.logmsg:
0687 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
0688
0689 if sysvals.dmesglog:
0690 hf.write('<div id="dmesglog" style="display:none;">\n')
0691 for line in data.dmesgtext:
0692 line = line.replace('<', '<').replace('>', '>')
0693 hf.write(line)
0694 hf.write('</div>\n')
0695
0696
0697 aslib.addScriptCode(hf, [data])
0698 hf.write('</body>\n</html>\n')
0699 hf.close()
0700 return True
0701
0702
0703
0704
0705
0706 def updateCron(restore=False):
0707 if not restore:
0708 sysvals.rootUser(True)
0709 crondir = '/var/spool/cron/crontabs/'
0710 if not os.path.exists(crondir):
0711 crondir = '/var/spool/cron/'
0712 if not os.path.exists(crondir):
0713 doError('%s not found' % crondir)
0714 cronfile = crondir+'root'
0715 backfile = crondir+'root-analyze_boot-backup'
0716 cmd = sysvals.getExec('crontab')
0717 if not cmd:
0718 doError('crontab not found')
0719
0720 if restore:
0721 if os.path.exists(backfile):
0722 shutil.move(backfile, cronfile)
0723 call([cmd, cronfile])
0724 return
0725
0726 if os.path.exists(cronfile):
0727 shutil.move(cronfile, backfile)
0728 else:
0729 fp = open(backfile, 'w')
0730 fp.close()
0731 res = -1
0732 try:
0733 fp = open(backfile, 'r')
0734 op = open(cronfile, 'w')
0735 for line in fp:
0736 if not sysvals.myCronJob(line):
0737 op.write(line)
0738 continue
0739 fp.close()
0740 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
0741 op.close()
0742 res = call([cmd, cronfile])
0743 except Exception as e:
0744 pprint('Exception: %s' % str(e))
0745 shutil.move(backfile, cronfile)
0746 res = -1
0747 if res != 0:
0748 doError('crontab failed')
0749
0750
0751
0752
0753 def updateGrub(restore=False):
0754
0755 if restore:
0756 try:
0757 call(sysvals.blexec, stderr=PIPE, stdout=PIPE,
0758 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'})
0759 except Exception as e:
0760 pprint('Exception: %s\n' % str(e))
0761 return
0762
0763 sysvals.rootUser(True)
0764 tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
0765 cmdline = ''
0766 grubfile = '/etc/default/grub'
0767 tempfile = '/etc/default/grub.analyze_boot'
0768 shutil.move(grubfile, tempfile)
0769 res = -1
0770 try:
0771 fp = open(tempfile, 'r')
0772 op = open(grubfile, 'w')
0773 cont = False
0774 for line in fp:
0775 line = line.strip()
0776 if len(line) == 0 or line[0] == '#':
0777 continue
0778 opt = line.split('=')[0].strip()
0779 if opt == tgtopt:
0780 cmdline = line.split('=', 1)[1].strip('\\')
0781 if line[-1] == '\\':
0782 cont = True
0783 elif cont:
0784 cmdline += line.strip('\\')
0785 if line[-1] != '\\':
0786 cont = False
0787 else:
0788 op.write('%s\n' % line)
0789 fp.close()
0790
0791 sp = '"'
0792 val = cmdline.strip()
0793 if val and (val[0] == '\'' or val[0] == '"'):
0794 sp = val[0]
0795 val = val.strip(sp)
0796 cmdline = val
0797
0798 if len(cmdline) > 0:
0799 cmdline += ' '
0800 cmdline += sysvals.kernelParams()
0801
0802 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
0803 op.close()
0804 res = call(sysvals.blexec)
0805 os.remove(grubfile)
0806 except Exception as e:
0807 pprint('Exception: %s' % str(e))
0808 res = -1
0809
0810 shutil.move(tempfile, grubfile)
0811 if res != 0:
0812 doError('update grub failed')
0813
0814
0815
0816
0817 def updateKernelParams(restore=False):
0818
0819 sysvals.getBootLoader()
0820 if sysvals.bootloader == 'grub':
0821 updateGrub(restore)
0822
0823
0824
0825
0826
0827
0828 def doError(msg, help=False):
0829 if help == True:
0830 printHelp()
0831 pprint('ERROR: %s\n' % msg)
0832 sysvals.outputResult({'error':msg})
0833 sys.exit()
0834
0835
0836
0837
0838 def printHelp():
0839 pprint('\n%s v%s\n'\
0840 'Usage: bootgraph <options> <command>\n'\
0841 '\n'\
0842 'Description:\n'\
0843 ' This tool reads in a dmesg log of linux kernel boot and\n'\
0844 ' creates an html representation of the boot timeline up to\n'\
0845 ' the start of the init process.\n'\
0846 '\n'\
0847 ' If no specific command is given the tool reads the current dmesg\n'\
0848 ' and/or ftrace log and creates a timeline\n'\
0849 '\n'\
0850 ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\
0851 ' HTML output: <hostname>_boot.html\n'\
0852 ' raw dmesg output: <hostname>_boot_dmesg.txt\n'\
0853 ' raw ftrace output: <hostname>_boot_ftrace.txt\n'\
0854 '\n'\
0855 'Options:\n'\
0856 ' -h Print this help text\n'\
0857 ' -v Print the current tool version\n'\
0858 ' -verbose Print extra information during execution and analysis\n'\
0859 ' -addlogs Add the dmesg log to the html output\n'\
0860 ' -result fn Export a results table to a text file for parsing.\n'\
0861 ' -o name Overrides the output subdirectory name when running a new test\n'\
0862 ' default: boot-{date}-{time}\n'\
0863 ' [advanced]\n'\
0864 ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\
0865 ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\
0866 ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\
0867 ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\
0868 ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\
0869 ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\
0870 ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\
0871 ' -cgfilter S Filter the callgraph output in the timeline\n'\
0872 ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\
0873 ' -bl name Use the following boot loader for kernel params (default: grub)\n'\
0874 ' -reboot Reboot the machine automatically and generate a new timeline\n'\
0875 ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\
0876 '\n'\
0877 'Other commands:\n'\
0878 ' -flistall Print all functions capable of being captured in ftrace\n'\
0879 ' -sysinfo Print out system info extracted from BIOS\n'\
0880 ' -which exec Print an executable path, should function even without PATH\n'\
0881 ' [redo]\n'\
0882 ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\
0883 ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\
0884 '' % (sysvals.title, sysvals.version))
0885 return True
0886
0887
0888
0889 if __name__ == '__main__':
0890
0891 cmd = ''
0892 testrun = True
0893 switchoff = ['disable', 'off', 'false', '0']
0894 simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
0895 cgskip = ''
0896 if '-f' in sys.argv:
0897 cgskip = sysvals.configFile('cgskip.txt')
0898 args = iter(sys.argv[1:])
0899 mdset = False
0900 for arg in args:
0901 if(arg == '-h'):
0902 printHelp()
0903 sys.exit()
0904 elif(arg == '-v'):
0905 pprint("Version %s" % sysvals.version)
0906 sys.exit()
0907 elif(arg == '-verbose'):
0908 sysvals.verbose = True
0909 elif(arg in simplecmds):
0910 cmd = arg[1:]
0911 elif(arg == '-fstat'):
0912 sysvals.useftrace = True
0913 elif(arg == '-callgraph' or arg == '-f'):
0914 sysvals.useftrace = True
0915 sysvals.usecallgraph = True
0916 elif(arg == '-cgdump'):
0917 sysvals.cgdump = True
0918 elif(arg == '-mincg'):
0919 sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
0920 elif(arg == '-cgfilter'):
0921 try:
0922 val = next(args)
0923 except:
0924 doError('No callgraph functions supplied', True)
0925 sysvals.setCallgraphFilter(val)
0926 elif(arg == '-cgskip'):
0927 try:
0928 val = next(args)
0929 except:
0930 doError('No file supplied', True)
0931 if val.lower() in switchoff:
0932 cgskip = ''
0933 else:
0934 cgskip = sysvals.configFile(val)
0935 if(not cgskip):
0936 doError('%s does not exist' % cgskip)
0937 elif(arg == '-bl'):
0938 try:
0939 val = next(args)
0940 except:
0941 doError('No boot loader name supplied', True)
0942 if val.lower() not in ['grub']:
0943 doError('Unknown boot loader: %s' % val, True)
0944 sysvals.bootloader = val.lower()
0945 elif(arg == '-timeprec'):
0946 sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
0947 elif(arg == '-maxdepth'):
0948 mdset = True
0949 sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
0950 elif(arg == '-func'):
0951 try:
0952 val = next(args)
0953 except:
0954 doError('No filter functions supplied', True)
0955 sysvals.useftrace = True
0956 sysvals.usecallgraph = True
0957 sysvals.rootCheck(True)
0958 sysvals.setGraphFilter(val)
0959 elif(arg == '-ftrace'):
0960 try:
0961 val = next(args)
0962 except:
0963 doError('No ftrace file supplied', True)
0964 if(os.path.exists(val) == False):
0965 doError('%s does not exist' % val)
0966 testrun = False
0967 sysvals.ftracefile = val
0968 elif(arg == '-addlogs'):
0969 sysvals.dmesglog = True
0970 elif(arg == '-expandcg'):
0971 sysvals.cgexp = True
0972 elif(arg == '-dmesg'):
0973 try:
0974 val = next(args)
0975 except:
0976 doError('No dmesg file supplied', True)
0977 if(os.path.exists(val) == False):
0978 doError('%s does not exist' % val)
0979 testrun = False
0980 sysvals.dmesgfile = val
0981 elif(arg == '-o'):
0982 try:
0983 val = next(args)
0984 except:
0985 doError('No subdirectory name supplied', True)
0986 sysvals.testdir = sysvals.setOutputFolder(val)
0987 elif(arg == '-result'):
0988 try:
0989 val = next(args)
0990 except:
0991 doError('No result file supplied', True)
0992 sysvals.result = val
0993 elif(arg == '-reboot'):
0994 sysvals.reboot = True
0995 elif(arg == '-manual'):
0996 sysvals.reboot = True
0997 sysvals.manual = True
0998
0999 elif(arg == '-cronjob'):
1000 sysvals.iscronjob = True
1001 elif(arg == '-which'):
1002 try:
1003 val = next(args)
1004 except:
1005 doError('No executable supplied', True)
1006 out = sysvals.getExec(val)
1007 if not out:
1008 print('%s not found' % val)
1009 sys.exit(1)
1010 print(out)
1011 sys.exit(0)
1012 else:
1013 doError('Invalid argument: '+arg, True)
1014
1015
1016 if(sysvals.iscronjob and (sysvals.reboot or \
1017 sysvals.dmesgfile or sysvals.ftracefile or cmd)):
1018 doError('-cronjob is meant for batch purposes only')
1019 if(sysvals.reboot and (sysvals.dmesgfile or sysvals.ftracefile)):
1020 doError('-reboot and -dmesg/-ftrace are incompatible')
1021 if cmd or sysvals.reboot or sysvals.iscronjob or testrun:
1022 sysvals.rootCheck(True)
1023 if (testrun and sysvals.useftrace) or cmd == 'flistall':
1024 if not sysvals.verifyFtrace():
1025 doError('Ftrace is not properly enabled')
1026
1027
1028 sysvals.cpuInfo()
1029 if cmd != '':
1030 if cmd == 'kpupdate':
1031 updateKernelParams()
1032 elif cmd == 'flistall':
1033 for f in sysvals.getBootFtraceFilterFunctions():
1034 print(f)
1035 elif cmd == 'checkbl':
1036 sysvals.getBootLoader()
1037 pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec))
1038 elif(cmd == 'sysinfo'):
1039 sysvals.printSystemInfo(True)
1040 sys.exit()
1041
1042
1043 if sysvals.reboot:
1044 if (sysvals.useftrace or sysvals.usecallgraph) and \
1045 not sysvals.checkFtraceKernelVersion():
1046 doError('Ftrace functionality requires kernel v4.10 or newer')
1047 if not sysvals.manual:
1048 updateKernelParams()
1049 updateCron()
1050 call('reboot')
1051 else:
1052 sysvals.manualRebootRequired()
1053 sys.exit()
1054
1055 if sysvals.usecallgraph and cgskip:
1056 sysvals.vprint('Using cgskip file: %s' % cgskip)
1057 sysvals.setCallgraphBlacklist(cgskip)
1058
1059
1060 if sysvals.iscronjob:
1061 updateCron(True)
1062 updateKernelParams(True)
1063 try:
1064 sysvals.fsetVal('0', 'tracing_on')
1065 except:
1066 pass
1067
1068
1069 if testrun:
1070 retrieveLogs()
1071 else:
1072 sysvals.setOutputFile()
1073
1074
1075 if sysvals.dmesgfile:
1076 if not mdset:
1077 sysvals.max_graph_depth = 0
1078 data = parseKernelLog()
1079 if(not data.valid):
1080 doError('No initcall data found in %s' % sysvals.dmesgfile)
1081 if sysvals.useftrace and sysvals.ftracefile:
1082 parseTraceLog(data)
1083 if sysvals.cgdump:
1084 data.debugPrint()
1085 sys.exit()
1086 else:
1087 doError('dmesg file required')
1088
1089 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
1090 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
1091 sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams)
1092 data.printDetails()
1093 createBootGraph(data)
1094
1095
1096 if testrun and os.path.isdir(sysvals.testdir) and \
1097 os.getuid() == 0 and 'SUDO_USER' in os.environ:
1098 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
1099 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
1100
1101 sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
1102 sysvals.stamp['lastinit'] = data.end * 1000
1103 sysvals.outputResult(sysvals.stamp)
