#!/usr/bin/python## Tool for analyzing suspend/resume 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.## You should have received a copy of the GNU General Public License along with# this program; if not, write to the Free Software Foundation, Inc.,# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.## 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 suspend/resume time. Using a kernel image built#	 with a few extra options enabled, the tool will execute a suspend and#	 will capture dmesg and ftrace data until resume is complete. This data#	 is transformed into a device timeline and a callgraph to give a quick#	 and detailed view of which devices and callbacks are taking the most#	 time in suspend/resume. The output is a single html file which can be#	 viewed in firefox or chrome.##	 The following kernel build options are required:#		 CONFIG_PM_DEBUG=y#		 CONFIG_PM_SLEEP_DEBUG=y#		 CONFIG_FTRACE=y#		 CONFIG_FUNCTION_TRACER=y#		 CONFIG_FUNCTION_GRAPH_TRACER=y##	 The following additional kernel parameters are required:#		 (e.g. in file /etc/default/grub)#		 GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."# import sysimport timeimport osimport stringimport reimport arrayimport platformimport datetimeimport struct # -- classes -- class SystemValues:	testdir = "."	tpath = "/sys/kernel/debug/tracing/"	mempath = "/dev/mem"	powerfile = "/sys/power/state"	suspendmode = "mem"	prefix = "test"	teststamp = ""	dmesgfile = ""	ftracefile = ""	htmlfile = ""	rtcwake = False	def setOutputFile(self):		if((self.htmlfile == "") and (self.dmesgfile != "")):			m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile)			if(m):				self.htmlfile = m.group("name")+".html"		if((self.htmlfile == "") and (self.ftracefile != "")):			m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile)			if(m):				self.htmlfile = m.group("name")+".html"		if(self.htmlfile == ""):			self.htmlfile = "output.html"	def initTestOutput(self):		hostname = platform.node()		if(hostname != ""):			self.prefix = hostname		v = os.popen("cat /proc/version").read().strip()		kver = string.split(v)[2]		self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip()		self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver		self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt"		self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt"		self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html"		os.mkdir(self.testdir) class Data:	altdevname = dict()	usedmesg = False	useftrace = False	notestrun = False	verbose = False	phases = []	dmesg = {} # root data structure	start = 0.0	end = 0.0	stamp = {'time': "", 'host': "", 'mode': ""}	id = 0	tSuspended = 0.0	fwValid = False	fwSuspend = 0	fwResume = 0	def initialize(self):		self.dmesg = { # dmesg log data			'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "#CCFFCC", 'order': 0},			  'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "green", 'order': 1},			  'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "#00FFFF", 'order': 2},				'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "blue", 'order': 3},				 'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "red", 'order': 4},			   'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "orange", 'order': 5},			   'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "yellow", 'order': 6},			 'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0,								'row': 0, 'color': "#FFFFCC", 'order': 7}		}		self.phases = self.sortedPhases()	def normalizeTime(self):		tSus = tRes = self.tSuspended		if self.fwValid:			tSus -= -self.fwSuspend / 1000000000.0			tRes -= self.fwResume / 1000000000.0		self.tSuspended = 0.0		self.start -= tSus		self.end -= tRes		for phase in self.phases:			zero = tRes			if "suspend" in phase:				zero = tSus			p = self.dmesg[phase]			p['start'] -= zero			p['end'] -= zero			list = p['list']			for name in list:				d = list[name]				d['start'] -= zero				d['end'] -= zero				if('ftrace' in d):					cg = d['ftrace']					cg.start -= zero					cg.end -= zero					for line in cg.list:						line.time -= zero		if self.fwValid:			fws = -self.fwSuspend / 1000000000.0			fwr = self.fwResume / 1000000000.0			list = dict()			self.id += 1			devid = "dc%d" % self.id			list["firmware-suspend"] = \				{'start': fws, 'end': 0, 'pid': 0, 'par': "",				'length': -fws, 'row': 0, 'id': devid };			self.id += 1			devid = "dc%d" % self.id			list["firmware-resume"] = \				{'start': 0, 'end': fwr, 'pid': 0, 'par': "",				'length': fwr, 'row': 0, 'id': devid };			self.dmesg['BIOS'] = \				{'list': list, 'start': fws, 'end': fwr,				'row': 0, 'color': "purple", 'order': 4}			self.dmesg['resume_cpu']['order'] += 1			self.dmesg['resume_noirq']['order'] += 1			self.dmesg['resume_early']['order'] += 1			self.dmesg['resume_general']['order'] += 1			self.phases = self.sortedPhases()	def vprint(self, msg):		if(self.verbose):			print(msg)	def dmesgSortVal(self, phase):		return self.dmesg[phase]['order']	def sortedPhases(self):		return sorted(self.dmesg, key=self.dmesgSortVal)	def sortedDevices(self, phase):		list = self.dmesg[phase]['list']		slist = []		tmp = dict()		for devname in list:			dev = list[devname]			tmp[dev['start']] = devname		for t in sorted(tmp):			slist.append(tmp[t])		return slist	def fixupInitcalls(self, phase, end):		# if any calls never returned, clip them at system resume end		phaselist = self.dmesg[phase]['list']		for devname in phaselist:			dev = phaselist[devname]			if(dev['end'] < 0):				dev['end'] = end				self.vprint("%s (%s): callback didn't return" % (devname, phase))	def fixupInitcallsThatDidntReturn(self):		# if any calls never returned, clip them at system resume end		for phase in self.phases:			self.fixupInitcalls(phase, self.dmesg['resume_general']['end'])			if(phase == "resume_general"):				break	def newAction(self, phase, name, pid, parent, start, end):		self.id += 1		devid = "dc%d" % self.id		list = self.dmesg[phase]['list']		length = -1.0		if(start >= 0 and end >= 0):			length = end - start		list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,					  'length': length, 'row': 0, 'id': devid }	def deviceIDs(self, devlist, phase):		idlist = []		for p in self.phases:			if(p[0] != phase[0]):				continue			list = data.dmesg[p]['list']			for devname in list:				if devname in devlist:					idlist.append(list[devname]['id'])		return idlist	def deviceParentID(self, devname, phase):		pdev = ""		pdevid = ""		for p in self.phases:			if(p[0] != phase[0]):				continue			list = data.dmesg[p]['list']			if devname in list:				pdev = list[devname]['par']		for p in self.phases:			if(p[0] != phase[0]):				continue			list = data.dmesg[p]['list']			if pdev in list:				return list[pdev]['id']		return pdev	def deviceChildrenIDs(self, devname, phase):		devlist = []		for p in self.phases:			if(p[0] != phase[0]):				continue			list = data.dmesg[p]['list']			for child in list:				if(list[child]['par'] == devname):					devlist.append(child)		return self.deviceIDs(devlist, phase) class FTraceLine:	time = 0.0	length = 0.0	fcall = False	freturn = False	fevent = False	depth = 0	name = ""	def __init__(self, t, m, d):		self.time = float(t)		# check to see if this is a trace event		em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m)		if(em):			self.name = em.group("msg")			self.fevent = True			return		# convert the duration to seconds		if(d):			self.length = float(d)/1000000		# the indentation determines the depth		match = re.match(r"^(?P<d> *)(?P<o>.*)$", m)		if(not match):			return		self.depth = self.getDepth(match.group('d'))		m = match.group('o')		# function return		if(m[0] == '}'):			self.freturn = True			if(len(m) > 1):				# includes comment with function name				match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m)				if(match):					self.name = match.group('n')		# function call		else:			self.fcall = True			# function call with children			if(m[-1] == '{'):				match = re.match(r"^(?P<n>.*) *\(.*", m)				if(match):					self.name = match.group('n')			# function call with no children (leaf)			elif(m[-1] == ';'):				self.freturn = True				match = re.match(r"^(?P<n>.*) *\(.*", m)				if(match):					self.name = match.group('n')			# something else (possibly a trace marker)			else:				self.name = m	def getDepth(self, str):		return len(str)/2 class FTraceCallGraph:	start = -1.0	end = -1.0	list = []	invalid = False	depth = 0	def __init__(self):		self.start = -1.0		self.end = -1.0		self.list = []		self.depth = 0	def setDepth(self, line):		if(line.fcall and not line.freturn):			line.depth = self.depth			self.depth += 1		elif(line.freturn and not line.fcall):			self.depth -= 1			line.depth = self.depth		else:			line.depth = self.depth	def addLine(self, line, match):		if(not self.invalid):			self.setDepth(line)		if(line.depth == 0 and line.freturn):			self.end = line.time			self.list.append(line)			return True		if(self.invalid):			return False		if(len(self.list) >= 1000000 or self.depth < 0):		   first = self.list[0]		   self.list = []		   self.list.append(first)		   self.invalid = True		   id = "task %s cpu %s" % (match.group("pid"), match.group("cpu"))		   window = "(%f - %f)" % (self.start, line.time)		   data.vprint("Too much data for "+id+" "+window+", ignoring this callback")		   return False		self.list.append(line)		if(self.start < 0):			self.start = line.time		return False	def sanityCheck(self):		stack = dict()		cnt = 0		for l in self.list:			if(l.fcall and not l.freturn):				stack[l.depth] = l				cnt += 1			elif(l.freturn and not l.fcall):				if(not stack[l.depth]):					return False				stack[l.depth].length = l.length				stack[l.depth] = 0				l.length = 0				cnt -= 1		if(cnt == 0):			return True		return False	def debugPrint(self, filename):		if(filename == "stdout"):			print("[%f - %f]") % (self.start, self.end)			for l in self.list:				if(l.freturn and l.fcall):					print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))				elif(l.freturn):					print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))				else:					print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))			print(" ")		else:			fp = open(filename, 'w')			print(filename)			for l in self.list:				if(l.freturn and l.fcall):					fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))				elif(l.freturn):					fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))				else:					fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))			fp.close() class Timeline:	html = {}	scaleH = 0.0 # height of the timescale row as a percent of the timeline height	rowH = 0.0 # height of each row in percent of the timeline height	row_height_pixels = 30	maxrows = 0	height = 0	def __init__(self):		self.html = {			'timeline': "",			'legend': "",			'scale': ""		}	def setRows(self, rows):		self.maxrows = int(rows)		self.scaleH = 100.0/float(self.maxrows)		self.height = self.maxrows*self.row_height_pixels		r = float(self.maxrows - 1)		if(r < 1.0):			r = 1.0		self.rowH = (100.0 - self.scaleH)/r # -- global objects -- sysvals = SystemValues()data = Data() # -- functions -- # Function: initFtrace# Description:#	 Configure ftrace to capture a function trace during suspend/resumedef initFtrace():	global sysvals 	print("INITIALIZING FTRACE...")	# turn trace off	os.system("echo 0 > "+sysvals.tpath+"tracing_on")	# set the trace clock to global	os.system("echo global > "+sysvals.tpath+"trace_clock")	# set trace buffer to a huge value	os.system("echo nop > "+sysvals.tpath+"current_tracer")	os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb")	# clear the trace buffer	os.system("echo \"\" > "+sysvals.tpath+"trace")	# set trace type	os.system("echo function_graph > "+sysvals.tpath+"current_tracer")	os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter")	# set trace format options	os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options")	os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options")	# focus only on device suspend and resume	os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function") # Function: verifyFtrace# Description:#	 Check that ftrace is working on the systemdef verifyFtrace():	global sysvals	files = ["available_filter_functions", "buffer_size_kb",			 "current_tracer", "set_ftrace_filter",			 "trace", "trace_marker"]	for f in files:		if(os.path.exists(sysvals.tpath+f) == False):			return False	return True def parseStamp(line):	global data, sysvals	stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\				"(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\				" (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$"	m = re.match(stampfmt, line)	if(m):		dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")),			int(m.group("d")), int(m.group("H")), int(m.group("M")),			int(m.group("S")))		data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p")		data.stamp['host'] = m.group("host")		data.stamp['mode'] = m.group("mode")		data.stamp['kernel'] = m.group("kernel")		sysvals.suspendmode = data.stamp['mode'] # Function: analyzeTraceLog# Description:#	 Analyse an ftrace log output file generated from this app during#	 the execution phase. Create an "ftrace" structure in memory for#	 subsequent formatting in the html output filedef analyzeTraceLog():	global sysvals, data 	# the ftrace data is tied to the dmesg data	if(not data.usedmesg):		return 	# read through the ftrace and parse the data	data.vprint("Analyzing the ftrace data...")	ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\					   " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\					   "[ +!]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)"	ftemp = dict()	inthepipe = False	tf = open(sysvals.ftracefile, 'r')	count = 0	for line in tf:		count = count + 1		# grab the time stamp if it's valid		if(count == 1):			parseStamp(line)			continue		# parse only valid lines		m = re.match(ftrace_line_fmt, line)		if(not m):

Lines 1–500 of 1446. Load more