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