#!/usr/bin/env python3# SPDX-License-Identifier: GPL-2.0-only## Tool for analyzing boot timing# Copyright (c) 2013, Intel Corporation.## This program is free software; you can redistribute it and/or modify it# under the terms and conditions of the GNU General Public License,# version 2, as published by the Free Software Foundation.## This program is distributed in the hope it will be useful, but WITHOUT# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or# FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for# more details.## Authors:#	 Todd Brandt <todd.e.brandt@linux.intel.com>## Description:#	 This tool is designed to assist kernel and OS developers in optimizing#	 their linux stack's boot time. It creates an html representation of#	 the kernel boot timeline up to the start of the init process.# # ----------------- LIBRARIES -------------------- import sysimport timeimport osimport stringimport reimport platformimport shutilfrom datetime import datetime, timedeltafrom subprocess import call, Popen, PIPEimport sleepgraph as aslib def pprint(msg):	print(msg)	sys.stdout.flush() # ----------------- CLASSES -------------------- # Class: SystemValues# Description:#	 A global, single-instance container used to#	 store system values and test parametersclass SystemValues(aslib.SystemValues):	title = 'BootGraph'	version = '2.2'	hostname = 'localhost'	testtime = ''	kernel = ''	dmesgfile = ''	ftracefile = ''	htmlfile = 'bootgraph.html'	testdir = ''	kparams = ''	result = ''	useftrace = False	usecallgraph = False	suspendmode = 'boot'	max_graph_depth = 2	graph_filter = 'do_one_initcall'	reboot = False	manual = False	iscronjob = False	timeformat = '%.6f'	bootloader = 'grub'	blexec = []	def __init__(self):		self.kernel, self.hostname = 'unknown', platform.node()		self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')		if os.path.exists('/proc/version'):			fp = open('/proc/version', 'r')			self.kernel = self.kernelVersion(fp.read().strip())			fp.close()		self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S')	def kernelVersion(self, msg):		m = re.match(r'^[Ll]inux *[Vv]ersion *(?P<v>\S*) .*', msg)		if m:			return m.group('v')		return 'unknown'	def checkFtraceKernelVersion(self):		m = re.match(r'^(?P<x>[0-9]*)\.(?P<y>[0-9]*)\.(?P<z>[0-9]*).*', self.kernel)		if m:			val = tuple(map(int, m.groups()))			if val >= (4, 10, 0):				return True		return False	def kernelParams(self):		cmdline = 'initcall_debug log_buf_len=32M'		if self.useftrace:			if self.cpucount > 0:				bs = min(self.memtotal // 2, 2*1024*1024) // self.cpucount			else:				bs = 131072			cmdline += ' trace_buf_size=%dK trace_clock=global '\			'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\			'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\			'nofuncgraph-overhead,context-info,graph-time '\			'ftrace=function_graph '\			'ftrace_graph_max_depth=%d '\			'ftrace_graph_filter=%s' % \				(bs, self.max_graph_depth, self.graph_filter)		return cmdline	def setGraphFilter(self, val):		master = self.getBootFtraceFilterFunctions()		fs = ''		for i in val.split(','):			func = i.strip()			if func == '':				doError('badly formatted filter function string')			if '[' in func or ']' in func:				doError('loadable module functions not allowed - "%s"' % func)			if ' ' in func:				doError('spaces found in filter functions - "%s"' % func)			if func not in master:				doError('function "%s" not available for ftrace' % func)			if not fs:				fs = func			else:				fs += ','+func		if not fs:			doError('badly formatted filter function string')		self.graph_filter = fs	def getBootFtraceFilterFunctions(self):		self.rootCheck(True)		fp = open(self.tpath+'available_filter_functions')		fulllist = fp.read().split('\n')		fp.close()		list = []		for i in fulllist:			if not i or ' ' in i or '[' in i or ']' in i:				continue			list.append(i)		return list	def myCronJob(self, line):		if '@reboot' not in line:			return False		if 'bootgraph' in line or 'analyze_boot.py' in line or '-cronjob' in line:			return True		return False	def cronjobCmdString(self):		cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])		args = iter(sys.argv[1:])		for arg in args:			if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:				continue			elif arg in ['-o', '-dmesg', '-ftrace', '-func']:				next(args)				continue			elif arg == '-result':				cmdline += ' %s "%s"' % (arg, os.path.abspath(next(args)))				continue			elif arg == '-cgskip':				file = self.configFile(next(args))				cmdline += ' %s "%s"' % (arg, os.path.abspath(file))				continue			cmdline += ' '+arg		if self.graph_filter != 'do_one_initcall':			cmdline += ' -func "%s"' % self.graph_filter		cmdline += ' -o "%s"' % os.path.abspath(self.testdir)		return cmdline	def manualRebootRequired(self):		cmdline = self.kernelParams()		pprint('To generate a new timeline manually, follow these steps:\n\n'\		'1. Add the CMDLINE string to your kernel command line.\n'\		'2. Reboot the system.\n'\		'3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\		'CMDLINE="%s"' % cmdline)		sys.exit()	def blGrub(self):		blcmd = ''		for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:			if blcmd:				break			blcmd = self.getExec(cmd)		if not blcmd:			doError('[GRUB] missing update command')		if not os.path.exists('/etc/default/grub'):			doError('[GRUB] missing /etc/default/grub')		if 'grub2' in blcmd:			cfg = '/boot/grub2/grub.cfg'		else:			cfg = '/boot/grub/grub.cfg'		if not os.path.exists(cfg):			doError('[GRUB] missing %s' % cfg)		if 'update-grub' in blcmd:			self.blexec = [blcmd]		else:			self.blexec = [blcmd, '-o', cfg]	def getBootLoader(self):		if self.bootloader == 'grub':			self.blGrub()		else:			doError('unknown boot loader: %s' % self.bootloader)	def writeDatafileHeader(self, filename):		self.kparams = open('/proc/cmdline', 'r').read().strip()		fp = open(filename, 'w')		fp.write(self.teststamp+'\n')		fp.write(self.sysstamp+'\n')		fp.write('# command | %s\n' % self.cmdline)		fp.write('# kparams | %s\n' % self.kparams)		fp.close() sysvals = SystemValues() # Class: Data# Description:#	 The primary container for test data.class Data(aslib.Data):	dmesg = {}  # root data structure	start = 0.0 # test start	end = 0.0   # test end	dmesgtext = []   # dmesg text file in memory	testnumber = 0	idstr = ''	html_device_id = 0	valid = False	tUserMode = 0.0	boottime = ''	phases = ['kernel', 'user']	do_one_initcall = False	def __init__(self, num):		self.testnumber = num		self.idstr = 'a'		self.dmesgtext = []		self.dmesg = {			'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,				'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'},			'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,				'order': 1, 'color': '#fff'}		}	def deviceTopology(self):		return ''	def newAction(self, phase, name, pid, start, end, ret, ulen):		# new device callback for a specific phase		self.html_device_id += 1		devid = '%s%d' % (self.idstr, self.html_device_id)		list = self.dmesg[phase]['list']		length = -1.0		if(start >= 0 and end >= 0):			length = end - start		i = 2		origname = name		while(name in list):			name = '%s[%d]' % (origname, i)			i += 1		list[name] = {'name': name, 'start': start, 'end': end,			'pid': pid, 'length': length, 'row': 0, 'id': devid,			'ret': ret, 'ulen': ulen }		return name	def deviceMatch(self, pid, cg):		if cg.end - cg.start == 0:			return ''		for p in data.phases:			list = self.dmesg[p]['list']			for devname in list:				dev = list[devname]				if pid != dev['pid']:					continue				if cg.name == 'do_one_initcall':					if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):						dev['ftrace'] = cg						self.do_one_initcall = True						return devname				else:					if(cg.start > dev['start'] and cg.end < dev['end']):						if 'ftraces' not in dev:							dev['ftraces'] = []						dev['ftraces'].append(cg)						return devname		return ''	def printDetails(self):		sysvals.vprint('Timeline Details:')		sysvals.vprint('          Host: %s' % sysvals.hostname)		sysvals.vprint('        Kernel: %s' % sysvals.kernel)		sysvals.vprint('     Test time: %s' % sysvals.testtime)		sysvals.vprint('     Boot time: %s' % self.boottime)		for phase in self.phases:			dc = len(self.dmesg[phase]['list'])			sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,				self.dmesg[phase]['start']*1000,				self.dmesg[phase]['end']*1000, dc)) # ----------------- FUNCTIONS -------------------- # Function: parseKernelLog# Description:#	 parse a kernel log for boot datadef parseKernelLog():	sysvals.vprint('Analyzing the dmesg data (%s)...' % \		os.path.basename(sysvals.dmesgfile))	phase = 'kernel'	data = Data(0)	data.dmesg['kernel']['start'] = data.start = ktime = 0.0	sysvals.stamp = {		'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),		'host': sysvals.hostname,		'mode': 'boot', 'kernel': ''} 	tp = aslib.TestProps()	devtemp = dict()	if(sysvals.dmesgfile):		lf = open(sysvals.dmesgfile, 'rb')	else:		lf = Popen('dmesg', stdout=PIPE).stdout	for line in lf:		line = aslib.ascii(line).replace('\r\n', '')		# grab the stamp and sysinfo		if re.match(tp.stampfmt, line):			tp.stamp = line			continue		elif re.match(tp.sysinfofmt, line):			tp.sysinfo = line			continue		elif re.match(tp.cmdlinefmt, line):			tp.cmdline = line			continue		elif re.match(tp.kparamsfmt, line):			tp.kparams = line			continue		idx = line.find('[')		if idx > 1:			line = line[idx:]		m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)		if(not m):			continue		ktime = float(m.group('ktime'))		if(ktime > 120):			break		msg = m.group('msg')		data.dmesgtext.append(line)		if(ktime == 0.0 and re.match(r'^Linux version .*', msg)):			if(not sysvals.stamp['kernel']):				sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)			continue		m = re.match(r'.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg)		if(m):			bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S')			bt = bt - timedelta(seconds=int(ktime))			data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')			sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')			continue		m = re.match(r'^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)		if(m):			func = m.group('f')			pid = int(m.group('p'))			devtemp[func] = (ktime, pid)			continue		m = re.match(r'^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)		if(m):			data.valid = True			data.end = ktime			f, r, t = m.group('f', 'r', 't')			if(f in devtemp):				start, pid = devtemp[f]				data.newAction(phase, f, pid, start, ktime, int(r), int(t))				del devtemp[f]			continue		if(re.match(r'^Freeing unused kernel .*', msg)):			data.tUserMode = ktime			data.dmesg['kernel']['end'] = ktime			data.dmesg['user']['start'] = ktime			phase = 'user' 	if tp.stamp:		sysvals.stamp = 0		tp.parseStamp(data, sysvals)	data.dmesg['user']['end'] = data.end	lf.close()	return data # Function: parseTraceLog# Description:#	 Check if trace is available and copy to a temp filedef parseTraceLog(data):	sysvals.vprint('Analyzing the ftrace data (%s)...' % \		os.path.basename(sysvals.ftracefile))	# if available, calculate cgfilter allowable ranges	cgfilter = []	if len(sysvals.cgfilter) > 0:		for p in data.phases:			list = data.dmesg[p]['list']			for i in sysvals.cgfilter:				if i in list:					cgfilter.append([list[i]['start']-0.0001,						list[i]['end']+0.0001])	# parse the trace log	ftemp = dict()	tp = aslib.TestProps()	tp.setTracerType('function_graph')	tf = open(sysvals.ftracefile, 'r')	for line in tf:		if line[0] == '#':			continue		m = re.match(tp.ftrace_line_fmt, line.strip())		if(not m):			continue		m_time, m_proc, m_pid, m_msg, m_dur = \			m.group('time', 'proc', 'pid', 'msg', 'dur')		t = float(m_time)		if len(cgfilter) > 0:			allow = False			for r in cgfilter:				if t >= r[0] and t < r[1]:					allow = True					break			if not allow:				continue		if t > data.end:			break		if(m_time and m_pid and m_msg):			t = aslib.FTraceLine(m_time, m_msg, m_dur)			pid = int(m_pid)		else:			continue		if t.fevent or t.fkprobe:			continue		key = (m_proc, pid)		if(key not in ftemp):			ftemp[key] = []			ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))		cg = ftemp[key][-1]		res = cg.addLine(t)		if(res != 0):			ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))		if(res == -1):			ftemp[key][-1].addLine(t) 	tf.close() 	# add the callgraph data to the device hierarchy	for key in ftemp:		proc, pid = key		for cg in ftemp[key]:			if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):				continue			if(not cg.postProcess()):				pprint('Sanity check failed for %s-%d' % (proc, pid))				continue			# match cg data to devices			devname = data.deviceMatch(pid, cg)			if not devname:				kind = 'Orphan'				if cg.partial:					kind = 'Partial'				sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\					(kind, cg.name, proc, pid, cg.start, cg.end))			elif len(cg.list) > 1000000:				pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\					(devname, len(cg.list))) # Function: retrieveLogs# Description:#	 Create copies of dmesg and/or ftrace for later processingdef retrieveLogs():	# check ftrace is configured first	if sysvals.useftrace:		tracer = sysvals.fgetVal('current_tracer').strip()		if tracer != 'function_graph':			doError('ftrace not configured for a boot callgraph')	# create the folder and get dmesg	sysvals.systemInfo(aslib.dmidecode(sysvals.mempath))	sysvals.initTestOutput('boot')	sysvals.writeDatafileHeader(sysvals.dmesgfile)	call('dmesg >> '+sysvals.dmesgfile, shell=True)	if not sysvals.useftrace:		return	# get ftrace	sysvals.writeDatafileHeader(sysvals.ftracefile)	call('cat '+sysvals.tpath+'trace >> '+sysvals.ftracefile, shell=True) # Function: colorForName# Description:#	 Generate a repeatable color from a list for a given namedef colorForName(name):	list = [		('c1', '#ec9999'),		('c2', '#ffc1a6'),		('c3', '#fff0a6'),		('c4', '#adf199'),		('c5', '#9fadea'),		('c6', '#a699c1'),		('c7', '#ad99b4'),		('c8', '#eaffea'),		('c9', '#dcecfb'),		('c10', '#ffffea')	]	i = 0	total = 0	count = len(list)	while i < len(name):		total += ord(name[i])		i += 1	return list[total % count] def cgOverview(cg, minlen):	stats = dict()

Lines 1–500 of 1103. Load more