diff options
author | Todd E Brandt <todd.e.brandt@linux.intel.com> | 2017-04-07 14:05:36 -0400 |
---|---|---|
committer | Rafael J. Wysocki <rafael.j.wysocki@intel.com> | 2017-04-19 17:26:41 -0400 |
commit | c4980cee82efb4fef8afac3675cb25fba3baca34 (patch) | |
tree | 03b43d6d3a04a373b1d8195049579250b603c9b9 | |
parent | bc167c7de8886f08b3d8266b176eefaa9f22cd80 (diff) |
tools: power: pm-graph: AnalyzeBoot v2.0
First release into the kernel tools source
- pulls in analyze_suspend.py as as library, same html formatting
- supplants scripts/bootgraph.pl, outputs HTML instead of SVG
- enables automatic reboot and collection for easy timeline capture
- enables ftrace callgraph collection from early boot
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
-rwxr-xr-x | tools/power/pm-graph/analyze_boot.py | 824 |
1 files changed, 824 insertions, 0 deletions
diff --git a/tools/power/pm-graph/analyze_boot.py b/tools/power/pm-graph/analyze_boot.py new file mode 100755 index 000000000000..3e1dcbbf1adc --- /dev/null +++ b/tools/power/pm-graph/analyze_boot.py | |||
@@ -0,0 +1,824 @@ | |||
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.0 | ||
46 | hostname = 'localhost' | ||
47 | testtime = '' | ||
48 | kernel = '' | ||
49 | dmesgfile = '' | ||
50 | ftracefile = '' | ||
51 | htmlfile = 'bootgraph.html' | ||
52 | outfile = '' | ||
53 | phoronix = False | ||
54 | addlogs = False | ||
55 | useftrace = False | ||
56 | usedevsrc = True | ||
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 | def __init__(self): | ||
65 | if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): | ||
66 | self.phoronix = True | ||
67 | self.addlogs = True | ||
68 | self.outfile = os.environ['LOG_FILE'] | ||
69 | self.htmlfile = os.environ['LOG_FILE'] | ||
70 | self.hostname = platform.node() | ||
71 | self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S') | ||
72 | if os.path.exists('/proc/version'): | ||
73 | fp = open('/proc/version', 'r') | ||
74 | val = fp.read().strip() | ||
75 | fp.close() | ||
76 | self.kernel = self.kernelVersion(val) | ||
77 | else: | ||
78 | self.kernel = 'unknown' | ||
79 | def kernelVersion(self, msg): | ||
80 | return msg.split()[2] | ||
81 | def kernelParams(self): | ||
82 | cmdline = 'initcall_debug log_buf_len=32M' | ||
83 | if self.useftrace: | ||
84 | cmdline += ' trace_buf_size=128M trace_clock=global '\ | ||
85 | 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\ | ||
86 | 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\ | ||
87 | 'nofuncgraph-overhead,context-info,graph-time '\ | ||
88 | 'ftrace=function_graph '\ | ||
89 | 'ftrace_graph_max_depth=%d '\ | ||
90 | 'ftrace_graph_filter=%s' % \ | ||
91 | (self.max_graph_depth, self.graph_filter) | ||
92 | return cmdline | ||
93 | def setGraphFilter(self, val): | ||
94 | fp = open(self.tpath+'available_filter_functions') | ||
95 | master = fp.read().split('\n') | ||
96 | fp.close() | ||
97 | for i in val.split(','): | ||
98 | func = i.strip() | ||
99 | if func not in master: | ||
100 | doError('function "%s" not available for ftrace' % func) | ||
101 | self.graph_filter = val | ||
102 | def cronjobCmdString(self): | ||
103 | cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0]) | ||
104 | args = iter(sys.argv[1:]) | ||
105 | for arg in args: | ||
106 | if arg in ['-h', '-v', '-cronjob', '-reboot']: | ||
107 | continue | ||
108 | elif arg in ['-o', '-dmesg', '-ftrace', '-filter']: | ||
109 | args.next() | ||
110 | continue | ||
111 | cmdline += ' '+arg | ||
112 | if self.graph_filter != 'do_one_initcall': | ||
113 | cmdline += ' -filter "%s"' % self.graph_filter | ||
114 | cmdline += ' -o "%s"' % os.path.abspath(self.htmlfile) | ||
115 | return cmdline | ||
116 | def manualRebootRequired(self): | ||
117 | cmdline = self.kernelParams() | ||
118 | print 'To generate a new timeline manually, follow these steps:\n' | ||
119 | print '1. Add the CMDLINE string to your kernel command line.' | ||
120 | print '2. Reboot the system.' | ||
121 | print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n' | ||
122 | print 'CMDLINE="%s"' % cmdline | ||
123 | sys.exit() | ||
124 | |||
125 | sysvals = SystemValues() | ||
126 | |||
127 | # Class: Data | ||
128 | # Description: | ||
129 | # The primary container for test data. | ||
130 | class Data(aslib.Data): | ||
131 | dmesg = {} # root data structure | ||
132 | start = 0.0 # test start | ||
133 | end = 0.0 # test end | ||
134 | dmesgtext = [] # dmesg text file in memory | ||
135 | testnumber = 0 | ||
136 | idstr = '' | ||
137 | html_device_id = 0 | ||
138 | valid = False | ||
139 | initstart = 0.0 | ||
140 | boottime = '' | ||
141 | phases = ['boot'] | ||
142 | do_one_initcall = False | ||
143 | def __init__(self, num): | ||
144 | self.testnumber = num | ||
145 | self.idstr = 'a' | ||
146 | self.dmesgtext = [] | ||
147 | self.dmesg = { | ||
148 | 'boot': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0, 'color': '#dddddd'} | ||
149 | } | ||
150 | def deviceTopology(self): | ||
151 | return '' | ||
152 | def newAction(self, phase, name, start, end, ret, ulen): | ||
153 | # new device callback for a specific phase | ||
154 | self.html_device_id += 1 | ||
155 | devid = '%s%d' % (self.idstr, self.html_device_id) | ||
156 | list = self.dmesg[phase]['list'] | ||
157 | length = -1.0 | ||
158 | if(start >= 0 and end >= 0): | ||
159 | length = end - start | ||
160 | i = 2 | ||
161 | origname = name | ||
162 | while(name in list): | ||
163 | name = '%s[%d]' % (origname, i) | ||
164 | i += 1 | ||
165 | list[name] = {'name': name, 'start': start, 'end': end, | ||
166 | 'pid': 0, 'length': length, 'row': 0, 'id': devid, | ||
167 | 'ret': ret, 'ulen': ulen } | ||
168 | return name | ||
169 | def deviceMatch(self, cg): | ||
170 | if cg.end - cg.start == 0: | ||
171 | return True | ||
172 | list = self.dmesg['boot']['list'] | ||
173 | for devname in list: | ||
174 | dev = list[devname] | ||
175 | if cg.name == 'do_one_initcall': | ||
176 | if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0): | ||
177 | dev['ftrace'] = cg | ||
178 | self.do_one_initcall = True | ||
179 | return True | ||
180 | else: | ||
181 | if(cg.start > dev['start'] and cg.end < dev['end']): | ||
182 | if 'ftraces' not in dev: | ||
183 | dev['ftraces'] = [] | ||
184 | dev['ftraces'].append(cg) | ||
185 | return True | ||
186 | return False | ||
187 | |||
188 | # ----------------- FUNCTIONS -------------------- | ||
189 | |||
190 | # Function: loadKernelLog | ||
191 | # Description: | ||
192 | # Load a raw kernel log from dmesg | ||
193 | def loadKernelLog(): | ||
194 | data = Data(0) | ||
195 | data.dmesg['boot']['start'] = data.start = ktime = 0.0 | ||
196 | sysvals.stamp = { | ||
197 | 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'), | ||
198 | 'host': sysvals.hostname, | ||
199 | 'mode': 'boot', 'kernel': ''} | ||
200 | |||
201 | devtemp = dict() | ||
202 | if(sysvals.dmesgfile): | ||
203 | lf = open(sysvals.dmesgfile, 'r') | ||
204 | else: | ||
205 | lf = Popen('dmesg', stdout=PIPE).stdout | ||
206 | for line in lf: | ||
207 | line = line.replace('\r\n', '') | ||
208 | idx = line.find('[') | ||
209 | if idx > 1: | ||
210 | line = line[idx:] | ||
211 | m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) | ||
212 | if(not m): | ||
213 | continue | ||
214 | ktime = float(m.group('ktime')) | ||
215 | if(ktime > 120): | ||
216 | break | ||
217 | msg = m.group('msg') | ||
218 | data.end = data.initstart = ktime | ||
219 | data.dmesgtext.append(line) | ||
220 | if(ktime == 0.0 and re.match('^Linux version .*', msg)): | ||
221 | if(not sysvals.stamp['kernel']): | ||
222 | sysvals.stamp['kernel'] = sysvals.kernelVersion(msg) | ||
223 | continue | ||
224 | m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg) | ||
225 | if(m): | ||
226 | bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S') | ||
227 | bt = bt - timedelta(seconds=int(ktime)) | ||
228 | data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S') | ||
229 | sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p') | ||
230 | continue | ||
231 | m = re.match('^calling *(?P<f>.*)\+.*', msg) | ||
232 | if(m): | ||
233 | devtemp[m.group('f')] = ktime | ||
234 | continue | ||
235 | m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg) | ||
236 | if(m): | ||
237 | data.valid = True | ||
238 | f, r, t = m.group('f', 'r', 't') | ||
239 | if(f in devtemp): | ||
240 | data.newAction('boot', f, devtemp[f], ktime, int(r), int(t)) | ||
241 | data.end = ktime | ||
242 | del devtemp[f] | ||
243 | continue | ||
244 | if(re.match('^Freeing unused kernel memory.*', msg)): | ||
245 | break | ||
246 | |||
247 | data.dmesg['boot']['end'] = data.end | ||
248 | lf.close() | ||
249 | return data | ||
250 | |||
251 | # Function: loadTraceLog | ||
252 | # Description: | ||
253 | # Check if trace is available and copy to a temp file | ||
254 | def loadTraceLog(data): | ||
255 | # load the data to a temp file if none given | ||
256 | if not sysvals.ftracefile: | ||
257 | lib = aslib.sysvals | ||
258 | aslib.rootCheck(True) | ||
259 | if not lib.verifyFtrace(): | ||
260 | doError('ftrace not available') | ||
261 | if lib.fgetVal('current_tracer').strip() != 'function_graph': | ||
262 | doError('ftrace not configured for a boot callgraph') | ||
263 | sysvals.ftracefile = '/tmp/boot_ftrace.%s.txt' % os.getpid() | ||
264 | call('cat '+lib.tpath+'trace > '+sysvals.ftracefile, shell=True) | ||
265 | if not sysvals.ftracefile: | ||
266 | doError('No trace data available') | ||
267 | |||
268 | # parse the trace log | ||
269 | ftemp = dict() | ||
270 | tp = aslib.TestProps() | ||
271 | tp.setTracerType('function_graph') | ||
272 | tf = open(sysvals.ftracefile, 'r') | ||
273 | for line in tf: | ||
274 | if line[0] == '#': | ||
275 | continue | ||
276 | m = re.match(tp.ftrace_line_fmt, line.strip()) | ||
277 | if(not m): | ||
278 | continue | ||
279 | m_time, m_proc, m_pid, m_msg, m_dur = \ | ||
280 | m.group('time', 'proc', 'pid', 'msg', 'dur') | ||
281 | if float(m_time) > data.end: | ||
282 | break | ||
283 | if(m_time and m_pid and m_msg): | ||
284 | t = aslib.FTraceLine(m_time, m_msg, m_dur) | ||
285 | pid = int(m_pid) | ||
286 | else: | ||
287 | continue | ||
288 | if t.fevent or t.fkprobe: | ||
289 | continue | ||
290 | key = (m_proc, pid) | ||
291 | if(key not in ftemp): | ||
292 | ftemp[key] = [] | ||
293 | ftemp[key].append(aslib.FTraceCallGraph(pid)) | ||
294 | cg = ftemp[key][-1] | ||
295 | if(cg.addLine(t)): | ||
296 | ftemp[key].append(aslib.FTraceCallGraph(pid)) | ||
297 | tf.close() | ||
298 | |||
299 | # add the callgraph data to the device hierarchy | ||
300 | for key in ftemp: | ||
301 | proc, pid = key | ||
302 | for cg in ftemp[key]: | ||
303 | if len(cg.list) < 1 or cg.invalid: | ||
304 | continue | ||
305 | if(not cg.postProcess()): | ||
306 | print('Sanity check failed for %s-%d' % (proc, pid)) | ||
307 | continue | ||
308 | # match cg data to devices | ||
309 | if not data.deviceMatch(cg): | ||
310 | print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid, cg.start, cg.end) | ||
311 | |||
312 | # Function: colorForName | ||
313 | # Description: | ||
314 | # Generate a repeatable color from a list for a given name | ||
315 | def colorForName(name): | ||
316 | list = [ | ||
317 | ('c1', '#ec9999'), | ||
318 | ('c2', '#ffc1a6'), | ||
319 | ('c3', '#fff0a6'), | ||
320 | ('c4', '#adf199'), | ||
321 | ('c5', '#9fadea'), | ||
322 | ('c6', '#a699c1'), | ||
323 | ('c7', '#ad99b4'), | ||
324 | ('c8', '#eaffea'), | ||
325 | ('c9', '#dcecfb'), | ||
326 | ('c10', '#ffffea') | ||
327 | ] | ||
328 | i = 0 | ||
329 | total = 0 | ||
330 | count = len(list) | ||
331 | while i < len(name): | ||
332 | total += ord(name[i]) | ||
333 | i += 1 | ||
334 | return list[total % count] | ||
335 | |||
336 | def cgOverview(cg, minlen): | ||
337 | stats = dict() | ||
338 | large = [] | ||
339 | for l in cg.list: | ||
340 | if l.fcall and l.depth == 1: | ||
341 | if l.length >= minlen: | ||
342 | large.append(l) | ||
343 | if l.name not in stats: | ||
344 | stats[l.name] = [0, 0.0] | ||
345 | stats[l.name][0] += (l.length * 1000.0) | ||
346 | stats[l.name][1] += 1 | ||
347 | return (large, stats) | ||
348 | |||
349 | # Function: createBootGraph | ||
350 | # Description: | ||
351 | # Create the output html file from the resident test data | ||
352 | # Arguments: | ||
353 | # testruns: array of Data objects from parseKernelLog or parseTraceLog | ||
354 | # Output: | ||
355 | # True if the html file was created, false if it failed | ||
356 | def createBootGraph(data, embedded): | ||
357 | # html function templates | ||
358 | 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' | ||
359 | html_timetotal = '<table class="time1">\n<tr>'\ | ||
360 | '<td class="blue">Time from Kernel Boot to start of User Mode: <b>{0} ms</b></td>'\ | ||
361 | '</tr>\n</table>\n' | ||
362 | |||
363 | # device timeline | ||
364 | devtl = aslib.Timeline(100, 20) | ||
365 | |||
366 | # write the test title and general info header | ||
367 | devtl.createHeader(sysvals, 'noftrace') | ||
368 | |||
369 | # Generate the header for this timeline | ||
370 | t0 = data.start | ||
371 | tMax = data.end | ||
372 | tTotal = tMax - t0 | ||
373 | if(tTotal == 0): | ||
374 | print('ERROR: No timeline data') | ||
375 | return False | ||
376 | boot_time = '%.0f'%(tTotal*1000) | ||
377 | devtl.html += html_timetotal.format(boot_time) | ||
378 | |||
379 | # determine the maximum number of rows we need to draw | ||
380 | phase = 'boot' | ||
381 | list = data.dmesg[phase]['list'] | ||
382 | devlist = [] | ||
383 | for devname in list: | ||
384 | d = aslib.DevItem(0, phase, list[devname]) | ||
385 | devlist.append(d) | ||
386 | devtl.getPhaseRows(devlist) | ||
387 | devtl.calcTotalRows() | ||
388 | |||
389 | # draw the timeline background | ||
390 | devtl.createZoomBox() | ||
391 | boot = data.dmesg[phase] | ||
392 | length = boot['end']-boot['start'] | ||
393 | left = '%.3f' % (((boot['start']-t0)*100.0)/tTotal) | ||
394 | width = '%.3f' % ((length*100.0)/tTotal) | ||
395 | devtl.html += devtl.html_tblock.format(phase, left, width, devtl.scaleH) | ||
396 | devtl.html += devtl.html_phase.format('0', '100', \ | ||
397 | '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ | ||
398 | 'white', '') | ||
399 | |||
400 | # draw the device timeline | ||
401 | num = 0 | ||
402 | devstats = dict() | ||
403 | for devname in sorted(list): | ||
404 | cls, color = colorForName(devname) | ||
405 | dev = list[devname] | ||
406 | info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0, | ||
407 | dev['ulen']/1000.0, dev['ret']) | ||
408 | devstats[dev['id']] = {'info':info} | ||
409 | dev['color'] = color | ||
410 | height = devtl.phaseRowHeight(0, phase, dev['row']) | ||
411 | top = '%.6f' % ((dev['row']*height) + devtl.scaleH) | ||
412 | left = '%.6f' % (((dev['start']-t0)*100)/tTotal) | ||
413 | width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal) | ||
414 | length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) | ||
415 | devtl.html += devtl.html_device.format(dev['id'], | ||
416 | devname+length+'kernel_mode', left, top, '%.3f'%height, | ||
417 | width, devname, ' '+cls, '') | ||
418 | rowtop = devtl.phaseRowTop(0, phase, dev['row']) | ||
419 | height = '%.6f' % (devtl.rowH / 2) | ||
420 | top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2)) | ||
421 | if data.do_one_initcall: | ||
422 | if('ftrace' not in dev): | ||
423 | continue | ||
424 | cg = dev['ftrace'] | ||
425 | large, stats = cgOverview(cg, 0.001) | ||
426 | devstats[dev['id']]['fstat'] = stats | ||
427 | for l in large: | ||
428 | left = '%f' % (((l.time-t0)*100)/tTotal) | ||
429 | width = '%f' % (l.length*100/tTotal) | ||
430 | title = '%s (%0.3fms)' % (l.name, l.length * 1000.0) | ||
431 | devtl.html += html_srccall.format(l.name, left, | ||
432 | top, height, width, title, 'x%d'%num) | ||
433 | num += 1 | ||
434 | continue | ||
435 | if('ftraces' not in dev): | ||
436 | continue | ||
437 | for cg in dev['ftraces']: | ||
438 | left = '%f' % (((cg.start-t0)*100)/tTotal) | ||
439 | width = '%f' % ((cg.end-cg.start)*100/tTotal) | ||
440 | cglen = (cg.end - cg.start) * 1000.0 | ||
441 | title = '%s (%0.3fms)' % (cg.name, cglen) | ||
442 | cg.id = 'x%d' % num | ||
443 | devtl.html += html_srccall.format(cg.name, left, | ||
444 | top, height, width, title, dev['id']+cg.id) | ||
445 | num += 1 | ||
446 | |||
447 | # draw the time scale, try to make the number of labels readable | ||
448 | devtl.createTimeScale(t0, tMax, tTotal, phase) | ||
449 | devtl.html += '</div>\n' | ||
450 | |||
451 | # timeline is finished | ||
452 | devtl.html += '</div>\n</div>\n' | ||
453 | |||
454 | if(sysvals.outfile == sysvals.htmlfile): | ||
455 | hf = open(sysvals.htmlfile, 'a') | ||
456 | else: | ||
457 | hf = open(sysvals.htmlfile, 'w') | ||
458 | |||
459 | # add the css if this is not an embedded run | ||
460 | extra = '\ | ||
461 | .c1 {background:rgba(209,0,0,0.4);}\n\ | ||
462 | .c2 {background:rgba(255,102,34,0.4);}\n\ | ||
463 | .c3 {background:rgba(255,218,33,0.4);}\n\ | ||
464 | .c4 {background:rgba(51,221,0,0.4);}\n\ | ||
465 | .c5 {background:rgba(17,51,204,0.4);}\n\ | ||
466 | .c6 {background:rgba(34,0,102,0.4);}\n\ | ||
467 | .c7 {background:rgba(51,0,68,0.4);}\n\ | ||
468 | .c8 {background:rgba(204,255,204,0.4);}\n\ | ||
469 | .c9 {background:rgba(169,208,245,0.4);}\n\ | ||
470 | .c10 {background:rgba(255,255,204,0.4);}\n\ | ||
471 | .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\ | ||
472 | table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\ | ||
473 | .fstat th {width:55px;}\n\ | ||
474 | .fstat td {text-align:left;width:35px;}\n\ | ||
475 | .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\ | ||
476 | .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n' | ||
477 | if(not embedded): | ||
478 | aslib.addCSS(hf, sysvals, 1, False, extra) | ||
479 | |||
480 | # write the device timeline | ||
481 | hf.write(devtl.html) | ||
482 | |||
483 | # add boot specific html | ||
484 | statinfo = 'var devstats = {\n' | ||
485 | for n in sorted(devstats): | ||
486 | statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info']) | ||
487 | if 'fstat' in devstats[n]: | ||
488 | funcs = devstats[n]['fstat'] | ||
489 | for f in sorted(funcs, key=funcs.get, reverse=True): | ||
490 | if funcs[f][0] < 0.01 and len(funcs) > 10: | ||
491 | break | ||
492 | statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1]) | ||
493 | statinfo += '\t],\n' | ||
494 | statinfo += '};\n' | ||
495 | html = \ | ||
496 | '<div id="devicedetailtitle"></div>\n'\ | ||
497 | '<div id="devicedetail" style="display:none;">\n'\ | ||
498 | '<div id="devicedetail0">\n'\ | ||
499 | '<div id="kernel_mode" class="phaselet" style="left:0%;width:100%;background:#DDDDDD"></div>\n'\ | ||
500 | '</div>\n</div>\n'\ | ||
501 | '<script type="text/javascript">\n'+statinfo+\ | ||
502 | '</script>\n' | ||
503 | hf.write(html) | ||
504 | |||
505 | # add the callgraph html | ||
506 | if(sysvals.usecallgraph): | ||
507 | aslib.addCallgraphs(sysvals, hf, data) | ||
508 | |||
509 | # add the dmesg log as a hidden div | ||
510 | if sysvals.addlogs: | ||
511 | hf.write('<div id="dmesglog" style="display:none;">\n') | ||
512 | for line in data.dmesgtext: | ||
513 | line = line.replace('<', '<').replace('>', '>') | ||
514 | hf.write(line) | ||
515 | hf.write('</div>\n') | ||
516 | |||
517 | if(not embedded): | ||
518 | # write the footer and close | ||
519 | aslib.addScriptCode(hf, [data]) | ||
520 | hf.write('</body>\n</html>\n') | ||
521 | else: | ||
522 | # embedded out will be loaded in a page, skip the js | ||
523 | hf.write('<div id=bounds style=display:none>%f,%f</div>' % \ | ||
524 | (data.start*1000, data.initstart*1000)) | ||
525 | hf.close() | ||
526 | return True | ||
527 | |||
528 | # Function: updateCron | ||
529 | # Description: | ||
530 | # (restore=False) Set the tool to run automatically on reboot | ||
531 | # (restore=True) Restore the original crontab | ||
532 | def updateCron(restore=False): | ||
533 | if not restore: | ||
534 | sysvals.rootUser(True) | ||
535 | crondir = '/var/spool/cron/crontabs/' | ||
536 | cronfile = crondir+'root' | ||
537 | backfile = crondir+'root-analyze_boot-backup' | ||
538 | if not os.path.exists(crondir): | ||
539 | doError('%s not found' % crondir) | ||
540 | out = Popen(['which', 'crontab'], stdout=PIPE).stdout.read() | ||
541 | if not out: | ||
542 | doError('crontab not found') | ||
543 | # on restore: move the backup cron back into place | ||
544 | if restore: | ||
545 | if os.path.exists(backfile): | ||
546 | shutil.move(backfile, cronfile) | ||
547 | return | ||
548 | # backup current cron and install new one with reboot | ||
549 | if os.path.exists(cronfile): | ||
550 | shutil.move(cronfile, backfile) | ||
551 | else: | ||
552 | fp = open(backfile, 'w') | ||
553 | fp.close() | ||
554 | res = -1 | ||
555 | try: | ||
556 | fp = open(backfile, 'r') | ||
557 | op = open(cronfile, 'w') | ||
558 | for line in fp: | ||
559 | if '@reboot' not in line: | ||
560 | op.write(line) | ||
561 | continue | ||
562 | fp.close() | ||
563 | op.write('@reboot python %s\n' % sysvals.cronjobCmdString()) | ||
564 | op.close() | ||
565 | res = call('crontab %s' % cronfile, shell=True) | ||
566 | except Exception, e: | ||
567 | print 'Exception: %s' % str(e) | ||
568 | shutil.move(backfile, cronfile) | ||
569 | res = -1 | ||
570 | if res != 0: | ||
571 | doError('crontab failed') | ||
572 | |||
573 | # Function: updateGrub | ||
574 | # Description: | ||
575 | # update grub.cfg for all kernels with our parameters | ||
576 | def updateGrub(restore=False): | ||
577 | # call update-grub on restore | ||
578 | if restore: | ||
579 | try: | ||
580 | call(['update-grub'], stderr=PIPE, stdout=PIPE, | ||
581 | env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'}) | ||
582 | except Exception, e: | ||
583 | print 'Exception: %s\n' % str(e) | ||
584 | return | ||
585 | # verify we can do this | ||
586 | sysvals.rootUser(True) | ||
587 | grubfile = '/etc/default/grub' | ||
588 | if not os.path.exists(grubfile): | ||
589 | print 'ERROR: Unable to set the kernel parameters via grub.\n' | ||
590 | sysvals.manualRebootRequired() | ||
591 | out = Popen(['which', 'update-grub'], stdout=PIPE).stdout.read() | ||
592 | if not out: | ||
593 | print 'ERROR: Unable to set the kernel parameters via grub.\n' | ||
594 | sysvals.manualRebootRequired() | ||
595 | |||
596 | # extract the option and create a grub config without it | ||
597 | tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT' | ||
598 | cmdline = '' | ||
599 | tempfile = '/etc/default/grub.analyze_boot' | ||
600 | shutil.move(grubfile, tempfile) | ||
601 | res = -1 | ||
602 | try: | ||
603 | fp = open(tempfile, 'r') | ||
604 | op = open(grubfile, 'w') | ||
605 | cont = False | ||
606 | for line in fp: | ||
607 | line = line.strip() | ||
608 | if len(line) == 0 or line[0] == '#': | ||
609 | continue | ||
610 | opt = line.split('=')[0].strip() | ||
611 | if opt == tgtopt: | ||
612 | cmdline = line.split('=', 1)[1].strip('\\') | ||
613 | if line[-1] == '\\': | ||
614 | cont = True | ||
615 | elif cont: | ||
616 | cmdline += line.strip('\\') | ||
617 | if line[-1] != '\\': | ||
618 | cont = False | ||
619 | else: | ||
620 | op.write('%s\n' % line) | ||
621 | fp.close() | ||
622 | # if the target option value is in quotes, strip them | ||
623 | sp = '"' | ||
624 | val = cmdline.strip() | ||
625 | if val[0] == '\'' or val[0] == '"': | ||
626 | sp = val[0] | ||
627 | val = val.strip(sp) | ||
628 | cmdline = val | ||
629 | # append our cmd line options | ||
630 | if len(cmdline) > 0: | ||
631 | cmdline += ' ' | ||
632 | cmdline += sysvals.kernelParams() | ||
633 | # write out the updated target option | ||
634 | op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp)) | ||
635 | op.close() | ||
636 | res = call('update-grub') | ||
637 | os.remove(grubfile) | ||
638 | except Exception, e: | ||
639 | print 'Exception: %s' % str(e) | ||
640 | res = -1 | ||
641 | # cleanup | ||
642 | shutil.move(tempfile, grubfile) | ||
643 | if res != 0: | ||
644 | doError('update-grub failed') | ||
645 | |||
646 | # Function: doError | ||
647 | # Description: | ||
648 | # generic error function for catastrphic failures | ||
649 | # Arguments: | ||
650 | # msg: the error message to print | ||
651 | # help: True if printHelp should be called after, False otherwise | ||
652 | def doError(msg, help=False): | ||
653 | if help == True: | ||
654 | printHelp() | ||
655 | print 'ERROR: %s\n' % msg | ||
656 | sys.exit() | ||
657 | |||
658 | # Function: printHelp | ||
659 | # Description: | ||
660 | # print out the help text | ||
661 | def printHelp(): | ||
662 | print('') | ||
663 | print('%s v%.1f' % (sysvals.title, sysvals.version)) | ||
664 | print('Usage: bootgraph <options> <command>') | ||
665 | print('') | ||
666 | print('Description:') | ||
667 | print(' This tool reads in a dmesg log of linux kernel boot and') | ||
668 | print(' creates an html representation of the boot timeline up to') | ||
669 | print(' the start of the init process.') | ||
670 | print('') | ||
671 | print(' If no specific command is given the tool reads the current dmesg') | ||
672 | print(' and/or ftrace log and outputs bootgraph.html') | ||
673 | print('') | ||
674 | print('Options:') | ||
675 | print(' -h Print this help text') | ||
676 | print(' -v Print the current tool version') | ||
677 | print(' -addlogs Add the dmesg log to the html output') | ||
678 | print(' -o file Html timeline name (default: bootgraph.html)') | ||
679 | print(' [advanced]') | ||
680 | print(' -f Use ftrace to add function detail (default: disabled)') | ||
681 | print(' -callgraph Add callgraph detail, can be very large (default: disabled)') | ||
682 | print(' -maxdepth N limit the callgraph data to N call levels (default: 2)') | ||
683 | print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') | ||
684 | print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])') | ||
685 | print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') | ||
686 | print(' -filter list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)') | ||
687 | print(' [commands]') | ||
688 | print(' -reboot Reboot the machine automatically and generate a new timeline') | ||
689 | print(' -manual Show the requirements to generate a new timeline manually') | ||
690 | print(' -dmesg file Load a stored dmesg file (used with -ftrace)') | ||
691 | print(' -ftrace file Load a stored ftrace file (used with -dmesg)') | ||
692 | print(' -flistall Print all functions capable of being captured in ftrace') | ||
693 | print('') | ||
694 | return True | ||
695 | |||
696 | # ----------------- MAIN -------------------- | ||
697 | # exec start (skipped if script is loaded as library) | ||
698 | if __name__ == '__main__': | ||
699 | # loop through the command line arguments | ||
700 | cmd = '' | ||
701 | simplecmds = ['-updategrub', '-flistall'] | ||
702 | args = iter(sys.argv[1:]) | ||
703 | for arg in args: | ||
704 | if(arg == '-h'): | ||
705 | printHelp() | ||
706 | sys.exit() | ||
707 | elif(arg == '-v'): | ||
708 | print("Version %.1f" % sysvals.version) | ||
709 | sys.exit() | ||
710 | elif(arg in simplecmds): | ||
711 | cmd = arg[1:] | ||
712 | elif(arg == '-f'): | ||
713 | sysvals.useftrace = True | ||
714 | elif(arg == '-callgraph'): | ||
715 | sysvals.useftrace = True | ||
716 | sysvals.usecallgraph = True | ||
717 | elif(arg == '-mincg'): | ||
718 | sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0) | ||
719 | elif(arg == '-timeprec'): | ||
720 | sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6)) | ||
721 | elif(arg == '-maxdepth'): | ||
722 | sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000) | ||
723 | elif(arg == '-filter'): | ||
724 | try: | ||
725 | val = args.next() | ||
726 | except: | ||
727 | doError('No filter functions supplied', True) | ||
728 | aslib.rootCheck(True) | ||
729 | sysvals.setGraphFilter(val) | ||
730 | elif(arg == '-ftrace'): | ||
731 | try: | ||
732 | val = args.next() | ||
733 | except: | ||
734 | doError('No ftrace file supplied', True) | ||
735 | if(os.path.exists(val) == False): | ||
736 | doError('%s does not exist' % val) | ||
737 | sysvals.ftracefile = val | ||
738 | elif(arg == '-addlogs'): | ||
739 | sysvals.addlogs = True | ||
740 | elif(arg == '-expandcg'): | ||
741 | sysvals.cgexp = True | ||
742 | elif(arg == '-dmesg'): | ||
743 | try: | ||
744 | val = args.next() | ||
745 | except: | ||
746 | doError('No dmesg file supplied', True) | ||
747 | if(os.path.exists(val) == False): | ||
748 | doError('%s does not exist' % val) | ||
749 | if(sysvals.htmlfile == val or sysvals.outfile == val): | ||
750 | doError('Output filename collision') | ||
751 | sysvals.dmesgfile = val | ||
752 | elif(arg == '-o'): | ||
753 | try: | ||
754 | val = args.next() | ||
755 | except: | ||
756 | doError('No HTML filename supplied', True) | ||
757 | if(sysvals.dmesgfile == val or sysvals.ftracefile == val): | ||
758 | doError('Output filename collision') | ||
759 | sysvals.htmlfile = val | ||
760 | elif(arg == '-reboot'): | ||
761 | if sysvals.iscronjob: | ||
762 | doError('-reboot and -cronjob are incompatible') | ||
763 | sysvals.reboot = True | ||
764 | elif(arg == '-manual'): | ||
765 | sysvals.reboot = True | ||
766 | sysvals.manual = True | ||
767 | # remaining options are only for cron job use | ||
768 | elif(arg == '-cronjob'): | ||
769 | sysvals.iscronjob = True | ||
770 | if sysvals.reboot: | ||
771 | doError('-reboot and -cronjob are incompatible') | ||
772 | else: | ||
773 | doError('Invalid argument: '+arg, True) | ||
774 | |||
775 | if cmd != '': | ||
776 | if cmd == 'updategrub': | ||
777 | updateGrub() | ||
778 | elif cmd == 'flistall': | ||
779 | sysvals.getFtraceFilterFunctions(False) | ||
780 | sys.exit() | ||
781 | |||
782 | # update grub, setup a cronjob, and reboot | ||
783 | if sysvals.reboot: | ||
784 | if not sysvals.manual: | ||
785 | updateGrub() | ||
786 | updateCron() | ||
787 | call('reboot') | ||
788 | else: | ||
789 | sysvals.manualRebootRequired() | ||
790 | sys.exit() | ||
791 | |||
792 | # disable the cronjob | ||
793 | if sysvals.iscronjob: | ||
794 | updateCron(True) | ||
795 | updateGrub(True) | ||
796 | |||
797 | data = loadKernelLog() | ||
798 | if sysvals.useftrace: | ||
799 | loadTraceLog(data) | ||
800 | if sysvals.iscronjob: | ||
801 | try: | ||
802 | sysvals.fsetVal('0', 'tracing_on') | ||
803 | except: | ||
804 | pass | ||
805 | |||
806 | if(sysvals.outfile and sysvals.phoronix): | ||
807 | fp = open(sysvals.outfile, 'w') | ||
808 | fp.write('pass %s initstart %.3f end %.3f boot %s\n' % | ||
809 | (data.valid, data.initstart*1000, data.end*1000, data.boottime)) | ||
810 | fp.close() | ||
811 | if(not data.valid): | ||
812 | if sysvals.dmesgfile: | ||
813 | doError('No initcall data found in %s' % sysvals.dmesgfile) | ||
814 | else: | ||
815 | doError('No initcall data found, is initcall_debug enabled?') | ||
816 | |||
817 | print(' Host: %s' % sysvals.hostname) | ||
818 | print(' Test time: %s' % sysvals.testtime) | ||
819 | print(' Boot time: %s' % data.boottime) | ||
820 | print('Kernel Version: %s' % sysvals.kernel) | ||
821 | print(' Kernel start: %.3f' % (data.start * 1000)) | ||
822 | print(' init start: %.3f' % (data.initstart * 1000)) | ||
823 | |||
824 | createBootGraph(data, sysvals.phoronix) | ||