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