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