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)