#!/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>## Links:#	 Home Page#	   https://01.org/suspendresume#	 Source repo#	   https://github.com/01org/suspendresume## 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#		 CONFIG_KPROBES=y#		 CONFIG_KPROBES_ON_FTRACE=y##	 For kernel versions older than 3.15:#	 The following additional kernel parameters are required:#		 (e.g. in file /etc/default/grub)#		 GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."# # ----------------- LIBRARIES -------------------- import sysimport timeimport osimport stringimport reimport platformfrom datetime import datetimeimport structimport ConfigParserfrom threading import Threadfrom subprocess import call, Popen, PIPE # ----------------- CLASSES -------------------- # Class: SystemValues# Description:#	 A global, single-instance container used to#	 store system values and test parametersclass SystemValues:	ansi = False	version = '4.5'	verbose = False	addlogs = False	mindevlen = 0.0	mincglen = 0.0	cgphase = ''	cgtest = -1	callloopmaxgap = 0.0001	callloopmaxlen = 0.005	srgap = 0	cgexp = False	outdir = ''	testdir = '.'	tpath = '/sys/kernel/debug/tracing/'	fpdtpath = '/sys/firmware/acpi/tables/FPDT'	epath = '/sys/kernel/debug/tracing/events/power/'	traceevents = [		'suspend_resume',		'device_pm_callback_end',		'device_pm_callback_start'	]	logmsg = ''	testcommand = ''	mempath = '/dev/mem'	powerfile = '/sys/power/state'	suspendmode = 'mem'	hostname = 'localhost'	prefix = 'test'	teststamp = ''	dmesgstart = 0.0	dmesgfile = ''	ftracefile = ''	htmlfile = ''	embedded = False	rtcwake = False	rtcwaketime = 10	rtcpath = ''	devicefilter = []	stamp = 0	execcount = 1	x2delay = 0	usecallgraph = False	usetraceevents = False	usetraceeventsonly = False	usetracemarkers = True	usekprobes = True	usedevsrc = False	useprocmon = False	notestrun = False	mixedphaseheight = True	devprops = dict()	predelay = 0	postdelay = 0	procexecfmt = 'ps - (?P<ps>.*)$'	devpropfmt = '# Device Properties: .*'	tracertypefmt = '# tracer: (?P<t>.*)'	firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'	stampfmt = '# 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>.*)$'	tracefuncs = {		'sys_sync': dict(),		'pm_prepare_console': dict(),		'pm_notifier_call_chain': dict(),		'freeze_processes': dict(),		'freeze_kernel_threads': dict(),		'pm_restrict_gfp_mask': dict(),		'acpi_suspend_begin': dict(),		'suspend_console': dict(),		'acpi_pm_prepare': dict(),		'syscore_suspend': dict(),		'arch_enable_nonboot_cpus_end': dict(),		'syscore_resume': dict(),		'acpi_pm_finish': dict(),		'resume_console': dict(),		'acpi_pm_end': dict(),		'pm_restore_gfp_mask': dict(),		'thaw_processes': dict(),		'pm_restore_console': dict(),		'CPU_OFF': {			'func':'_cpu_down',			'args_x86_64': {'cpu':'%di:s32'},			'format': 'CPU_OFF[{cpu}]'		},		'CPU_ON': {			'func':'_cpu_up',			'args_x86_64': {'cpu':'%di:s32'},			'format': 'CPU_ON[{cpu}]'		},	}	dev_tracefuncs = {		# general wait/delay/sleep		'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },		'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },		'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },		'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },		'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },		'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },		'acpi_os_stall': {'ub': 1},		# ACPI		'acpi_resume_power_resources': dict(),		'acpi_ps_parse_aml': dict(),		# filesystem		'ext4_sync_fs': dict(),		# 80211		'iwlagn_mac_start': dict(),		'iwlagn_alloc_bcast_station': dict(),		'iwl_trans_pcie_start_hw': dict(),		'iwl_trans_pcie_start_fw': dict(),		'iwl_run_init_ucode': dict(),		'iwl_load_ucode_wait_alive': dict(),		'iwl_alive_start': dict(),		'iwlagn_mac_stop': dict(),		'iwlagn_mac_suspend': dict(),		'iwlagn_mac_resume': dict(),		'iwlagn_mac_add_interface': dict(),		'iwlagn_mac_remove_interface': dict(),		'iwlagn_mac_change_interface': dict(),		'iwlagn_mac_config': dict(),		'iwlagn_configure_filter': dict(),		'iwlagn_mac_hw_scan': dict(),		'iwlagn_bss_info_changed': dict(),		'iwlagn_mac_channel_switch': dict(),		'iwlagn_mac_flush': dict(),		# ATA		'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },		# i915		'i915_gem_resume': dict(),		'i915_restore_state': dict(),		'intel_opregion_setup': dict(),		'g4x_pre_enable_dp': dict(),		'vlv_pre_enable_dp': dict(),		'chv_pre_enable_dp': dict(),		'g4x_enable_dp': dict(),		'vlv_enable_dp': dict(),		'intel_hpd_init': dict(),		'intel_opregion_register': dict(),		'intel_dp_detect': dict(),		'intel_hdmi_detect': dict(),		'intel_opregion_init': dict(),		'intel_fbdev_set_suspend': dict(),	}	kprobes = dict()	timeformat = '%.3f'	def __init__(self):		# if this is a phoronix test run, set some default options		if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):			self.embedded = True			self.addlogs = True			self.htmlfile = os.environ['LOG_FILE']		self.archargs = 'args_'+platform.machine()		self.hostname = platform.node()		if(self.hostname == ''):			self.hostname = 'localhost'		rtc = "rtc0"		if os.path.exists('/dev/rtc'):			rtc = os.readlink('/dev/rtc')		rtc = '/sys/class/rtc/'+rtc		if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \			os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):			self.rtcpath = rtc		if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):			self.ansi = True	def setPrecision(self, num):		if num < 0 or num > 6:			return		self.timeformat = '%.{0}f'.format(num)	def setOutputFolder(self, value):		args = dict()		n = datetime.now()		args['date'] = n.strftime('%y%m%d')		args['time'] = n.strftime('%H%M%S')		args['hostname'] = self.hostname		self.outdir = value.format(**args)	def setOutputFile(self):		if((self.htmlfile == '') and (self.dmesgfile != '')):			m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)			if(m):				self.htmlfile = m.group('name')+'.html'		if((self.htmlfile == '') and (self.ftracefile != '')):			m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)			if(m):				self.htmlfile = m.group('name')+'.html'		if(self.htmlfile == ''):			self.htmlfile = 'output.html'	def initTestOutput(self, subdir, testpath=''):		self.prefix = self.hostname		v = open('/proc/version', 'r').read().strip()		kver = string.split(v)[2]		n = datetime.now()		testtime = n.strftime('suspend-%m%d%y-%H%M%S')		if not testpath:			testpath = n.strftime('suspend-%y%m%d-%H%M%S')		if(subdir != "."):			self.testdir = subdir+"/"+testpath		else:			self.testdir = testpath		self.teststamp = \			'# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver		if(self.embedded):			self.dmesgfile = \				'/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'			self.ftracefile = \				'/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'			return		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'		if not os.path.isdir(self.testdir):			os.mkdir(self.testdir)	def setDeviceFilter(self, value):		self.devicefilter = []		if value:			value = value.split(',')		for i in value:			self.devicefilter.append(i.strip())	def rtcWakeAlarmOn(self):		call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)		outD = open(self.rtcpath+'/date', 'r').read().strip()		outT = open(self.rtcpath+'/time', 'r').read().strip()		mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)		mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)		if(mD and mT):			# get the current time from hardware			utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())			dt = datetime(\				int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),				int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))			nowtime = int(dt.strftime('%s')) + utcoffset		else:			# if hardware time fails, use the software time			nowtime = int(datetime.now().strftime('%s'))		alarm = nowtime + self.rtcwaketime		call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)	def rtcWakeAlarmOff(self):		call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)	def initdmesg(self):		# get the latest time stamp from the dmesg log		fp = Popen('dmesg', stdout=PIPE).stdout		ktime = '0'		for line in fp:			line = line.replace('\r\n', '')			idx = line.find('[')			if idx > 1:				line = line[idx:]			m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)			if(m):				ktime = m.group('ktime')		fp.close()		self.dmesgstart = float(ktime)	def getdmesg(self):		# store all new dmesg lines since initdmesg was called		fp = Popen('dmesg', stdout=PIPE).stdout		op = open(self.dmesgfile, 'a')		for line in fp:			line = line.replace('\r\n', '')			idx = line.find('[')			if idx > 1:				line = line[idx:]			m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)			if(not m):				continue			ktime = float(m.group('ktime'))			if ktime > self.dmesgstart:				op.write(line)		fp.close()		op.close()	def addFtraceFilterFunctions(self, file):		fp = open(file)		list = fp.read().split('\n')		fp.close()		for i in list:			if len(i) < 2:				continue			self.tracefuncs[i] = dict()	def getFtraceFilterFunctions(self, current):		rootCheck(True)		if not current:			call('cat '+self.tpath+'available_filter_functions', shell=True)			return		fp = open(self.tpath+'available_filter_functions')		master = fp.read().split('\n')		fp.close()		for i in self.tracefuncs:			if 'func' in self.tracefuncs[i]:				i = self.tracefuncs[i]['func']			if i in master:				print i			else:				print self.colorText(i)	def setFtraceFilterFunctions(self, list):		fp = open(self.tpath+'available_filter_functions')		master = fp.read().split('\n')		fp.close()		flist = ''		for i in list:			if i not in master:				continue			if ' [' in i:				flist += i.split(' ')[0]+'\n'			else:				flist += i+'\n'		fp = open(self.tpath+'set_graph_function', 'w')		fp.write(flist)		fp.close()	def basicKprobe(self, name):		self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}	def defaultKprobe(self, name, kdata):		k = kdata		for field in ['name', 'format', 'func']:			if field not in k:				k[field] = name		if self.archargs in k:			k['args'] = k[self.archargs]		else:			k['args'] = dict()			k['format'] = name		self.kprobes[name] = k	def kprobeColor(self, name):		if name not in self.kprobes or 'color' not in self.kprobes[name]:			return ''		return self.kprobes[name]['color']	def kprobeDisplayName(self, name, dataraw):		if name not in self.kprobes:			self.basicKprobe(name)		data = ''		quote=0		# first remvoe any spaces inside quotes, and the quotes		for c in dataraw:			if c == '"':				quote = (quote + 1) % 2			if quote and c == ' ':				data += '_'			elif c != '"':				data += c		fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']		arglist = dict()		# now process the args		for arg in sorted(args):			arglist[arg] = ''			m = re.match('.* '+arg+'=(?P<arg>.*) ', data);			if m:				arglist[arg] = m.group('arg')			else:				m = re.match('.* '+arg+'=(?P<arg>.*)', data);				if m:					arglist[arg] = m.group('arg')		out = fmt.format(**arglist)		out = out.replace(' ', '_').replace('"', '')		return out	def kprobeText(self, kname, kprobe):		name = fmt = func = kname		args = dict()		if 'name' in kprobe:			name = kprobe['name']		if 'format' in kprobe:			fmt = kprobe['format']		if 'func' in kprobe:			func = kprobe['func']		if self.archargs in kprobe:			args = kprobe[self.archargs]		if 'args' in kprobe:			args = kprobe['args']		if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):			doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))		for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):			if arg not in args:				doError('Kprobe "%s" is missing argument "%s"' % (name, arg))		val = 'p:%s_cal %s' % (name, func)		for i in sorted(args):			val += ' %s=%s' % (i, args[i])		val += '\nr:%s_ret %s $retval\n' % (name, func)		return val	def addKprobes(self, output=False):		if len(sysvals.kprobes) < 1:			return		if output:			print('    kprobe functions in this kernel:')		# first test each kprobe		rejects = []		# sort kprobes: trace, ub-dev, custom, dev		kpl = [[], [], [], []]		for name in sorted(self.kprobes):			res = self.colorText('YES', 32)			if not self.testKprobe(name, self.kprobes[name]):				res = self.colorText('NO')				rejects.append(name)			else:				if name in self.tracefuncs:					kpl[0].append(name)				elif name in self.dev_tracefuncs:					if 'ub' in self.dev_tracefuncs[name]:						kpl[1].append(name)					else:						kpl[3].append(name)				else:					kpl[2].append(name)			if output:				print('         %s: %s' % (name, res))		kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]		# remove all failed ones from the list		for name in rejects:			self.kprobes.pop(name)		# set the kprobes all at once		self.fsetVal('', 'kprobe_events')		kprobeevents = ''		for kp in kplist:			kprobeevents += self.kprobeText(kp, self.kprobes[kp])		self.fsetVal(kprobeevents, 'kprobe_events')		# verify that the kprobes were set as ordered		check = self.fgetVal('kprobe_events')		linesout = len(kprobeevents.split('\n')) - 1		linesack = len(check.split('\n')) - 1		if output:			res = '%d/%d' % (linesack, linesout)			if linesack < linesout:				res = self.colorText(res, 31)			else:				res = self.colorText(res, 32)			print('    working kprobe functions enabled: %s' % res)		self.fsetVal('1', 'events/kprobes/enable')	def testKprobe(self, kname, kprobe):		self.fsetVal('0', 'events/kprobes/enable')

Lines 1–500 of 5235. Load more