tools: power: pm-graph: AnalyzeSuspend v4.6

Moved from scripts into tools, and updated from 4.5 to 4.6
- Changed the tool title to SleepGraph
- Reformatted the code so analyze_suspend can be used as a library
- Reorganized all html/js/css handling code to be used by other tools
- upgraded the -summary feature to work faster with better readability

Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

1 files changed, 5309 insertions, 0 deletions

diff --git a/tools/power/pm-graph/analyze_suspend.py b/tools/power/pm-graph/analyze_suspend.py
new file mode 100755
index 000000000000..a9206e67fc1f
--- /dev/null
+++ b/tools/power/pm-graph/analyze_suspend.py
@@ -0,0 +1,5309 @@
+#!/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.
+#
+# Authors:
+#	 Todd Brandt <todd.e.brandt@linux.intel.com>
+#
+# Links:
+#	 Home Page
+#	   https://01.org/suspendresume
+#	 Source repo
+#	   https://github.com/01org/pm-graph
+#
+# 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 sys
+import time
+import os
+import string
+import re
+import platform
+from datetime import datetime
+import struct
+import ConfigParser
+from threading import Thread
+from subprocess import call, Popen, PIPE
+
+# ----------------- CLASSES --------------------
+
+# Class: SystemValues
+# Description:
+#	 A global, single-instance container used to
+#	 store system values and test parameters
+class SystemValues:
+	title = 'SleepGraph'
+	version = '4.6'
+	ansi = False
+	verbose = False
+	addlogs = False
+	mindevlen = 0.0
+	mincglen = 0.0
+	cgphase = ''
+	cgtest = -1
+	max_graph_depth = 0
+	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 = True
+	rtcwaketime = 15
+	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 rootUser(self, fatal=False):
+		if 'USER' in os.environ and os.environ['USER'] == 'root':
+			return True
+		if fatal:
+			doError('This command must be run as root')
+		return False
+	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')
+		kprobeevents = self.kprobeText(kname, kprobe)
+		if not kprobeevents:
+			return False
+		try:
+			self.fsetVal(kprobeevents, 'kprobe_events')
+			check = self.fgetVal('kprobe_events')
+		except:
+			return False
+		linesout = len(kprobeevents.split('\n'))
+		linesack = len(check.split('\n'))
+		if linesack < linesout:
+			return False
+		return True
+	def fsetVal(self, val, path, mode='w'):
+		file = self.tpath+path
+		if not os.path.exists(file):
+			return False
+		try:
+			fp = open(file, mode, 0)
+			fp.write(val)
+			fp.flush()
+			fp.close()
+		except:
+			pass
+		return True
+	def fgetVal(self, path):
+		file = self.tpath+path
+		res = ''
+		if not os.path.exists(file):
+			return res
+		try:
+			fp = open(file, 'r')
+			res = fp.read()
+			fp.close()
+		except:
+			pass
+		return res
+	def cleanupFtrace(self):
+		if(self.usecallgraph or self.usetraceevents):
+			self.fsetVal('0', 'events/kprobes/enable')
+			self.fsetVal('', 'kprobe_events')
+	def setupAllKprobes(self):
+		for name in self.tracefuncs:
+			self.defaultKprobe(name, self.tracefuncs[name])
+		for name in self.dev_tracefuncs:
+			self.defaultKprobe(name, self.dev_tracefuncs[name])
+	def isCallgraphFunc(self, name):
+		if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
+			return True
+		for i in self.tracefuncs:
+			if 'func' in self.tracefuncs[i]:
+				f = self.tracefuncs[i]['func']
+			else:
+				f = i
+			if name == f:
+				return True
+		return False
+	def initFtrace(self, testing=False):
+		print('INITIALIZING FTRACE...')
+		# turn trace off
+		self.fsetVal('0', 'tracing_on')
+		self.cleanupFtrace()
+		# set the trace clock to global
+		self.fsetVal('global', 'trace_clock')
+		# set trace buffer to a huge value
+		self.fsetVal('nop', 'current_tracer')
+		self.fsetVal('131073', 'buffer_size_kb')
+		# go no further if this is just a status check
+		if testing:
+			return
+		# initialize the callgraph trace
+		if(self.usecallgraph):
+			# set trace type
+			self.fsetVal('function_graph', 'current_tracer')
+			self.fsetVal('', 'set_ftrace_filter')
+			# set trace format options
+			self.fsetVal('print-parent', 'trace_options')
+			self.fsetVal('funcgraph-abstime', 'trace_options')
+			self.fsetVal('funcgraph-cpu', 'trace_options')
+			self.fsetVal('funcgraph-duration', 'trace_options')
+			self.fsetVal('funcgraph-proc', 'trace_options')
+			self.fsetVal('funcgraph-tail', 'trace_options')
+			self.fsetVal('nofuncgraph-overhead', 'trace_options')
+			self.fsetVal('context-info', 'trace_options')
+			self.fsetVal('graph-time', 'trace_options')
+			self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
+			cf = ['dpm_run_callback']
+			if(self.usetraceeventsonly):
+				cf += ['dpm_prepare', 'dpm_complete']
+			for fn in self.tracefuncs:
+				if 'func' in self.tracefuncs[fn]:
+					cf.append(self.tracefuncs[fn]['func'])
+				else:
+					cf.append(fn)
+			self.setFtraceFilterFunctions(cf)
+		# initialize the kprobe trace
+		elif self.usekprobes:
+			for name in self.tracefuncs:
+				self.defaultKprobe(name, self.tracefuncs[name])
+			if self.usedevsrc:
+				for name in self.dev_tracefuncs:
+					self.defaultKprobe(name, self.dev_tracefuncs[name])
+			print('INITIALIZING KPROBES...')
+			self.addKprobes(self.verbose)
+		if(self.usetraceevents):
+			# turn trace events on
+			events = iter(self.traceevents)
+			for e in events:
+				self.fsetVal('1', 'events/power/'+e+'/enable')
+		# clear the trace buffer
+		self.fsetVal('', 'trace')
+	def verifyFtrace(self):
+		# files needed for any trace data
+		files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
+				 'trace_marker', 'trace_options', 'tracing_on']
+		# files needed for callgraph trace data
+		tp = self.tpath
+		if(self.usecallgraph):
+			files += [
+				'available_filter_functions',
+				'set_ftrace_filter',
+				'set_graph_function'
+			]
+		for f in files:
+			if(os.path.exists(tp+f) == False):
+				return False
+		return True
+	def verifyKprobes(self):
+		# files needed for kprobes to work
+		files = ['kprobe_events', 'events']
+		tp = self.tpath
+		for f in files:
+			if(os.path.exists(tp+f) == False):
+				return False
+		return True
+	def colorText(self, str, color=31):
+		if not self.ansi:
+			return str
+		return '\x1B[%d;40m%s\x1B[m' % (color, str)
+
+sysvals = SystemValues()
+suspendmodename = {
+	'freeze': 'Freeze (S0)',
+	'standby': 'Standby (S1)',
+	'mem': 'Suspend (S3)',
+	'disk': 'Hibernate (S4)'
+}
+
+# Class: DevProps
+# Description:
+#	 Simple class which holds property values collected
+#	 for all the devices used in the timeline.
+class DevProps:
+	syspath = ''
+	altname = ''
+	async = True
+	xtraclass = ''
+	xtrainfo = ''
+	def out(self, dev):
+		return '%s,%s,%d;' % (dev, self.altname, self.async)
+	def debug(self, dev):
+		print '%s:\n\taltname = %s\n\t  async = %s' % (dev, self.altname, self.async)
+	def altName(self, dev):
+		if not self.altname or self.altname == dev:
+			return dev
+		return '%s [%s]' % (self.altname, dev)
+	def xtraClass(self):
+		if self.xtraclass:
+			return ' '+self.xtraclass
+		if not self.async:
+			return ' sync'
+		return ''
+	def xtraInfo(self):
+		if self.xtraclass:
+			return ' '+self.xtraclass
+		if self.async:
+			return ' async_device'
+		return ' sync_device'
+
+# Class: DeviceNode
+# Description:
+#	 A container used to create a device hierachy, with a single root node
+#	 and a tree of child nodes. Used by Data.deviceTopology()
+class DeviceNode:
+	name = ''
+	children = 0
+	depth = 0
+	def __init__(self, nodename, nodedepth):
+		self.name = nodename
+		self.children = []
+		self.depth = nodedepth
+
+# Class: Data
+# Description:
+#	 The primary container for suspend/resume test data. There is one for
+#	 each test run. The data is organized into a cronological hierarchy:
+#	 Data.dmesg {
+#		phases {
+#			10 sequential, non-overlapping phases of S/R
+#			contents: times for phase start/end, order/color data for html
+#			devlist {
+#				device callback or action list for this phase
+#				device {
+#					a single device callback or generic action
+#					contents: start/stop times, pid/cpu/driver info
+#						parents/children, html id for timeline/callgraph
+#						optionally includes an ftrace callgraph
+#						optionally includes dev/ps data
+#				}
+#			}
+#		}
+#	}
+#
+class Data:
+	dmesg = {}  # root data structure
+	phases = [] # ordered list of phases
+	start = 0.0 # test start
+	end = 0.0   # test end
+	tSuspended = 0.0 # low-level suspend start
+	tResumed = 0.0   # low-level resume start
+	tKernSus = 0.0   # kernel level suspend start
+	tKernRes = 0.0   # kernel level resume end
+	tLow = 0.0       # time spent in low-level suspend (standby/freeze)
+	fwValid = False  # is firmware data available
+	fwSuspend = 0    # time spent in firmware suspend
+	fwResume = 0     # time spent in firmware resume
+	dmesgtext = []   # dmesg text file in memory
+	pstl = 0         # process timeline
+	testnumber = 0
+	idstr = ''
+	html_device_id = 0
+	stamp = 0
+	outfile = ''
+	devpids = []
+	kerror = False
+	def __init__(self, num):
+		idchar = 'abcdefghij'
+		self.pstl = dict()
+		self.testnumber = num
+		self.idstr = idchar[num]
+		self.dmesgtext = []
+		self.phases = []
+		self.dmesg = { # fixed list of 10 phases
+			'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#CCFFCC', 'order': 0},
+			        'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#88FF88', 'order': 1},
+			   'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#00AA00', 'order': 2},
+			  'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#008888', 'order': 3},
+		    'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#0000FF', 'order': 4},
+			 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#FF0000', 'order': 5},
+			   'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#FF9900', 'order': 6},
+			   'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#FFCC00', 'order': 7},
+			         'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#FFFF88', 'order': 8},
+			'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': '#FFFFCC', 'order': 9}
+		}
+		self.phases = self.sortedPhases()
+		self.devicegroups = []
+		for phase in self.phases:
+			self.devicegroups.append([phase])
+		self.errorinfo = {'suspend':[],'resume':[]}
+	def extractErrorInfo(self, dmesg):
+		error = ''
+		tm = 0.0
+		for i in range(len(dmesg)):
+			if 'Call Trace:' in dmesg[i]:
+				m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i])
+				if not m:
+					continue
+				tm = float(m.group('ktime'))
+				if tm < self.start or tm > self.end:
+					continue
+				for j in range(i-10, i+1):
+					error += dmesg[j]
+				continue
+			if error:
+				m = re.match('[ \t]*\[ *[0-9\.]*\]  \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
+				if m:
+					error += dmesg[i]
+				else:
+					if tm < self.tSuspended:
+						dir = 'suspend'
+					else:
+						dir = 'resume'
+					error = error.replace('<', '&lt').replace('>', '&gt')
+					vprint('kernel error found in %s at %f' % (dir, tm))
+					self.errorinfo[dir].append((tm, error))
+					self.kerror = True
+					error = ''
+	def setStart(self, time):
+		self.start = time
+	def setEnd(self, time):
+		self.end = time
+	def isTraceEventOutsideDeviceCalls(self, pid, time):
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			for dev in list:
+				d = list[dev]
+				if(d['pid'] == pid and time >= d['start'] and
+					time < d['end']):
+					return False
+		return True
+	def sourcePhase(self, start):
+		for phase in self.phases:
+			pend = self.dmesg[phase]['end']
+			if start <= pend:
+				return phase
+		return 'resume_complete'
+	def sourceDevice(self, phaselist, start, end, pid, type):
+		tgtdev = ''
+		for phase in phaselist:
+			list = self.dmesg[phase]['list']
+			for devname in list:
+				dev = list[devname]
+				# pid must match
+				if dev['pid'] != pid:
+					continue
+				devS = dev['start']
+				devE = dev['end']
+				if type == 'device':
+					# device target event is entirely inside the source boundary
+					if(start < devS or start >= devE or end <= devS or end > devE):
+						continue
+				elif type == 'thread':
+					# thread target event will expand the source boundary
+					if start < devS:
+						dev['start'] = start
+					if end > devE:
+						dev['end'] = end
+				tgtdev = dev
+				break
+		return tgtdev
+	def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
+		# try to place the call in a device
+		tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device')
+		# calls with device pids that occur outside device bounds are dropped
+		# TODO: include these somehow
+		if not tgtdev and pid in self.devpids:
+			return False
+		# try to place the call in a thread
+		if not tgtdev:
+			tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread')
+		# create new thread blocks, expand as new calls are found
+		if not tgtdev:
+			if proc == '<...>':
+				threadname = 'kthread-%d' % (pid)
+			else:
+				threadname = '%s-%d' % (proc, pid)
+			tgtphase = self.sourcePhase(start)
+			self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
+			return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
+		# this should not happen
+		if not tgtdev:
+			vprint('[%f - %f] %s-%d %s %s %s' % \
+				(start, end, proc, pid, kprobename, cdata, rdata))
+			return False
+		# place the call data inside the src element of the tgtdev
+		if('src' not in tgtdev):
+			tgtdev['src'] = []
+		dtf = sysvals.dev_tracefuncs
+		ubiquitous = False
+		if kprobename in dtf and 'ub' in dtf[kprobename]:
+			ubiquitous = True
+		title = cdata+' '+rdata
+		mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
+		m = re.match(mstr, title)
+		if m:
+			c = m.group('caller')
+			a = m.group('args').strip()
+			r = m.group('ret')
+			if len(r) > 6:
+				r = ''
+			else:
+				r = 'ret=%s ' % r
+			if ubiquitous and c in dtf and 'ub' in dtf[c]:
+				return False
+		color = sysvals.kprobeColor(kprobename)
+		e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
+		tgtdev['src'].append(e)
+		return True
+	def overflowDevices(self):
+		# get a list of devices that extend beyond the end of this test run
+		devlist = []
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			for devname in list:
+				dev = list[devname]
+				if dev['end'] > self.end:
+					devlist.append(dev)
+		return devlist
+	def mergeOverlapDevices(self, devlist):
+		# merge any devices that overlap devlist
+		for dev in devlist:
+			devname = dev['name']
+			for phase in self.phases:
+				list = self.dmesg[phase]['list']
+				if devname not in list:
+					continue
+				tdev = list[devname]
+				o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
+				if o <= 0:
+					continue
+				dev['end'] = tdev['end']
+				if 'src' not in dev or 'src' not in tdev:
+					continue
+				dev['src'] += tdev['src']
+				del list[devname]
+	def usurpTouchingThread(self, name, dev):
+		# the caller test has priority of this thread, give it to him
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			if name in list:
+				tdev = list[name]
+				if tdev['start'] - dev['end'] < 0.1:
+					dev['end'] = tdev['end']
+					if 'src' not in dev:
+						dev['src'] = []
+					if 'src' in tdev:
+						dev['src'] += tdev['src']
+					del list[name]
+				break
+	def stitchTouchingThreads(self, testlist):
+		# merge any threads between tests that touch
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			for devname in list:
+				dev = list[devname]
+				if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
+					continue
+				for data in testlist:
+					data.usurpTouchingThread(devname, dev)
+	def optimizeDevSrc(self):
+		# merge any src call loops to reduce timeline size
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			for dev in list:
+				if 'src' not in list[dev]:
+					continue
+				src = list[dev]['src']
+				p = 0
+				for e in sorted(src, key=lambda event: event.time):
+					if not p or not e.repeat(p):
+						p = e
+						continue
+					# e is another iteration of p, move it into p
+					p.end = e.end
+					p.length = p.end - p.time
+					p.count += 1
+					src.remove(e)
+	def trimTimeVal(self, t, t0, dT, left):
+		if left:
+			if(t > t0):
+				if(t - dT < t0):
+					return t0
+				return t - dT
+			else:
+				return t
+		else:
+			if(t < t0 + dT):
+				if(t > t0):
+					return t0 + dT
+				return t + dT
+			else:
+				return t
+	def trimTime(self, t0, dT, left):
+		self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
+		self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
+		self.start = self.trimTimeVal(self.start, t0, dT, left)
+		self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
+		self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
+		self.end = self.trimTimeVal(self.end, t0, dT, left)
+		for phase in self.phases:
+			p = self.dmesg[phase]
+			p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
+			p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
+			list = p['list']
+			for name in list:
+				d = list[name]
+				d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
+				d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
+				if('ftrace' in d):
+					cg = d['ftrace']
+					cg.start = self.trimTimeVal(cg.start, t0, dT, left)
+					cg.end = self.trimTimeVal(cg.end, t0, dT, left)
+					for line in cg.list:
+						line.time = self.trimTimeVal(line.time, t0, dT, left)
+				if('src' in d):
+					for e in d['src']:
+						e.time = self.trimTimeVal(e.time, t0, dT, left)
+	def normalizeTime(self, tZero):
+		# trim out any standby or freeze clock time
+		if(self.tSuspended != self.tResumed):
+			if(self.tResumed > tZero):
+				self.trimTime(self.tSuspended, \
+					self.tResumed-self.tSuspended, True)
+			else:
+				self.trimTime(self.tSuspended, \
+					self.tResumed-self.tSuspended, False)
+	def setPhase(self, phase, ktime, isbegin):
+		if(isbegin):
+			self.dmesg[phase]['start'] = ktime
+		else:
+			self.dmesg[phase]['end'] = ktime
+	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]
+			if dev['length'] == 0:
+				continue
+			tmp[dev['start']] = devname
+		for t in sorted(tmp):
+			slist.append(tmp[t])
+		return slist
+	def fixupInitcalls(self, phase):
+		# 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):
+				for p in self.phases:
+					if self.dmesg[p]['end'] > dev['start']:
+						dev['end'] = self.dmesg[p]['end']
+						break
+				vprint('%s (%s): callback didnt return' % (devname, phase))
+	def deviceFilter(self, devicefilter):
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			rmlist = []
+			for name in list:
+				keep = False
+				for filter in devicefilter:
+					if filter in name or \
+						('drv' in list[name] and filter in list[name]['drv']):
+						keep = True
+				if not keep:
+					rmlist.append(name)
+			for name in rmlist:
+				del list[name]
+	def fixupInitcallsThatDidntReturn(self):
+		# if any calls never returned, clip them at system resume end
+		for phase in self.phases:
+			self.fixupInitcalls(phase)
+	def phaseOverlap(self, phases):
+		rmgroups = []
+		newgroup = []
+		for group in self.devicegroups:
+			for phase in phases:
+				if phase not in group:
+					continue
+				for p in gro