pm-graph: AnalyzeBoot v2.2

Add the dmesg log to the html output. It will be viewable by

clicking a button in the timeline.

.TP

\fB-result \fIfile\fR

Export a results table to a text file for parsing.

.TP

\fB-o \fIname\fR

Overrides the output subdirectory name when running a new test.

Use {date}, {time}, {hostname} for current values.

e.g. boot-{hostname}-{date}-{time}

.SS "advanced"

.TP

\fB-f\fR

Use ftrace to add function detail (default: disabled)

.TP

\fB-callgraph\fR

\fB-f or -callgraph\fR

Use ftrace to create initcall callgraphs (default: disabled). If -func

is not used there will be one callgraph per initcall. This can produce

very large outputs, i.e. 10MB - 100MB.

.TP

\fB-fstat\fR

Use ftrace to add function detail (default: disabled)

.TP

\fB-maxdepth \fIlevel\fR

limit the callgraph trace depth to \fIlevel\fR (default: 2). This is

the best way to limit the output size when using -callgraph.

argument can be a single function name or a comma delimited list.

(default: none)

.TP

\fB-cgskip \fIfile\fR

Reduce callgraph output in the timeline by skipping over uninteresting

functions in the trace, e.g. printk or console_unlock. The functions listed

in this file will show up as empty leaves in the callgraph with only the start/end

times displayed.

(default: none)

.TP

\fB-timeprec \fIn\fR

Number of significant digits in timestamps (0:S, 3:ms, [6:us])

.TP

import shutil

from datetime import datetime, timedelta

from subprocess import call, Popen, PIPE

import analyze_suspend as aslib

import sleepgraph as aslib

# ----------------- CLASSES --------------------

#	 store system values and test parameters

class SystemValues(aslib.SystemValues):

	title = 'BootGraph'

	version = '2.1'

	version = '2.2'

	hostname = 'localhost'

	testtime = ''

	kernel = ''

	dmesgfile = ''

	ftracefile = ''

	htmlfile = 'bootgraph.html'

	outfile = ''

	testdir = ''

	testdirprefix = 'boot'

	embedded = False

	testlog = False

	dmesglog = False

	ftracelog = False

	kparams = ''

	result = ''

	useftrace = False

	usecallgraph = False

	usedevsrc = True

	suspendmode = 'boot'

	max_graph_depth = 2

	graph_filter = 'do_one_initcall'

	bootloader = 'grub'

	blexec = []

	def __init__(self):

		if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):

			self.embedded = True

			self.dmesglog = True

			self.outfile = os.environ['LOG_FILE']

			self.htmlfile = os.environ['LOG_FILE']

		self.hostname = platform.node()

		self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')

		if os.path.exists('/proc/version'):

		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']:

			if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:

				continue

			elif arg in ['-o', '-dmesg', '-ftrace', '-func']:

				args.next()

				continue

			elif arg == '-result':

				cmdline += ' %s "%s"' % (arg, os.path.abspath(args.next()))

				continue

			elif arg == '-cgskip':

				file = self.configFile(args.next())

				cmdline += ' %s "%s"' % (arg, os.path.abspath(file))

				continue

			cmdline += ' '+arg

		if self.graph_filter != 'do_one_initcall':

			cmdline += ' -func "%s"' % self.graph_filter

		print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n'

		print 'CMDLINE="%s"' % cmdline

		sys.exit()

	def getExec(self, cmd):

		dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',

			'/usr/local/sbin', '/usr/local/bin']

		for path in dirlist:

			cmdfull = os.path.join(path, cmd)

			if os.path.exists(cmdfull):

				return cmdfull

		return ''

	def blGrub(self):

		blcmd = ''

		for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:

			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()

		return name

	def deviceMatch(self, pid, cg):

		if cg.end - cg.start == 0:

			return True

			return ''

		for p in data.phases:

			list = self.dmesg[p]['list']

			for devname in list:

					if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):

						dev['ftrace'] = cg

						self.do_one_initcall = True

						return 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 True

		return False

						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 --------------------

# Description:

#	 parse a kernel log for boot data

def 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

		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:]

# Description:

#	 Check if trace is available and copy to a temp file

def 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()

			continue

		m_time, m_proc, m_pid, m_msg, m_dur = \

			m.group('time', 'proc', 'pid', 'msg', 'dur')

		if float(m_time) > data.end:

		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)

		key = (m_proc, pid)

		if(key not in ftemp):

			ftemp[key] = []

			ftemp[key].append(aslib.FTraceCallGraph(pid))

			ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))

		cg = ftemp[key][-1]

		if(cg.addLine(t)):

			ftemp[key].append(aslib.FTraceCallGraph(pid))

		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:

			if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):

				continue

			if(not cg.postProcess()):

				print('Sanity check failed for %s-%d' % (proc, pid))

				continue

			# match cg data to devices

			if not data.deviceMatch(pid, cg):

				print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid, cg.start, cg.end)

			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:

				print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\

					(devname, len(cg.list))

# Function: retrieveLogs

# Description:

	devtl = aslib.Timeline(100, 20)

	# write the test title and general info header

	devtl.createHeader(sysvals)

	devtl.createHeader(sysvals, sysvals.stamp)

	# Generate the header for this timeline

	t0 = data.start

			data.dmesg[phase]['color'], phase+'_mode', phase[0])

	devtl.html += '</div>\n'

	if(sysvals.outfile == sysvals.htmlfile):

		hf = open(sysvals.htmlfile, 'a')

	else:

	hf = open(sysvals.htmlfile, 'w')

	# add the css if this is not an embedded run

	# add the css

	extra = '\

		.c1 {background:rgba(209,0,0,0.4);}\n\

		.c2 {background:rgba(255,102,34,0.4);}\n\

		.fstat td {text-align:left;width:35px;}\n\

		.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\

		.srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'

	if(not sysvals.embedded):

	aslib.addCSS(hf, sysvals, 1, False, extra)

	# write the device timeline

	if(sysvals.usecallgraph):

		aslib.addCallgraphs(sysvals, hf, data)

	# add the test log as a hidden div

	if sysvals.testlog and sysvals.logmsg:

		hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')

	# add the dmesg log as a hidden div

	if sysvals.dmesglog:

		hf.write('<div id="dmesglog" style="display:none;">\n')

			hf.write(line)

		hf.write('</div>\n')

	if(not sysvals.embedded):

	# write the footer and close

	aslib.addScriptCode(hf, [data])

	hf.write('</body>\n</html>\n')

	else:

		# embedded out will be loaded in a page, skip the js

		hf.write('<div id=bounds style=display:none>%f,%f</div>' % \

			(data.start*1000, data.end*1000))

	hf.close()

	return True

	if help == True:

		printHelp()

	print 'ERROR: %s\n' % msg

	sysvals.outputResult({'error':msg})

	sys.exit()

# Function: printHelp

	print('Options:')

	print('  -h            Print this help text')

	print('  -v            Print the current tool version')

	print('  -verbose      Print extra information during execution and analysis')

	print('  -addlogs      Add the dmesg log to the html output')

	print('  -result fn    Export a results table to a text file for parsing.')

	print('  -o name       Overrides the output subdirectory name when running a new test')

	print('                default: boot-{date}-{time}')

	print(' [advanced]')

	print('  -f            Use ftrace to add function detail (default: disabled)')

	print('  -callgraph    Add callgraph detail, can be very large (default: disabled)')

	print('  -fstat        Use ftrace to add function detail and statistics (default: disabled)')

	print('  -f/-callgraph Add callgraph detail, can be very large (default: disabled)')

	print('  -maxdepth N   limit the callgraph data to N call levels (default: 2)')

	print('  -mincg ms     Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')

	print('  -timeprec N   Number of significant digits in timestamps (0:S, 3:ms, [6:us])')

	print('  -expandcg     pre-expand the callgraph data in the html output (default: disabled)')

	print('  -func list    Limit ftrace to comma-delimited list of functions (default: do_one_initcall)')

	print('  -cgfilter S   Filter the callgraph output in the timeline')

	print('  -cgskip file  Callgraph functions to skip, off to disable (default: cgskip.txt)')

	print('  -bl name      Use the following boot loader for kernel params (default: grub)')

	print('  -reboot       Reboot the machine automatically and generate a new timeline')

	print('  -manual       Show the steps to generate a new timeline manually (used with -reboot)')

	# loop through the command line arguments

	cmd = ''

	testrun = True

	switchoff = ['disable', 'off', 'false', '0']

	simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']

	cgskip = ''

	if '-f' in sys.argv:

		cgskip = sysvals.configFile('cgskip.txt')

	args = iter(sys.argv[1:])

	mdset = False

	for arg in args:

		if(arg == '-h'):

			printHelp()

		elif(arg == '-v'):

			print("Version %s" % sysvals.version)

			sys.exit()

		elif(arg == '-verbose'):

			sysvals.verbose = True

		elif(arg in simplecmds):

			cmd = arg[1:]

		elif(arg == '-f'):

		elif(arg == '-fstat'):

			sysvals.useftrace = True

		elif(arg == '-callgraph'):

		elif(arg == '-callgraph' or arg == '-f'):

			sysvals.useftrace = True

			sysvals.usecallgraph = True

		elif(arg == '-cgdump'):

			sysvals.cgdump = True

		elif(arg == '-mincg'):

			sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)

		elif(arg == '-cgfilter'):

				val = args.next()

			except:

				doError('No callgraph functions supplied', True)

			sysvals.setDeviceFilter(val)

			sysvals.setCallgraphFilter(val)

		elif(arg == '-cgskip'):

			try:

				val = args.next()

			except:

				doError('No file supplied', True)

			if val.lower() in switchoff:

				cgskip = ''

			else:

				cgskip = sysvals.configFile(val)

				if(not cgskip):

					doError('%s does not exist' % cgskip)

		elif(arg == '-bl'):

			try:

				val = args.next()

		elif(arg == '-timeprec'):

			sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))

		elif(arg == '-maxdepth'):

			mdset = True

			sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)

		elif(arg == '-func'):

			try:

				doError('No dmesg file supplied', True)

			if(os.path.exists(val) == False):

				doError('%s does not exist' % val)

			if(sysvals.htmlfile == val or sysvals.outfile == val):

				doError('Output filename collision')

			testrun = False

			sysvals.dmesgfile = val

		elif(arg == '-o'):

			except:

				doError('No subdirectory name supplied', True)

			sysvals.testdir = sysvals.setOutputFolder(val)

		elif(arg == '-result'):

			try:

				val = args.next()

			except:

				doError('No result file supplied', True)

			sysvals.result = val

		elif(arg == '-reboot'):

			sysvals.reboot = True

		elif(arg == '-manual'):

			sysvals.getBootLoader()

			print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)

		elif(cmd == 'sysinfo'):

			sysvals.printSystemInfo()

			sysvals.printSystemInfo(True)

		sys.exit()

	# reboot: update grub, setup a cronjob, and reboot

			sysvals.manualRebootRequired()

		sys.exit()

	if sysvals.usecallgraph and cgskip:

		sysvals.vprint('Using cgskip file: %s' % cgskip)

		sysvals.setCallgraphBlacklist(cgskip)

	# cronjob: remove the cronjob, grub changes, and disable ftrace

	if sysvals.iscronjob:

		updateCron(True)

	# process the log data

	if sysvals.dmesgfile:

		if not mdset:

			sysvals.max_graph_depth = 0

		data = parseKernelLog()

		if(not data.valid):

			doError('No initcall data found in %s' % sysvals.dmesgfile)

		if sysvals.useftrace and sysvals.ftracefile:

			parseTraceLog(data)

		if sysvals.cgdump:

			data.debugPrint()

			sys.exit()

	else:

		doError('dmesg file required')

	print('          Host: %s' % sysvals.hostname)

	print('     Test time: %s' % sysvals.testtime)

	print('     Boot time: %s' % data.boottime)

	print('Kernel Version: %s' % sysvals.kernel)

	print('  Kernel start: %.3f' % (data.start * 1000))

	print('Usermode start: %.3f' % (data.tUserMode * 1000))

	print('Last Init Call: %.3f' % (data.end * 1000))

	# handle embedded output logs

	if(sysvals.outfile and sysvals.embedded):

		fp = open(sysvals.outfile, 'w')

		fp.write('pass %s initstart %.3f end %.3f boot %s\n' %

			(data.valid, data.tUserMode*1000, data.end*1000, data.boottime))

		fp.close()

	sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)

	sysvals.vprint('Command:\n    %s' % sysvals.cmdline)

	sysvals.vprint('Kernel parameters:\n    %s' % sysvals.kparams)

	data.printDetails()

	createBootGraph(data)

	# if running as root, change output dir owner to sudo_user

		os.getuid() == 0 and 'SUDO_USER' in os.environ:

		cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'

		call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)

	sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000

	sysvals.stamp['lastinit'] = data.end * 1000

	sysvals.outputResult(sysvals.stamp)