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