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