Loading...
Note: File does not exist in v3.1.
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)