PM / tools: analyze_suspend.py: update to v3.0

Update of analyze_suspend.py to v3.0

New features include back-2-back suspend testing, device filters to
reduce the html size, the inclusion of device_prepare and device_complete
callbacks, a usb topography list, and the ability to control USB
device autosuspend.

UI upgrades include a device detail window and mini-timeline, the addition
of a suspend_prepare and resume_complete phase to the timeline which includes
the associated device callbacks, automatic highlight of related callbacks,
and general color and name changes for better reability.

The new version relies on two trace point patches that are already in
the kernel:
        enable_trace_events_suspend_resume.patch
        enable_trace_events_device_pm_callback.patch

It has legacy support for older kernels without these trace events, but
when available the tool processes the ftrace output alone (dmesg has
been deprecated as a tool input, and is only gathered for convenience).

Link: https://01.org/suspendresume/downloads/analyzesuspend-v3.0
Signed-off-by: Todd Brandt <todd.e.brandt@intel.com>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

1 files changed, 2981 insertions, 836 deletions

diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index 4f2cc12dc7c7..93e1fd40f430 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -36,146 +36,392 @@
 #		 CONFIG_FUNCTION_TRACER=y
 #		 CONFIG_FUNCTION_GRAPH_TRACER=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 array
 import platform
-import datetime
+from datetime import datetime
 import struct
 
-# -- classes --
+# ----------------- CLASSES --------------------
 
+# Class: SystemValues
+# Description:
+#	 A global, single-instance container used to
+#	 store system values and test parameters
 class SystemValues:
-	testdir = "."
-	tpath = "/sys/kernel/debug/tracing/"
-	mempath = "/dev/mem"
-	powerfile = "/sys/power/state"
-	suspendmode = "mem"
-	prefix = "test"
-	teststamp = ""
-	dmesgfile = ""
-	ftracefile = ""
-	htmlfile = ""
+	version = 3.0
+	verbose = False
+	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'
+	]
+	modename = {
+		'freeze': 'Suspend-To-Idle (S0)',
+		'standby': 'Power-On Suspend (S1)',
+		'mem': 'Suspend-to-RAM (S3)',
+		'disk': 'Suspend-to-disk (S4)'
+	}
+	mempath = '/dev/mem'
+	powerfile = '/sys/power/state'
+	suspendmode = 'mem'
+	hostname = 'localhost'
+	prefix = 'test'
+	teststamp = ''
+	dmesgfile = ''
+	ftracefile = ''
+	htmlfile = ''
 	rtcwake = False
+	rtcwaketime = 10
+	rtcpath = ''
+	android = False
+	adb = 'adb'
+	devicefilter = []
+	stamp = 0
+	execcount = 1
+	x2delay = 0
+	usecallgraph = False
+	usetraceevents = False
+	usetraceeventsonly = False
+	notestrun = False
+	altdevname = dict()
+	postresumetime = 0
+	tracertypefmt = '# tracer: (?P<t>.*)'
+	firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
+	postresumefmt = '# post resume time (?P<t>[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>.*)$'
+	def __init__(self):
+		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
 	def setOutputFile(self):
-		if((self.htmlfile == "") and (self.dmesgfile != "")):
-			m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile)
+		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(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile)
+				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):
-		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"
+				self.htmlfile = m.group('name')+'.html'
+		if(self.htmlfile == ''):
+			self.htmlfile = 'output.html'
+	def initTestOutput(self, subdir):
+		if(not self.android):
+			self.prefix = self.hostname
+			v = open('/proc/version', 'r').read().strip()
+			kver = string.split(v)[2]
+		else:
+			self.prefix = 'android'
+			v = os.popen(self.adb+' shell cat /proc/version').read().strip()
+			kver = string.split(v)[2]
+		testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S')
+		if(subdir != "."):
+			self.testdir = subdir+"/"+testtime
+		else:
+			self.testdir = testtime
+		self.teststamp = \
+			'# '+testtime+' '+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)
+	def setDeviceFilter(self, devnames):
+		self.devicefilter = string.split(devnames)
+	def rtcWakeAlarm(self):
+		os.system('echo 0 > '+self.rtcpath+'/wakealarm')
+		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
+		os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
 
+sysvals = SystemValues()
+
+# 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 {
+#		root structure, started as dmesg & ftrace, but now only ftrace
+#		contents: times for suspend start/end, resume start/end, fwdata
+#		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 intradev trace events
+#				}
+#			}
+#		}
+#	}
+#
 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},
+	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
+	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
+	testnumber = 0
+	idstr = ''
+	html_device_id = 0
+	stamp = 0
+	outfile = ''
+	def __init__(self, num):
+		idchar = 'abcdefghijklmnopqrstuvwxyz'
+		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': "#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},
+								'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': "orange", 'order': 5},
+								'row': 0, 'color': '#FF9900', 'order': 6},
 			   '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}
+								'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()
-	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
+	def getStart(self):
+		return self.dmesg[self.phases[0]]['start']
+	def setStart(self, time):
+		self.start = time
+		self.dmesg[self.phases[0]]['start'] = time
+	def getEnd(self):
+		return self.dmesg[self.phases[-1]]['end']
+	def setEnd(self, time):
+		self.end = time
+		self.dmesg[self.phases[-1]]['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 addIntraDevTraceEvent(self, action, name, pid, time):
+		if(action == 'mutex_lock_try'):
+			color = 'red'
+		elif(action == 'mutex_lock_pass'):
+			color = 'green'
+		elif(action == 'mutex_unlock'):
+			color = 'blue'
+		else:
+			# create separate colors based on the name
+			v1 = len(name)*10 % 256
+			v2 = string.count(name, 'e')*100 % 256
+			v3 = ord(name[0])*20 % 256
+			color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3)
+		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']):
+					e = TraceEvent(action, name, color, time)
+					if('traceevents' not in d):
+						d['traceevents'] = []
+					d['traceevents'].append(e)
+					return d
+					break
+		return 0
+	def capIntraDevTraceEvent(self, action, name, 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']):
+					if('traceevents' not in d):
+						return
+					for e in d['traceevents']:
+						if(e.action == action and
+							e.name == name and not e.ready):
+							e.length = time - e.time
+							e.ready = True
+							break
+					return
+	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.end = self.trimTimeVal(self.end, t0, dT, left)
 		for phase in self.phases:
-			zero = tRes
-			if "suspend" in phase:
-				zero = tSus
 			p = self.dmesg[phase]
-			p['start'] -= zero
-			p['end'] -= zero
+			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'] -= zero
-				d['end'] -= zero
+				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 -= zero
-					cg.end -= zero
+					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 -= 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)
+						line.time = self.trimTimeVal(line.time, t0, dT, left)
+				if('traceevents' in d):
+					for e in d['traceevents']:
+						e.time = self.trimTimeVal(e.time, t0, dT, left)
+	def normalizeTime(self, tZero):
+		# first 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)
+		# shift the timeline so that tZero is the new 0
+		self.tSuspended -= tZero
+		self.tResumed -= tZero
+		self.start -= tZero
+		self.end -= tZero
+		for phase in self.phases:
+			p = self.dmesg[phase]
+			p['start'] -= tZero
+			p['end'] -= tZero
+			list = p['list']
+			for name in list:
+				d = list[name]
+				d['start'] -= tZero
+				d['end'] -= tZero
+				if('ftrace' in d):
+					cg = d['ftrace']
+					cg.start -= tZero
+					cg.end -= tZero
+					for line in cg.list:
+						line.time -= tZero
+				if('traceevents' in d):
+					for e in d['traceevents']:
+						e.time -= tZero
+	def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
+		for phase in self.phases:
+			self.dmesg[phase]['order'] += 1
+		self.html_device_id += 1
+		devid = '%s%d' % (self.idstr, self.html_device_id)
+		list = dict()
+		list[devname] = \
+			{'start': start, 'end': end, 'pid': 0, 'par': '',
+			'length': (end-start), 'row': 0, 'id': devid, 'drv': '' };
+		self.dmesg[phasename] = \
+			{'list': list, 'start': start, 'end': end,
+			'row': 0, 'color': color, 'order': 0}
+		self.phases = self.sortedPhases()
+	def newPhase(self, phasename, start, end, color, order):
+		if(order < 0):
+			order = len(self.phases)
+		for phase in self.phases[order:]:
+			self.dmesg[phase]['order'] += 1
+		if(order > 0):
+			p = self.phases[order-1]
+			self.dmesg[p]['end'] = start
+		if(order < len(self.phases)):
+			p = self.phases[order]
+			self.dmesg[p]['start'] = end
+		list = dict()
+		self.dmesg[phasename] = \
+			{'list': list, 'start': start, 'end': end,
+			'row': 0, 'color': color, 'order': order}
+		self.phases = self.sortedPhases()
+	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):
@@ -197,59 +443,180 @@ class Data:
 			dev = phaselist[devname]
 			if(dev['end'] < 0):
 				dev['end'] = end
-				self.vprint("%s (%s): callback didn't return" % (devname, phase))
+				vprint('%s (%s): callback didnt return' % (devname, phase))
+	def deviceFilter(self, devicefilter):
+		# remove all by the relatives of the filter devnames
+		filter = []
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			for name in devicefilter:
+				dev = name
+				while(dev in list):
+					if(dev not in filter):
+						filter.append(dev)
+					dev = list[dev]['par']
+				children = self.deviceDescendants(name, phase)
+				for dev in children:
+					if(dev not in filter):
+						filter.append(dev)
+		for phase in self.phases:
+			list = self.dmesg[phase]['list']
+			rmlist = []
+			for name in list:
+				pid = list[name]['pid']
+				if(name not in filter and pid >= 0):
+					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, 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
+			self.fixupInitcalls(phase, self.getEnd())
+	def newActionGlobal(self, name, start, end):
+		# which phase is this device callback or action "in"
+		targetphase = "none"
+		overlap = 0.0
+		for phase in self.phases:
+			pstart = self.dmesg[phase]['start']
+			pend = self.dmesg[phase]['end']
+			o = max(0, min(end, pend) - max(start, pstart))
+			if(o > overlap):
+				targetphase = phase
+				overlap = o
+		if targetphase in self.phases:
+			self.newAction(targetphase, name, -1, '', start, end, '')
+			return True
+		return False
+	def newAction(self, phase, name, pid, parent, start, end, drv):
+		# new device callback for a specific phase
+		self.html_device_id += 1
+		devid = '%s%d' % (self.idstr, self.html_device_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 }
+					  'length': length, 'row': 0, 'id': devid, 'drv': drv }
 	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'])
+		list = self.dmesg[phase]['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']
+		pdev = ''
+		pdevid = ''
+		list = self.dmesg[phase]['list']
+		if devname in list:
+			pdev = list[devname]['par']
+		if pdev in list:
+			return list[pdev]['id']
 		return pdev
-	def deviceChildrenIDs(self, devname, phase):
+	def deviceChildren(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)
+		list = self.dmesg[phase]['list']
+		for child in list:
+			if(list[child]['par'] == devname):
+				devlist.append(child)
+		return devlist
+	def deviceDescendants(self, devname, phase):
+		children = self.deviceChildren(devname, phase)
+		family = children
+		for child in children:
+			family += self.deviceDescendants(child, phase)
+		return family
+	def deviceChildrenIDs(self, devname, phase):
+		devlist = self.deviceChildren(devname, phase)
 		return self.deviceIDs(devlist, phase)
-
+	def printDetails(self):
+		vprint('          test start: %f' % self.start)
+		for phase in self.phases:
+			dc = len(self.dmesg[phase]['list'])
+			vprint('    %16s: %f - %f (%d devices)' % (phase, \
+				self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
+		vprint('            test end: %f' % self.end)
+	def masterTopology(self, name, list, depth):
+		node = DeviceNode(name, depth)
+		for cname in list:
+			clist = self.deviceChildren(cname, 'resume')
+			cnode = self.masterTopology(cname, clist, depth+1)
+			node.children.append(cnode)
+		return node
+	def printTopology(self, node):
+		html = ''
+		if node.name:
+			info = ''
+			drv = ''
+			for phase in self.phases:
+				list = self.dmesg[phase]['list']
+				if node.name in list:
+					s = list[node.name]['start']
+					e = list[node.name]['end']
+					if list[node.name]['drv']:
+						drv = ' {'+list[node.name]['drv']+'}'
+					info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
+			html += '<li><b>'+node.name+drv+'</b>'
+			if info:
+				html += '<ul>'+info+'</ul>'
+			html += '</li>'
+		if len(node.children) > 0:
+			html += '<ul>'
+			for cnode in node.children:
+				html += self.printTopology(cnode)
+			html += '</ul>'
+		return html
+	def rootDeviceList(self):
+		# list of devices graphed
+		real = []
+		for phase in self.dmesg:
+			list = self.dmesg[phase]['list']
+			for dev in list:
+				if list[dev]['pid'] >= 0 and dev not in real:
+					real.append(dev)
+		# list of top-most root devices
+		rootlist = []
+		for phase in self.dmesg:
+			list = self.dmesg[phase]['list']
+			for dev in list:
+				pdev = list[dev]['par']
+				if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
+					continue
+				if pdev and pdev not in real and pdev not in rootlist:
+					rootlist.append(pdev)
+		return rootlist
+	def deviceTopology(self):
+		rootlist = self.rootDeviceList()
+		master = self.masterTopology('', rootlist, 0)
+		return self.printTopology(master)
+
+# Class: TraceEvent
+# Description:
+#	 A container for trace event data found in the ftrace file
+class TraceEvent:
+	ready = False
+	name = ''
+	time = 0.0
+	color = '#FFFFFF'
+	length = 0.0
+	action = ''
+	def __init__(self, a, n, c, t):
+		self.action = a
+		self.name = n
+		self.color = c
+		self.time = t
+
+# Class: FTraceLine
+# Description:
+#	 A container for a single line of ftrace data. There are six basic types:
+#		 callgraph line:
+#			  call: "  dpm_run_callback() {"
+#			return: "  }"
+#			  leaf: " dpm_run_callback();"
+#		 trace event:
+#			 tracing_mark_write: SUSPEND START or RESUME COMPLETE
+#			 suspend_resume: phase or custom exec block data
+#			 device_pm_callback: device callback info
 class FTraceLine:
 	time = 0.0
 	length = 0.0
@@ -257,20 +624,33 @@ class FTraceLine:
 	freturn = False
 	fevent = False
 	depth = 0
-	name = ""
+	name = ''
+	type = ''
 	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")
+		# is this a trace event
+		if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
+			if(d == 'traceevent'):
+				# nop format trace event
+				msg = m
+			else:
+				# function_graph format trace event
+				em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
+				msg = em.group('msg')
+
+			emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
+			if(emm):
+				self.name = emm.group('msg')
+				self.type = emm.group('call')
+			else:
+				self.name = 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)
+		match = re.match('^(?P<d> *)(?P<o>.*)$', m)
 		if(not match):
 			return
 		self.depth = self.getDepth(match.group('d'))
@@ -280,7 +660,7 @@ class FTraceLine:
 			self.freturn = True
 			if(len(m) > 1):
 				# includes comment with function name
-				match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m)
+				match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
 				if(match):
 					self.name = match.group('n')
 		# function call
@@ -288,13 +668,13 @@ class FTraceLine:
 			self.fcall = True
 			# function call with children
 			if(m[-1] == '{'):
-				match = re.match(r"^(?P<n>.*) *\(.*", m)
+				match = re.match('^(?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)
+				match = re.match('^(?P<n>.*) *\(.*', m)
 				if(match):
 					self.name = match.group('n')
 			# something else (possibly a trace marker)
@@ -302,7 +682,23 @@ class FTraceLine:
 				self.name = m
 	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))
+		else:
+			print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
+				self.depth, self.name, self.length*1000000))
 
+# Class: FTraceCallGraph
+# Description:
+#	 A container for the ftrace callgraph of a single recursive function.
+#	 This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
+#	 Each instance is tied to a single device in a single phase, and is
+#	 comprised of an ordered list of FTraceLine objects
 class FTraceCallGraph:
 	start = -1.0
 	end = -1.0
@@ -327,24 +723,53 @@ class FTraceCallGraph:
 		if(not self.invalid):
 			self.setDepth(line)
 		if(line.depth == 0 and line.freturn):
+			if(self.start < 0):
+				self.start = line.time
 			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
+			if(len(self.list) > 0):
+				first = self.list[0]
+				self.list = []
+				self.list.append(first)
+			self.invalid = True
+			if(not match):
+				return False
+			id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
+			window = '(%f - %f)' % (self.start, line.time)
+			if(self.depth < 0):
+				print('Too much data for '+id+\
+					' (buffer overflow), ignoring this callback')
+			else:
+				print('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 slice(self, t0, tN):
+		minicg = FTraceCallGraph()
+		count = -1
+		firstdepth = 0
+		for l in self.list:
+			if(l.time < t0 or l.time > tN):
+				continue
+			if(count < 0):
+				if(not l.fcall or l.name == 'dev_driver_string'):
+					continue
+				firstdepth = l.depth
+				count = 0
+			l.depth -= firstdepth
+			minicg.addLine(l, 0)
+			if((count == 0 and l.freturn and l.fcall) or
+				(count > 0 and l.depth <= 0)):
+				break
+			count += 1
+		return minicg
 	def sanityCheck(self):
 		stack = dict()
 		cnt = 0
@@ -353,7 +778,7 @@ class FTraceCallGraph:
 				stack[l.depth] = l
 				cnt += 1
 			elif(l.freturn and not l.fcall):
-				if(not stack[l.depth]):
+				if(l.depth not in stack):
 					return False
 				stack[l.depth].length = l.length
 				stack[l.depth] = 0
@@ -363,40 +788,51 @@ class FTraceCallGraph:
 			return True
 		return False
 	def debugPrint(self, filename):
-		if(filename == "stdout"):
-			print("[%f - %f]") % (self.start, self.end)
+		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))
+					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))
+					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(" ")
+					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))
+					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))
+					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.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \
+						l.depth, l.name, l.length*1000000))
 			fp.close()
 
+# Class: Timeline
+# Description:
+#	 A container for a suspend/resume html timeline. In older versions
+#	 of the script there were multiple timelines, but in the latest
+#	 there is only one.
 class Timeline:
 	html = {}
-	scaleH = 0.0 # height of the timescale row as a percent of the timeline height
+	scaleH = 0.0 # height of the 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': ""
+			'timeline': '',
+			'legend': '',
+			'scale': ''
 		}
 	def setRows(self, rows):
 		self.maxrows = int(rows)
@@ -407,104 +843,261 @@ class Timeline:
 			r = 1.0
 		self.rowH = (100.0 - self.scaleH)/r
 
-# -- global objects --
+# Class: TestRun
+# Description:
+#	 A container for a suspend/resume test run. This is necessary as
+#	 there could be more than one, and they need to be separate.
+class TestRun:
+	ftrace_line_fmt_fg = \
+		'^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
+		' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
+		'[ +!]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)'
+	ftrace_line_fmt_nop = \
+		' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
+		'(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
+		'(?P<msg>.*)'
+	ftrace_line_fmt = ftrace_line_fmt_nop
+	cgformat = False
+	ftemp = dict()
+	ttemp = dict()
+	inthepipe = False
+	tracertype = ''
+	data = 0
+	def __init__(self, dataobj):
+		self.data = dataobj
+		self.ftemp = dict()
+		self.ttemp = dict()
+	def isReady(self):
+		if(tracertype == '' or not data):
+			return False
+		return True
+	def setTracerType(self, tracer):
+		self.tracertype = tracer
+		if(tracer == 'function_graph'):
+			self.cgformat = True
+			self.ftrace_line_fmt = self.ftrace_line_fmt_fg
+		elif(tracer == 'nop'):
+			self.ftrace_line_fmt = self.ftrace_line_fmt_nop
+		else:
+			doError('Invalid tracer format: [%s]' % tracer, False)
 
-sysvals = SystemValues()
-data = Data()
+# ----------------- FUNCTIONS --------------------
 
-# -- functions --
+# Function: vprint
+# Description:
+#	 verbose print (prints only with -verbose option)
+# Arguments:
+#	 msg: the debug/log message to print
+def vprint(msg):
+	global sysvals
+	if(sysvals.verbose):
+		print(msg)
 
 # Function: initFtrace
 # Description:
-#	 Configure ftrace to capture a function trace during suspend/resume
+#	 Configure ftrace to use trace events and/or a callgraph
 def 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")
+	tp = sysvals.tpath
+	cf = 'dpm_run_callback'
+	if(sysvals.usetraceeventsonly):
+		cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback'
+	if(sysvals.usecallgraph or sysvals.usetraceevents):
+		print('INITIALIZING FTRACE...')
+		# turn trace off
+		os.system('echo 0 > '+tp+'tracing_on')
+		# set the trace clock to global
+		os.system('echo global > '+tp+'trace_clock')
+		# set trace buffer to a huge value
+		os.system('echo nop > '+tp+'current_tracer')
+		os.system('echo 100000 > '+tp+'buffer_size_kb')
+		# initialize the callgraph trace, unless this is an x2 run
+		if(sysvals.usecallgraph and sysvals.execcount == 1):
+			# set trace type
+			os.system('echo func