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