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