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