pm-graph: AnalyzeSuspend v5.0

- add -cgskip option to reduce callgraph output size
- add -cgfilter option to focus on a list of devices
- add -result option for exporting batch test results
- removed all phoronix hooks, use -result to enable batch testing
- change -usbtopo to -devinfo, now prints all devices
- add -gzip option to read/write logs in gz format
- add -bufsize option to manually control ftrace buffer size
- add -sync option to run filesystem sync prior to test
- add -display option to enable/disable the display prior to test
- add -rs option to enable/disable runtime suspend on all devices for test
- add installed config files to search path
- add kernel error/warning links into the timeline
- fix callgraph trace to better handle interrupts
- include command string and kernel params in timeline output header

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, 1012 insertions, 613 deletions

diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py
index 1b60fe203741..266409fb27ae 100755
--- a/tools/power/pm-graph/sleepgraph.py
+++ b/tools/power/pm-graph/sleepgraph.py
@@ -19,7 +19,7 @@
 #	 Home Page
 #	   https://01.org/suspendresume
 #	 Source repo
-#	   https://github.com/01org/pm-graph
+#	   git@github.com:01org/pm-graph
 #
 # Description:
 #	 This tool is designed to assist kernel and OS developers in optimizing
@@ -57,6 +57,7 @@ import platform
 from datetime import datetime
 import struct
 import ConfigParser
+import gzip
 from threading import Thread
 from subprocess import call, Popen, PIPE
 
@@ -68,8 +69,12 @@ from subprocess import call, Popen, PIPE
 #	 store system values and test parameters
 class SystemValues:
 	title = 'SleepGraph'
-	version = '4.7'
+	version = '5.0'
 	ansi = False
+	rs = 0
+	display = 0
+	gzip = False
+	sync = False
 	verbose = False
 	testlog = True
 	dmesglog = False
@@ -78,14 +83,19 @@ class SystemValues:
 	mincglen = 0.0
 	cgphase = ''
 	cgtest = -1
+	cgskip = ''
+	multitest = {'run': False, 'count': 0, 'delay': 0}
 	max_graph_depth = 0
 	callloopmaxgap = 0.0001
 	callloopmaxlen = 0.005
+	bufsize = 0
 	cpucount = 0
 	memtotal = 204800
+	memfree = 204800
 	srgap = 0
 	cgexp = False
 	testdir = ''
+	outdir = ''
 	tpath = '/sys/kernel/debug/tracing/'
 	fpdtpath = '/sys/firmware/acpi/tables/FPDT'
 	epath = '/sys/kernel/debug/tracing/events/power/'
@@ -109,22 +119,24 @@ class SystemValues:
 	dmesgfile = ''
 	ftracefile = ''
 	htmlfile = 'output.html'
-	embedded = False
+	result = ''
 	rtcwake = True
 	rtcwaketime = 15
 	rtcpath = ''
 	devicefilter = []
+	cgfilter = []
 	stamp = 0
 	execcount = 1
 	x2delay = 0
+	skiphtml = False
 	usecallgraph = False
 	usetraceevents = False
-	usetraceeventsonly = False
 	usetracemarkers = True
 	usekprobes = True
 	usedevsrc = False
 	useprocmon = False
 	notestrun = False
+	cgdump = False
 	mixedphaseheight = True
 	devprops = dict()
 	predelay = 0
@@ -134,24 +146,33 @@ class SystemValues:
 	tracertypefmt = '# tracer: (?P<t>.*)'
 	firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
 	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(),
+		'sys_sync': {},
+		'__pm_notifier_call_chain': {},
+		'pm_prepare_console': {},
+		'pm_notifier_call_chain': {},
+		'freeze_processes': {},
+		'freeze_kernel_threads': {},
+		'pm_restrict_gfp_mask': {},
+		'acpi_suspend_begin': {},
+		'acpi_hibernation_begin': {},
+		'acpi_hibernation_enter': {},
+		'acpi_hibernation_leave': {},
+		'acpi_pm_freeze': {},
+		'acpi_pm_thaw': {},
+		'hibernate_preallocate_memory': {},
+		'create_basic_memory_bitmaps': {},
+		'swsusp_write': {},
+		'suspend_console': {},
+		'acpi_pm_prepare': {},
+		'syscore_suspend': {},
+		'arch_enable_nonboot_cpus_end': {},
+		'syscore_resume': {},
+		'acpi_pm_finish': {},
+		'resume_console': {},
+		'acpi_pm_end': {},
+		'pm_restore_gfp_mask': {},
+		'thaw_processes': {},
+		'pm_restore_console': {},
 		'CPU_OFF': {
 			'func':'_cpu_down',
 			'args_x86_64': {'cpu':'%di:s32'},
@@ -173,56 +194,54 @@ class SystemValues:
 		'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(),
+		'acpi_resume_power_resources': {},
+		'acpi_ps_parse_aml': {},
 		# filesystem
-		'ext4_sync_fs': dict(),
+		'ext4_sync_fs': {},
 		# 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(),
+		'iwlagn_mac_start': {},
+		'iwlagn_alloc_bcast_station': {},
+		'iwl_trans_pcie_start_hw': {},
+		'iwl_trans_pcie_start_fw': {},
+		'iwl_run_init_ucode': {},
+		'iwl_load_ucode_wait_alive': {},
+		'iwl_alive_start': {},
+		'iwlagn_mac_stop': {},
+		'iwlagn_mac_suspend': {},
+		'iwlagn_mac_resume': {},
+		'iwlagn_mac_add_interface': {},
+		'iwlagn_mac_remove_interface': {},
+		'iwlagn_mac_change_interface': {},
+		'iwlagn_mac_config': {},
+		'iwlagn_configure_filter': {},
+		'iwlagn_mac_hw_scan': {},
+		'iwlagn_bss_info_changed': {},
+		'iwlagn_mac_channel_switch': {},
+		'iwlagn_mac_flush': {},
 		# 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(),
+		'i915_gem_resume': {},
+		'i915_restore_state': {},
+		'intel_opregion_setup': {},
+		'g4x_pre_enable_dp': {},
+		'vlv_pre_enable_dp': {},
+		'chv_pre_enable_dp': {},
+		'g4x_enable_dp': {},
+		'vlv_enable_dp': {},
+		'intel_hpd_init': {},
+		'intel_opregion_register': {},
+		'intel_dp_detect': {},
+		'intel_hdmi_detect': {},
+		'intel_opregion_init': {},
+		'intel_fbdev_set_suspend': {},
 	}
+	cgblacklist = []
 	kprobes = dict()
 	timeformat = '%.3f'
+	cmdline = '%s %s' % \
+			(os.path.basename(sys.argv[0]), string.join(sys.argv[1:], ' '))
 	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.dmesglog = self.ftracelog = True
-			self.htmlfile = os.environ['LOG_FILE']
 		self.archargs = 'args_'+platform.machine()
 		self.hostname = platform.node()
 		if(self.hostname == ''):
@@ -237,18 +256,36 @@ class SystemValues:
 		if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
 			self.ansi = True
 		self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
+	def vprint(self, msg):
+		self.logmsg += msg+'\n'
+		if(self.verbose):
+			print(msg)
 	def rootCheck(self, fatal=True):
 		if(os.access(self.powerfile, os.W_OK)):
 			return True
 		if fatal:
-			doError('This command requires sysfs mount and root access')
+			msg = 'This command requires sysfs mount and root access'
+			print('ERROR: %s\n') % msg
+			self.outputResult({'error':msg})
+			sys.exit()
 		return False
 	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')
+			msg = 'This command must be run as root'
+			print('ERROR: %s\n') % msg
+			self.outputResult({'error':msg})
+			sys.exit()
 		return False
+	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 setPrecision(self, num):
 		if num < 0 or num > 6:
 			return
@@ -258,15 +295,15 @@ class SystemValues:
 		n = datetime.now()
 		args['date'] = n.strftime('%y%m%d')
 		args['time'] = n.strftime('%H%M%S')
-		args['hostname'] = self.hostname
+		args['hostname'] = args['host'] = self.hostname
 		return value.format(**args)
 	def setOutputFile(self):
 		if self.dmesgfile != '':
-			m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
+			m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)
 			if(m):
 				self.htmlfile = m.group('name')+'.html'
 		if self.ftracefile != '':
-			m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
+			m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
 			if(m):
 				self.htmlfile = m.group('name')+'.html'
 	def systemInfo(self, info):
@@ -283,16 +320,19 @@ class SystemValues:
 			c = info['processor-version']
 		if 'bios-version' in info:
 			b = info['bios-version']
-		self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d' % \
-			(m, p, c, b, self.cpucount, self.memtotal)
-	def printSystemInfo(self):
+		self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \
+			(m, p, c, b, self.cpucount, self.memtotal, self.memfree)
+	def printSystemInfo(self, fatal=False):
 		self.rootCheck(True)
-		out = dmidecode(self.mempath, True)
+		out = dmidecode(self.mempath, fatal)
+		if len(out) < 1:
+			return
 		fmt = '%-24s: %s'
 		for name in sorted(out):
 			print fmt % (name, out[name])
 		print fmt % ('cpucount', ('%d' % self.cpucount))
 		print fmt % ('memtotal', ('%d kB' % self.memtotal))
+		print fmt % ('memfree', ('%d kB' % self.memfree))
 	def cpuInfo(self):
 		self.cpucount = 0
 		fp = open('/proc/cpuinfo', 'r')
@@ -305,7 +345,9 @@ class SystemValues:
 			m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
 			if m:
 				self.memtotal = int(m.group('sz'))
-				break
+			m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)
+			if m:
+				self.memfree = int(m.group('sz'))
 		fp.close()
 	def initTestOutput(self, name):
 		self.prefix = self.hostname
@@ -315,39 +357,34 @@ class SystemValues:
 		testtime = datetime.now().strftime(fmt)
 		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
+		ext = ''
+		if self.gzip:
+			ext = '.gz'
 		self.dmesgfile = \
-			self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
+			self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
 		self.ftracefile = \
-			self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
+			self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
 		self.htmlfile = \
 			self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
 		if not os.path.isdir(self.testdir):
 			os.mkdir(self.testdir)
+	def getValueList(self, value):
+		out = []
+		for i in value.split(','):
+			if i.strip():
+				out.append(i.strip())
+		return out
 	def setDeviceFilter(self, value):
-		self.devicefilter = []
-		if value:
-			value = value.split(',')
-		for i in value:
-			self.devicefilter.append(i.strip())
+		self.devicefilter = self.getValueList(value)
+	def setCallgraphFilter(self, value):
+		self.cgfilter = self.getValueList(value)
+	def setCallgraphBlacklist(self, file):
+		self.cgblacklist = self.listFromFile(file)
 	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
+		nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()
+		if nowtime:
+			nowtime = int(nowtime)
 		else:
 			# if hardware time fails, use the software time
 			nowtime = int(datetime.now().strftime('%s'))
@@ -369,10 +406,10 @@ class SystemValues:
 				ktime = m.group('ktime')
 		fp.close()
 		self.dmesgstart = float(ktime)
-	def getdmesg(self):
+	def getdmesg(self, fwdata=[]):
+		op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata)
 		# 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('[')
@@ -386,11 +423,17 @@ class SystemValues:
 				op.write(line)
 		fp.close()
 		op.close()
-	def addFtraceFilterFunctions(self, file):
+	def listFromFile(self, file):
+		list = []
 		fp = open(file)
-		list = fp.read().split('\n')
+		for i in fp.read().split('\n'):
+			i = i.strip()
+			if i and i[0] != '#':
+				list.append(i)
 		fp.close()
-		for i in list:
+		return list
+	def addFtraceFilterFunctions(self, file):
+		for i in self.listFromFile(file):
 			if len(i) < 2:
 				continue
 			self.tracefuncs[i] = dict()
@@ -399,9 +442,7 @@ class SystemValues:
 		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()
+		master = self.listFromFile(self.tpath+'available_filter_functions')
 		for i in self.tracefuncs:
 			if 'func' in self.tracefuncs[i]:
 				i = self.tracefuncs[i]['func']
@@ -410,9 +451,7 @@ class SystemValues:
 			else:
 				print self.colorText(i)
 	def setFtraceFilterFunctions(self, list):
-		fp = open(self.tpath+'available_filter_functions')
-		master = fp.read().split('\n')
-		fp.close()
+		master = self.listFromFile(self.tpath+'available_filter_functions')
 		flist = ''
 		for i in list:
 			if i not in master:
@@ -501,6 +540,7 @@ class SystemValues:
 		rejects = []
 		# sort kprobes: trace, ub-dev, custom, dev
 		kpl = [[], [], [], []]
+		linesout = len(self.kprobes)
 		for name in sorted(self.kprobes):
 			res = self.colorText('YES', 32)
 			if not self.testKprobe(name, self.kprobes[name]):
@@ -528,17 +568,10 @@ class SystemValues:
 		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)
+			check = self.fgetVal('kprobe_events')
+			linesack = (len(check.split('\n')) - 1) / 2
+			print('    kprobe functions enabled: %d/%d' % (linesack, linesout))
 		self.fsetVal('1', 'events/kprobes/enable')
 	def testKprobe(self, kname, kprobe):
 		self.fsetVal('0', 'events/kprobes/enable')
@@ -555,8 +588,7 @@ class SystemValues:
 		if linesack < linesout:
 			return False
 		return True
-	def fsetVal(self, val, path, mode='w'):
-		file = self.tpath+path
+	def setVal(self, val, file, mode='w'):
 		if not os.path.exists(file):
 			return False
 		try:
@@ -567,8 +599,9 @@ class SystemValues:
 		except:
 			return False
 		return True
-	def fgetVal(self, path):
-		file = self.tpath+path
+	def fsetVal(self, val, path, mode='w'):
+		return self.setVal(val, self.tpath+path, mode)
+	def getVal(self, file):
 		res = ''
 		if not os.path.exists(file):
 			return res
@@ -579,10 +612,13 @@ class SystemValues:
 		except:
 			pass
 		return res
+	def fgetVal(self, path):
+		return self.getVal(self.tpath+path)
 	def cleanupFtrace(self):
-		if(self.usecallgraph or self.usetraceevents):
+		if(self.usecallgraph or self.usetraceevents or self.usedevsrc):
 			self.fsetVal('0', 'events/kprobes/enable')
 			self.fsetVal('', 'kprobe_events')
+			self.fsetVal('1024', 'buffer_size_kb')
 	def setupAllKprobes(self):
 		for name in self.tracefuncs:
 			self.defaultKprobe(name, self.tracefuncs[name])
@@ -599,7 +635,8 @@ class SystemValues:
 			if name == f:
 				return True
 		return False
-	def initFtrace(self, testing=False):
+	def initFtrace(self):
+		self.printSystemInfo(False)
 		print('INITIALIZING FTRACE...')
 		# turn trace off
 		self.fsetVal('0', 'tracing_on')
@@ -607,17 +644,21 @@ class SystemValues:
 		# set the trace clock to global
 		self.fsetVal('global', 'trace_clock')
 		self.fsetVal('nop', 'current_tracer')
-		# set trace buffer to a huge value
-		if self.usecallgraph or self.usedevsrc:
-			tgtsize = min(self.memtotal / 2, 2*1024*1024)
-			maxbuf = '%d' % (tgtsize / max(1, self.cpucount))
-			if self.cpucount < 1 or not self.fsetVal(maxbuf, 'buffer_size_kb'):
-				self.fsetVal('131072', 'buffer_size_kb')
+		# set trace buffer to an appropriate value
+		cpus = max(1, self.cpucount)
+		if self.bufsize > 0:
+			tgtsize = self.bufsize
+		elif self.usecallgraph or self.usedevsrc:
+			tgtsize = min(self.memfree, 3*1024*1024)
 		else:
-			self.fsetVal('16384', 'buffer_size_kb')
-		# go no further if this is just a status check
-		if testing:
-			return
+			tgtsize = 65536
+		while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
+			# if the size failed to set, lower it and keep trying
+			tgtsize -= 65536
+			if tgtsize < 65536:
+				tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
+				break
+		print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)
 		# initialize the callgraph trace
 		if(self.usecallgraph):
 			# set trace type
@@ -635,7 +676,7 @@ class SystemValues:
 			self.fsetVal('graph-time', 'trace_options')
 			self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
 			cf = ['dpm_run_callback']
-			if(self.usetraceeventsonly):
+			if(self.usetraceevents):
 				cf += ['dpm_prepare', 'dpm_complete']
 			for fn in self.tracefuncs:
 				if 'func' in self.tracefuncs[fn]:
@@ -688,16 +729,65 @@ class SystemValues:
 			return str
 		return '\x1B[%d;40m%s\x1B[m' % (color, str)
 	def writeDatafileHeader(self, filename, fwdata=[]):
-		fp = open(filename, 'w')
-		fp.write(self.teststamp+'\n')
-		fp.write(self.sysstamp+'\n')
+		fp = self.openlog(filename, 'w')
+		fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
 		if(self.suspendmode == 'mem' or self.suspendmode == 'command'):
 			for fw in fwdata:
 				if(fw):
 					fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
+		return fp
+	def sudouser(self, dir):
+		if os.path.exists(dir) and 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'], dir), shell=True)
+	def outputResult(self, testdata, num=0):
+		if not self.result:
+			return
+		n = ''
+		if num > 0:
+			n = '%d' % num
+		fp = open(self.result, 'a')
+		if 'error' in testdata:
+			fp.write('result%s: fail\n' % n)
+			fp.write('error%s: %s\n' % (n, testdata['error']))
+		else:
+			fp.write('result%s: pass\n' % n)
+		for v in ['suspend', 'resume', 'boot', 'lastinit']:
+			if v in testdata:
+				fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))
+		for v in ['fwsuspend', 'fwresume']:
+			if v in testdata:
+				fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0))
+		if 'bugurl' in testdata:
+			fp.write('url%s: %s\n' % (n, testdata['bugurl']))
 		fp.close()
+		self.sudouser(self.result)
+	def configFile(self, file):
+		dir = os.path.dirname(os.path.realpath(__file__))
+		if os.path.exists(file):
+			return file
+		elif os.path.exists(dir+'/'+file):
+			return dir+'/'+file
+		elif os.path.exists(dir+'/config/'+file):
+			return dir+'/config/'+file
+		return ''
+	def openlog(self, filename, mode):
+		isgz = self.gzip
+		if mode == 'r':
+			try:
+				with gzip.open(filename, mode+'b') as fp:
+					test = fp.read(64)
+				isgz = True
+			except:
+				isgz = False
+		if isgz:
+			return gzip.open(filename, mode+'b')
+		return open(filename, mode)
 
 sysvals = SystemValues()
+switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
+switchoff = ['disable', 'off', 'false', '0']
 suspendmodename = {
 	'freeze': 'Freeze (S0)',
 	'standby': 'Standby (S1)',
@@ -826,34 +916,65 @@ class Data:
 		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]
+	def extractErrorInfo(self):
+		lf = sysvals.openlog(sysvals.dmesgfile, 'r')
+		i = 0
+		list = []
+		# sl = start line, et = error time, el = error line
+		type = 'ERROR'
+		sl = et = el = -1
+		for line in lf:
+			i += 1
+			m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
+			if not m:
 				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))
+			t = float(m.group('ktime'))
+			if t < self.start or t > self.end:
+				continue
+			if t < self.tSuspended:
+				dir = 'suspend'
+			else:
+				dir = 'resume'
+			msg = m.group('msg')
+			if re.match('-*\[ *cut here *\]-*', msg):
+				type = 'WARNING'
+				sl = i
+			elif re.match('genirq: .*', msg):
+				type = 'IRQ'
+				sl = i
+			elif re.match('BUG: .*', msg) or re.match('kernel BUG .*', msg):
+				type = 'BUG'
+				sl = i
+			elif re.match('-*\[ *end trace .*\]-*', msg) or \
+				re.match('R13: .*', msg):
+				if et >= 0 and sl >= 0:
+					list.append((type, dir, et, sl, i))
 					self.kerror = True
-					error = ''
+					sl = et = el = -1
+					type = 'ERROR'
+			elif 'Call Trace:' in msg:
+				if el >= 0 and et >= 0:
+					list.append((type, dir, et, el, el))
+					self.kerror = True
+				et, el = t, i
+				if sl < 0 or type == 'BUG':
+					slval = i
+					if sl >= 0:
+						slval = sl
+					list.append((type, dir, et, slval, i))
+					self.kerror = True
+					sl = et = el = -1
+					type = 'ERROR'
+		if el >= 0 and et >= 0:
+			list.append((type, dir, et, el, el))
+			self.kerror = True
+		for e in list:
+			type, dir, t, idx1, idx2 = e
+			sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t))
+			self.errorinfo[dir].append((type, t, idx1, idx2))
+		if self.kerror:
+			sysvals.dmesglog = True
+		lf.close()
 	def setStart(self, time):
 		self.start = time
 	def setEnd(self, time):
@@ -867,6 +988,14 @@ class Data:
 					time < d['end']):
 					return False
 		return True
+	def phaseCollision(self, phase, isbegin, line):
+		key = 'end'
+		if isbegin:
+			key = 'start'
+		if self.dmesg[phase][key] >= 0:
+			sysvals.vprint('IGNORE: %s' % line.strip())
+			return True
+		return False
 	def sourcePhase(self, start):
 		for phase in self.phases:
 			pend = self.dmesg[phase]['end']
@@ -918,7 +1047,7 @@ class Data:
 			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' % \
+			sysvals.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
@@ -1054,6 +1183,13 @@ class Data:
 				if('src' in d):
 					for e in d['src']:
 						e.time = self.trimTimeVal(e.time, t0, dT, left)
+		for dir in ['suspend', 'resume']:
+			list = []
+			for e in self.errorinfo[dir]:
+				type, tm, idx1, idx2 = e
+				tm = self.trimTimeVal(tm, t0, dT, left)
+				list.append((type, tm, idx1, idx2))
+			self.errorinfo[dir] = list
 	def normalizeTime(self, tZero):
 		# trim out any standby or freeze clock time
 		if(self.tSuspended != self.tResumed):
@@ -1100,7 +1236,7 @@ class Data:
 					if self.dmesg[p]['end'] > dev['start']:
 						dev['end'] = self.dmesg[p]['end']
 						break
-				vprint('%s (%s): callback didnt return' % (devname, phase))
+				sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
 	def deviceFilter(self, devicefilter):
 		for phase in self.phases:
 			list = self.dmesg[phase]['list']
@@ -1200,15 +1336,15 @@ class Data:
 				devlist.append(child)
 		return devlist
 	def printDetails(self):
-		vprint('Timeline Details:')
-		vprint('          test start: %f' % self.start)
-		vprint('kernel suspend start: %f' % self.tKernSus)
+		sysvals.vprint('Timeline Details:')
+		sysvals.vprint('          test start: %f' % self.start)
+		sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
 		for phase in self.phases:
 			dc = len(self.dmesg[phase]['list'])
-			vprint('    %16s: %f - %f (%d devices)' % (phase, \
+			sysvals.vprint('    %16s: %f - %f (%d devices)' % (phase, \
 				self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
-		vprint('   kernel resume end: %f' % self.tKernRes)
-		vprint('            test end: %f' % self.end)
+		sysvals.vprint('   kernel resume end: %f' % self.tKernRes)
+		sysvals.vprint('            test end: %f' % self.end)
 	def deviceChildrenAllPhases(self, devname):
 		devlist = []
 		for phase in self.phases:
@@ -1358,14 +1494,21 @@ class Data:
 				tres.append(t)
 		# process the events for suspend and resume
 		if len(proclist) > 0:
-			vprint('Process Execution:')
+			sysvals.vprint('Process Execution:')
 		for ps in proclist:
 			c = self.addProcessUsageEvent(ps, tsus)
 			if c > 0:
-				vprint('%25s (sus): %d' % (ps, c))
+				sysvals.vprint('%25s (sus): %d' % (ps, c))
 			c = self.addProcessUsageEvent(ps, tres)
 			if c > 0:
-				vprint('%25s (res): %d' % (ps, c))
+				sysvals.vprint('%25s (res): %d' % (ps, c))
+	def debugPrint(self):
+		for p in self.phases:
+			list = self.dmesg[p]['list']
+			for devname in list:
+				dev = list[devname]
+				if 'ftrace' in dev:
+					dev['ftrace'].debugPrint(' [%s]' % devname)
 
 # Class: DevFunction
 # Description:
@@ -1504,18 +1647,24 @@ class FTraceLine:
 			# something else (possibly a trace marker)
 			else:
 				self.name = m
+	def isCall(self):
+		return self.fcall and not self.freturn
+	def isReturn(self):
+		return self.freturn and not self.fcall
+	def isLeaf(self):
+		return self.fcall and self.freturn
 	def getDepth(self, str):
 		return len(str)/2
-	def debugPrint(self, dev=''):
-		if(self.freturn and self.fcall):
-			print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
-				self.depth, self.name, self.length*1000000))
-		elif(self.freturn):
-			print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
-				self.depth, self.name, self.length*1000000))
+	def debugPrint(self, info=''):
+		if self.isLeaf():
+			print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
+				self.depth, self.name, self.length*1000000, info))
+		elif self.freturn:
+			print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
+				self.depth, self.name, self.length*1000000, info))
 		else:
-			print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
-				self.depth, self.name, self.length*1000000))
+			print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
+				self.depth, self.name, self.length*1000000, info))
 	def startMarker(self):
 		# Is this the starting line of a suspend?
 		if not self.fevent:
@@ -1558,107 +1707,160 @@ class FTraceCallGraph:
 	depth = 0
 	pid = 0
 	name = ''
-	def __init__(self, pid):
+	partial = False
+	vfname = 'missing_function_name'
+	ignore = False
+	sv = 0
+	def __init__(self, pid, sv):
 		self.start = -1.0
 		self.end = -1.0
 		self.list = []
 		self.depth = 0
 		self.pid = pid
-	def addLine(self, line, debug=False):
+		self.sv = sv
+	def addLine(self, line):
 		# if this is already invalid, just leave
 		if(self.invalid):
-			return False
-		# invalidate on too much data or bad depth
-		if(len(self.list) >= 1000000 or self.depth < 0):
+			if(line.depth == 0 and line.freturn):
+				return 1
+			return 0
+		# invalidate on bad depth
+		if(self.depth < 0):
 			self.invalidate(line)
-			return False
+			return 0
+		# ignore data til we return to the current depth
+		if self.ignore:
+			if line.depth > self.depth:
+				return 0
+			else:
+				self.list[-1].freturn = True
+				self.list[-1].length = line.time - self.list[-1].time
+				self.ignore = False
+				# if this is a return at self.depth, no more work is needed
+				if line.depth == self.depth and line.isReturn():
+					if line.depth == 0:
+						self.end = line.time
+						return 1
+					return 0
 		# compare current depth with this lines pre-call depth
 		prelinedep = line.depth
-		if(line.freturn and not line.fcall):
+		if line.isReturn():
 			prelinedep += 1
 		last = 0
 		lasttime = line.time
-		virtualfname = 'missing_function_name'
 		if len(self.list) > 0:
 			last = self.list[-1]
 			lasttime = last.time
+			if last.isLeaf():
+				lasttime += last.length
 		# handle low misalignments by inserting returns
-		if prelinedep < self.depth:
-			if debug and last:
-				print '-------- task %d --------' % self.pid
-				last.debugPrint()
+		mismatch = prelinedep - self.depth
+		warning = self.sv.verbose and abs(mismatch) > 1
+		info = []
+		if mismatch < 0:
 			idx = 0
 			# add return calls to get the depth down
 			while prelinedep < self.depth:
-				if debug:
-					print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
 				self.depth -= 1
-				if idx == 0 and last and last.fcall and not last.freturn:
+				if idx == 0 and last and last.isCall():
 					# special case, turn last call into a leaf
 					last.depth = self.depth
 					last.freturn = True
 					last.length = line.time - last.time
-					if debug:
-						last.debugPrint()
+					if warning:
+						info.append(('[make leaf]', last))
 				else:
 					vline = FTraceLine(lasttime)
 					vline.depth = self.depth
-					vline.name = virtualfname
+					vline.name = self.vfname
 					vline.freturn = True
 					self.list.append(vline)
-					if debug:
-						vline.debugPrint()
+					if warning:
+						if idx == 0:
+							info.append(('', last))
+						info.append(('[add return]', vline))
 				idx += 1
-			if debug:
-				line.debugPrint()
-				print ''
+			if warning:
+				info.append(('', line))
 		# handle high misalignments by inserting calls
-		elif prelinedep > self.depth:
-			if debug and last:
-				print '-------- task %d --------' % self.pid
-				last.debugPrint()
+		elif mismatch > 0:
 			idx = 0
+			if warning:
+				info.append(('', last))
 			# add calls to get the depth up
 			while prelinedep > self.depth:
-				if debug:
-					print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
-				if idx == 0 and line.freturn and not line.fcall:
+				if idx == 0 and line.isReturn():
 					# special case, turn this return into a leaf
 					line.fcall = True
 					prelinedep -= 1
+					if warning:
+						info.append(('[make leaf]', line))
 				else:
 					vline = FTraceLine(lasttime)
 					vline.depth = self.depth
-					vline.name = virtualfname
+					vline.name = self.vfname
 					vline.fcall = True
-					if debug:
-						vline.debugPrint()
 					self.list.append(vline)
 					self.depth += 1
 					if not last:
 						self.start = vline.time
+					if warning:
+						info.append(('[add call]', vline))
 				idx += 1
-			if debug:
-				line.debugPrint()
-				print ''
+			if warning and ('[make leaf]', line) not in info:
+				info.append(('', line))
+		if warning:
+			print 'WARNING: ftrace data missing, corrections made:'
+			for i in info:
+				t, obj = i
+				if obj:
+					obj.debugPrint(t)
 		# process the call and set the new depth
-		if(line.fcall and not line.freturn):
-			self.depth += 1
-		elif(line.freturn and not line.fcall):
+		skipadd = False
+		md = self.sv.max_graph_depth
+		if line.isCall():
+			# ignore blacklisted/overdepth funcs
+			if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):
+				self.ignore = True
+			else:
+				self.depth += 1
+		elif line.isReturn():
 			self.depth -= 1
+			# remove blacklisted/overdepth/empty funcs that slipped through
+			if (last and last.isCall() and last.depth == line.depth) or \
+				(md and last and last.depth >= md) or \
+				(line.name in self.sv.cgblacklist):
+				while len(self.list) > 0 and self