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