PM / tools: new tool for suspend/resume performance optimization

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.

References: https://01.org/suspendresume
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, 1446 insertions, 0 deletions

diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
new file mode 100755
index 00000000000..4f2cc12dc7c
--- /dev/null
+++ b/scripts/analyze_suspend.py
@@ -0,0 +1,1446 @@
+#!/usr/bin/python
+#
+# Tool for analyzing suspend/resume timing
+# Copyright (c) 2013, Intel Corporation.
+#
+# This program is free software; you can redistribute it and/or modify it
+# under the terms and conditions of the GNU General Public License,
+# version 2, as published by the Free Software Foundation.
+#
+# This program is distributed in the hope it will be useful, but WITHOUT
+# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+# FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
+# more details.
+#
+# You should have received a copy of the GNU General Public License along with
+# this program; if not, write to the Free Software Foundation, Inc.,
+# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
+#
+# Authors:
+#	 Todd Brandt <todd.e.brandt@linux.intel.com>
+#
+# Description:
+#	 This tool is designed to assist kernel and OS developers in optimizing
+#	 their linux stack's suspend/resume time. Using a kernel image built
+#	 with a few extra options enabled, the tool will execute a suspend and
+#	 will capture dmesg and ftrace data until resume is complete. This data
+#	 is transformed into a device timeline and a callgraph to give a quick
+#	 and detailed view of which devices and callbacks are taking the most
+#	 time in suspend/resume. The output is a single html file which can be
+#	 viewed in firefox or chrome.
+#
+#	 The following kernel build options are required:
+#		 CONFIG_PM_DEBUG=y
+#		 CONFIG_PM_SLEEP_DEBUG=y
+#		 CONFIG_FTRACE=y
+#		 CONFIG_FUNCTION_TRACER=y
+#		 CONFIG_FUNCTION_GRAPH_TRACER=y
+#
+#	 The following additional kernel parameters are required:
+#		 (e.g. in file /etc/default/grub)
+#		 GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
+#
+
+import sys
+import time
+import os
+import string
+import re
+import array
+import platform
+import datetime
+import struct
+
+# -- classes --
+
+class SystemValues:
+	testdir = "."
+	tpath = "/sys/kernel/debug/tracing/"
+	mempath = "/dev/mem"
+	powerfile = "/sys/power/state"
+	suspendmode = "mem"
+	prefix = "test"
+	teststamp = ""
+	dmesgfile = ""
+	ftracefile = ""
+	htmlfile = ""
+	rtcwake = False
+	def setOutputFile(self):
+		if((self.htmlfile == "") and (self.dmesgfile != "")):
+			m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile)
+			if(m):
+				self.htmlfile = m.group("name")+".html"
+		if((self.htmlfile == "") and (self.ftracefile != "")):
+			m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile)
+			if(m):
+				self.htmlfile = m.group("name")+".html"
+		if(self.htmlfile == ""):
+			self.htmlfile = "output.html"
+	def initTestOutput(self):
+		hostname = platform.node()
+		if(hostname != ""):
+			self.prefix = hostname
+		v = os.popen("cat /proc/version").read().strip()
+		kver = string.split(v)[2]
+		self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip()
+		self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver
+		self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt"
+		self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt"
+		self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html"
+		os.mkdir(self.testdir)
+
+class Data:
+	altdevname = dict()
+	usedmesg = False
+	useftrace = False
+	notestrun = False
+	verbose = False
+	phases = []
+	dmesg = {} # root data structure
+	start = 0.0
+	end = 0.0
+	stamp = {'time': "", 'host': "", 'mode': ""}
+	id = 0
+	tSuspended = 0.0
+	fwValid = False
+	fwSuspend = 0
+	fwResume = 0
+	def initialize(self):
+		self.dmesg = { # dmesg log data
+			'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "#CCFFCC", 'order': 0},
+			  'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "green", 'order': 1},
+			  'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "#00FFFF", 'order': 2},
+				'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "blue", 'order': 3},
+				 'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "red", 'order': 4},
+			   'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "orange", 'order': 5},
+			   'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "yellow", 'order': 6},
+			 'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
+								'row': 0, 'color': "#FFFFCC", 'order': 7}
+		}
+		self.phases = self.sortedPhases()
+	def normalizeTime(self):
+		tSus = tRes = self.tSuspended
+		if self.fwValid:
+			tSus -= -self.fwSuspend / 1000000000.0
+			tRes -= self.fwResume / 1000000000.0
+		self.tSuspended = 0.0
+		self.start -= tSus
+		self.end -= tRes
+		for phase in self.phases:
+			zero = tRes
+			if "suspend" in phase:
+				zero = tSus
+			p = self.dmesg[phase]
+			p['start'] -= zero
+			p['end'] -= zero
+			list = p['list']
+			for name in list:
+				d = list[name]
+				d['start'] -= zero
+				d['end'] -= zero
+				if('ftrace' in d):
+					cg = d['ftrace']
+					cg.start -= zero
+					cg.end -= zero
+					for line in cg.list:
+						line.time -= zero
+		if self.fwValid:
+			fws = -self.fwSuspend / 1000000000.0
+			fwr = self.fwResume / 1000000000.0
+			list = dict()
+			self.id += 1
+			devid = "dc%d" % self.id
+			list["firmware-suspend"] = \
+				{'start': fws, 'end': 0, 'pid': 0, 'par': "",
+				'length': -fws, 'row': 0, 'id': devid };
+			self.id += 1
+			devid = "dc%d" % self.id
+			list["firmware-resume"] = \
+				{'start': 0, 'end': fwr, 'pid': 0, 'par': "",
+				'length': fwr, 'row': 0, 'id': devid };
+			self.dmesg['BIOS'] = \
+				{'list': list, 'start': fws, 'end': fwr,
+				'row': 0, 'color': "purple", 'order': 4}
+			self.dmesg['resume_cpu']['order'] += 1
+			self.dmesg['resume_noirq']['order'] += 1
+			self.dmesg['resume_early']['order'] += 1
+			self.dmesg['resume_general']['order'] += 1
+			self.phases = self.sortedPhases()
+	def vprint(self, msg):
+		if(self.verbose):
+			print(msg)
+	def dmesgSortVal(self, phase):
+		return self.dmesg[phase]['order']
+	def sortedPhases(self):
+		return sorted(self.dmesg, key=self.dmesgSortVal)
+	def sortedDevices(self, phase):
+		list = self.dmesg[phase]['list']
+		slist = []
+		tmp = dict()
+		for devname in list:
+			dev = list[devname]
+			tmp[dev['start']] = devname
+		for t in sorted(tmp):
+			slist.append(tmp[t])
+		return slist
+	def fixupInitcalls(self, phase, end):
+		# if any calls never returned, clip them at system resume end
+		phaselist = self.dmesg[phase]['list']
+		for devname in phaselist:
+			dev = phaselist[devname]
+			if(dev['end'] < 0):
+				dev['end'] = end
+				self.vprint("%s (%s): callback didn't return" % (devname, phase))
+	def fixupInitcallsThatDidntReturn(self):
+		# if any calls never returned, clip them at system resume end
+		for phase in self.phases:
+			self.fixupInitcalls(phase, self.dmesg['resume_general']['end'])
+			if(phase == "resume_general"):
+				break
+	def newAction(self, phase, name, pid, parent, start, end):
+		self.id += 1
+		devid = "dc%d" % self.id
+		list = self.dmesg[phase]['list']
+		length = -1.0
+		if(start >= 0 and end >= 0):
+			length = end - start
+		list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
+					  'length': length, 'row': 0, 'id': devid }
+	def deviceIDs(self, devlist, phase):
+		idlist = []
+		for p in self.phases:
+			if(p[0] != phase[0]):
+				continue
+			list = data.dmesg[p]['list']
+			for devname in list:
+				if devname in devlist:
+					idlist.append(list[devname]['id'])
+		return idlist
+	def deviceParentID(self, devname, phase):
+		pdev = ""
+		pdevid = ""
+		for p in self.phases:
+			if(p[0] != phase[0]):
+				continue
+			list = data.dmesg[p]['list']
+			if devname in list:
+				pdev = list[devname]['par']
+		for p in self.phases:
+			if(p[0] != phase[0]):
+				continue
+			list = data.dmesg[p]['list']
+			if pdev in list:
+				return list[pdev]['id']
+		return pdev
+	def deviceChildrenIDs(self, devname, phase):
+		devlist = []
+		for p in self.phases:
+			if(p[0] != phase[0]):
+				continue
+			list = data.dmesg[p]['list']
+			for child in list:
+				if(list[child]['par'] == devname):
+					devlist.append(child)
+		return self.deviceIDs(devlist, phase)
+
+class FTraceLine:
+	time = 0.0
+	length = 0.0
+	fcall = False
+	freturn = False
+	fevent = False
+	depth = 0
+	name = ""
+	def __init__(self, t, m, d):
+		self.time = float(t)
+		# check to see if this is a trace event
+		em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m)
+		if(em):
+			self.name = em.group("msg")
+			self.fevent = True
+			return
+		# convert the duration to seconds
+		if(d):
+			self.length = float(d)/1000000
+		# the indentation determines the depth
+		match = re.match(r"^(?P<d> *)(?P<o>.*)$", m)
+		if(not match):
+			return
+		self.depth = self.getDepth(match.group('d'))
+		m = match.group('o')
+		# function return
+		if(m[0] == '}'):
+			self.freturn = True
+			if(len(m) > 1):
+				# includes comment with function name
+				match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m)
+				if(match):
+					self.name = match.group('n')
+		# function call
+		else:
+			self.fcall = True
+			# function call with children
+			if(m[-1] == '{'):
+				match = re.match(r"^(?P<n>.*) *\(.*", m)
+				if(match):
+					self.name = match.group('n')
+			# function call with no children (leaf)
+			elif(m[-1] == ';'):
+				self.freturn = True
+				match = re.match(r"^(?P<n>.*) *\(.*", m)
+				if(match):
+					self.name = match.group('n')
+			# something else (possibly a trace marker)
+			else:
+				self.name = m
+	def getDepth(self, str):
+		return len(str)/2
+
+class FTraceCallGraph:
+	start = -1.0
+	end = -1.0
+	list = []
+	invalid = False
+	depth = 0
+	def __init__(self):
+		self.start = -1.0
+		self.end = -1.0
+		self.list = []
+		self.depth = 0
+	def setDepth(self, line):
+		if(line.fcall and not line.freturn):
+			line.depth = self.depth
+			self.depth += 1
+		elif(line.freturn and not line.fcall):
+			self.depth -= 1
+			line.depth = self.depth
+		else:
+			line.depth = self.depth
+	def addLine(self, line, match):
+		if(not self.invalid):
+			self.setDepth(line)
+		if(line.depth == 0 and line.freturn):
+			self.end = line.time
+			self.list.append(line)
+			return True
+		if(self.invalid):
+			return False
+		if(len(self.list) >= 1000000 or self.depth < 0):
+		   first = self.list[0]
+		   self.list = []
+		   self.list.append(first)
+		   self.invalid = True
+		   id = "task %s cpu %s" % (match.group("pid"), match.group("cpu"))
+		   window = "(%f - %f)" % (self.start, line.time)
+		   data.vprint("Too much data for "+id+" "+window+", ignoring this callback")
+		   return False
+		self.list.append(line)
+		if(self.start < 0):
+			self.start = line.time
+		return False
+	def sanityCheck(self):
+		stack = dict()
+		cnt = 0
+		for l in self.list:
+			if(l.fcall and not l.freturn):
+				stack[l.depth] = l
+				cnt += 1
+			elif(l.freturn and not l.fcall):
+				if(not stack[l.depth]):
+					return False
+				stack[l.depth].length = l.length
+				stack[l.depth] = 0
+				l.length = 0
+				cnt -= 1
+		if(cnt == 0):
+			return True
+		return False
+	def debugPrint(self, filename):
+		if(filename == "stdout"):
+			print("[%f - %f]") % (self.start, self.end)
+			for l in self.list:
+				if(l.freturn and l.fcall):
+					print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
+				elif(l.freturn):
+					print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
+				else:
+					print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
+			print(" ")
+		else:
+			fp = open(filename, 'w')
+			print(filename)
+			for l in self.list:
+				if(l.freturn and l.fcall):
+					fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
+				elif(l.freturn):
+					fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
+				else:
+					fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
+			fp.close()
+
+class Timeline:
+	html = {}
+	scaleH = 0.0 # height of the timescale row as a percent of the timeline height
+	rowH = 0.0 # height of each row in percent of the timeline height
+	row_height_pixels = 30
+	maxrows = 0
+	height = 0
+	def __init__(self):
+		self.html = {
+			'timeline': "",
+			'legend': "",
+			'scale': ""
+		}
+	def setRows(self, rows):
+		self.maxrows = int(rows)
+		self.scaleH = 100.0/float(self.maxrows)
+		self.height = self.maxrows*self.row_height_pixels
+		r = float(self.maxrows - 1)
+		if(r < 1.0):
+			r = 1.0
+		self.rowH = (100.0 - self.scaleH)/r
+
+# -- global objects --
+
+sysvals = SystemValues()
+data = Data()
+
+# -- functions --
+
+# Function: initFtrace
+# Description:
+#	 Configure ftrace to capture a function trace during suspend/resume
+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")
+
+# Function: verifyFtrace
+# Description:
+#	 Check that ftrace is working on the system
+def verifyFtrace():
+	global sysvals
+	files = ["available_filter_functions", "buffer_size_kb",
+			 "current_tracer", "set_ftrace_filter",
+			 "trace", "trace_marker"]
+	for f in files:
+		if(os.path.exists(sysvals.tpath+f) == False):
+			return False
+	return True
+
+def parseStamp(line):
+	global data, sysvals
+	stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\
+				"(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\
+				" (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$"
+	m = re.match(stampfmt, line)
+	if(m):
+		dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")),
+			int(m.group("d")), int(m.group("H")), int(m.group("M")),
+			int(m.group("S")))
+		data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p")
+		data.stamp['host'] = m.group("host")
+		data.stamp['mode'] = m.group("mode")
+		data.stamp['kernel'] = m.group("kernel")
+		sysvals.suspendmode = data.stamp['mode']
+
+# Function: analyzeTraceLog
+# Description:
+#	 Analyse an ftrace log output file generated from this app during
+#	 the execution phase. Create an "ftrace" structure in memory for
+#	 subsequent formatting in the html output file
+def analyzeTraceLog():
+	global sysvals, data
+
+	# the ftrace data is tied to the dmesg data
+	if(not data.usedmesg):
+		return
+
+	# read through the ftrace and parse the data
+	data.vprint("Analyzing the ftrace data...")
+	ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\
+					   " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\
+					   "[ +!]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)"
+	ftemp = dict()
+	inthepipe = False
+	tf = open(sysvals.ftracefile, 'r')
+	count = 0
+	for line in tf:
+		count = count + 1
+		# grab the time stamp if it's valid
+		if(count == 1):
+			parseStamp(line)
+			continue
+		# parse only valid lines
+		m = re.match(ftrace_line_fmt, line)
+		if(not m):
+			continue
+		m_time = m.group("time")
+		m_pid = m.group("pid")
+		m_msg = m.group("msg")
+		m_dur = m.group("dur")
+		if(m_time and m_pid and m_msg):
+			t = FTraceLine(m_time, m_msg, m_dur)
+			pid = int(m_pid)
+		else:
+			continue
+		# the line should be a call, return, or event
+		if(not t.fcall and not t.freturn and not t.fevent):
+			continue
+		# only parse the ftrace data during suspend/resume
+		if(not inthepipe):
+			# look for the suspend start marker
+			if(t.fevent):
+				if(t.name == "SUSPEND START"):
+					data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count))
+					inthepipe = True
+				continue
+		else:
+			# look for the resume end marker
+			if(t.fevent):
+				if(t.name == "RESUME COMPLETE"):
+					data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count))
+					inthepipe = False
+					break
+				continue
+			# create a callgraph object for the data
+			if(pid not in ftemp):
+				ftemp[pid] = FTraceCallGraph()
+			# when the call is finished, see which device matches it
+			if(ftemp[pid].addLine(t, m)):
+				if(not ftemp[pid].sanityCheck()):
+					id = "task %s cpu %s" % (pid, m.group("cpu"))
+					data.vprint("Sanity check failed for "+id+", ignoring this callback")
+					continue
+				callstart = ftemp[pid].start
+				callend = ftemp[pid].end
+				for p in data.phases:
+					if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']):
+						list = data.dmesg[p]['list']
+						for devname in list:
+							dev = list[devname]
+							if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']):
+								data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid))
+								dev['ftrace'] = ftemp[pid]
+						break
+				ftemp[pid] = FTraceCallGraph()
+	tf.close()
+
+# Function: sortKernelLog
+# Description:
+#	 The dmesg output log sometimes comes with with lines that have
+#	 timestamps out of order. This could cause issues since a call
+#	 could accidentally end up in the wrong phase
+def sortKernelLog():
+	global sysvals, data
+	lf = open(sysvals.dmesgfile, 'r')
+	dmesglist = []
+	count = 0
+	for line in lf:
+		line = line.replace("\r\n", "")
+		if(count == 0):
+			parseStamp(line)
+		elif(count == 1):
+			m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line)
+			if(m):
+				data.fwSuspend = int(m.group("s"))
+				data.fwResume = int(m.group("r"))
+				if(data.fwSuspend > 0 or data.fwResume > 0):
+					data.fwValid = True
+		if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)):
+			dmesglist.append(line)
+		count += 1
+	lf.close()
+	last = ""
+
+	# fix lines with the same time stamp and function with the call and return swapped
+	for line in dmesglist:
+		mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling  (?P<f>.*)\+ @ .*, parent: .*", line)
+		mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last)
+		if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))):
+			i = dmesglist.index(last)
+			j = dmesglist.index(line)
+			dmesglist[i] = line
+			dmesglist[j] = last
+		last = line
+	return dmesglist
+
+# Function: analyzeKernelLog
+# Description:
+#	 Analyse a dmesg log output file generated from this app during
+#	 the execution phase. Create a set of device structures in memory
+#	 for subsequent formatting in the html output file
+def analyzeKernelLog():
+	global sysvals, data
+
+	print("PROCESSING DATA")
+	data.vprint("Analyzing the dmesg data...")
+	if(os.path.exists(sysvals.dmesgfile) == False):
+		print("ERROR: %s doesn't exist") % sysvals.dmesgfile
+		return False
+
+	lf = sortKernelLog()
+	phase = "suspend_runtime"
+
+	dm = {
+		'suspend_general': r"PM: Syncing filesystems.*",
+		  'suspend_early': r"PM: suspend of devices complete after.*",
+		  'suspend_noirq': r"PM: late suspend of devices complete after.*",
+		    'suspend_cpu': r"PM: noirq suspend of devices complete after.*",
+		     'resume_cpu': r"ACPI: Low-level resume complete.*",
+		   'resume_noirq': r"ACPI: Waking up from system sleep state.*",
+		   'resume_early': r"PM: noirq resume of devices complete after.*",
+		 'resume_general': r"PM: early resume of devices complete after.*",
+		'resume_complete': r".*Restarting tasks \.\.\..*",
+	}
+	if(sysvals.suspendmode == "standby"):
+		dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
+	elif(sysvals.suspendmode == "disk"):
+		dm['suspend_early'] = r"PM: freeze of devices complete after.*"
+		dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*"
+		dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*"
+		dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
+		dm['resume_early'] = r"PM: noirq restore of devices complete after.*"
+		dm['resume_general'] = r"PM: early restore of devices complete after.*"
+
+	action_start = 0.0
+	for line in lf:
+		# -- preprocessing --
+		# parse each dmesg line into the time and message
+		m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)
+		if(m):
+			ktime = float(m.group("ktime"))
+			msg = m.group("msg")
+		else:
+			print line
+			continue
+
+		# -- phase changes --
+		# suspend_general start
+		if(re.match(dm['suspend_general'], msg)):
+			phase = "suspend_general"
+			data.dmesg[phase]['start'] = ktime
+			data.start = ktime
+			# action start: syncing filesystems
+			action_start = ktime
+		# suspend_early start
+		elif(re.match(dm['suspend_early'], msg)):
+			data.dmesg["suspend_general"]['end'] = ktime
+			phase = "suspend_early"
+			data.dmesg[phase]['start'] = ktime
+		# suspend_noirq start
+		elif(re.match(dm['suspend_noirq'], msg)):
+			data.dmesg["suspend_early"]['end'] = ktime
+			phase = "suspend_noirq"
+			data.dmesg[phase]['start'] = ktime
+		# suspend_cpu start
+		elif(re.match(dm['suspend_cpu'], msg)):
+			data.dmesg["suspend_noirq"]['end'] = ktime
+			phase = "suspend_cpu"
+			data.dmesg[phase]['start'] = ktime
+		# resume_cpu start
+		elif(re.match(dm['resume_cpu'], msg)):
+			data.tSuspended = ktime
+			data.dmesg["suspend_cpu"]['end'] = ktime
+			phase = "resume_cpu"
+			data.dmesg[phase]['start'] = ktime
+		# resume_noirq start
+		elif(re.match(dm['resume_noirq'], msg)):
+			data.dmesg["resume_cpu"]['end'] = ktime
+			phase = "resume_noirq"
+			data.dmesg[phase]['start'] = ktime
+			# action end: ACPI resume
+			data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime)
+		# resume_early start
+		elif(re.match(dm['resume_early'], msg)):
+			data.dmesg["resume_noirq"]['end'] = ktime
+			phase = "resume_early"
+			data.dmesg[phase]['start'] = ktime
+		# resume_general start
+		elif(re.match(dm['resume_general'], msg)):
+			data.dmesg["resume_early"]['end'] = ktime
+			phase = "resume_general"
+			data.dmesg[phase]['start'] = ktime
+		# resume complete start
+		elif(re.match(dm['resume_complete'], msg)):
+			data.dmesg["resume_general"]['end'] = ktime
+			data.end = ktime
+			phase = "resume_runtime"
+			break
+
+		# -- device callbacks --
+		if(phase in data.phases):
+			# device init call
+			if(re.match(r"calling  (?P<f>.*)\+ @ .*, parent: .*", msg)):
+				sm = re.match(r"calling  (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg);
+				f = sm.group("f")
+				n = sm.group("n")
+				p = sm.group("p")
+				if(f and n and p):
+					data.newAction(phase, f, int(n), p, ktime, -1)
+			# device init return
+			elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)):
+				sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg);
+				f = sm.group("f")
+				t = sm.group("t")
+				list = data.dmesg[phase]['list']
+				if(f in list):
+					dev = list[f]
+					dev['length'] = int(t)
+					dev['end'] = ktime
+					data.vprint("%15s [%f - %f] %s(%d) %s" %
+						(phase, dev['start'], dev['end'], f, dev['pid'], dev['par']))
+
+		# -- phase specific actions --
+		if(phase == "suspend_general"):
+			if(re.match(r"PM: Preparing system for mem sleep.*", msg)):
+				data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime)
+			elif(re.match(r"Freezing user space processes .*", msg)):
+				action_start = ktime
+			elif(re.match(r"Freezing remaining freezable tasks.*", msg)):
+				data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime)
+				action_start = ktime
+			elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)):
+				data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime)
+		elif(phase == "suspend_cpu"):
+			m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg)
+			if(m):
+				cpu = "CPU"+m.group("cpu")
+				data.newAction(phase, cpu, -1, "", action_start, ktime)
+				action_start = ktime
+			elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)):
+				action_start = ktime
+			elif(re.match(r"Disabling non-boot CPUs .*", msg)):
+				data.newAction(phase, "ACPI", -1, "", action_start, ktime)
+				action_start = ktime
+		elif(phase == "resume_cpu"):
+			m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg)
+			if(m):
+				cpu = "CPU"+m.group("cpu")
+				data.newAction(phase, cpu, -1, "", action_start, ktime)
+				action_start = ktime
+			elif(re.match(r"Enabling non-boot CPUs .*", msg)):
+				action_start = ktime
+
+	# fill in any missing phases
+	lp = "suspend_general"
+	for p in data.phases:
+		if(p == "suspend_general"):
+			continue
+		if(data.dmesg[p]['start'] < 0):
+			data.dmesg[p]['start'] = data.dmesg[lp]['end']
+			if(p == "resume_cpu"):
+				data.tSuspended = data.dmesg[lp]['end']
+		if(data.dmesg[p]['end'] < 0):
+			data.dmesg[p]['end'] = data.dmesg[p]['start']
+		lp = p
+
+	data.fixupInitcallsThatDidntReturn()
+	return True
+
+# Function: setTimelineRows
+# Description:
+#	 Organize the device or thread lists into the smallest
+#	 number of rows possible, with no entry overlapping
+# Arguments:
+#	 list: the list to sort (dmesg or ftrace)
+#	 sortedkeys: sorted key list to use
+def setTimelineRows(list, sortedkeys):
+	global data
+
+	# clear all rows and set them to undefined
+	remaining = len(list)
+	rowdata = dict()
+	row = 0
+	for item in list:
+		list[item]['row'] = -1
+
+	# try to pack each row with as many ranges as possible
+	while(remaining > 0):
+		if(row not in rowdata):
+			rowdata[row] = []
+		for item in sortedkeys:
+			if(list[item]['row'] < 0):
+				s = list[item]['start']
+				e = list[item]['end']
+				valid = True
+				for ritem in rowdata[row]:
+					rs = ritem['start']
+					re = ritem['end']
+					if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))):
+						valid = False
+						break
+				if(valid):
+					rowdata[row].append(list[item])
+					list[item]['row'] = row
+					remaining -= 1
+		row += 1
+	return row
+
+# Function: createTimeScale
+# Description:
+#	 Create timescale lines for the dmesg and ftrace timelines
+# Arguments:
+#	 t0: start time (suspend begin)
+#	 tMax: end time (resume end)
+#	 tSuspend: time when suspend occurs
+def createTimeScale(t0, tMax, tSuspended):
+	global data
+	timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n"
+	output = '<div id="timescale">\n'
+
+	# set scale for timeline
+	tTotal = tMax - t0
+	tS = 0.1
+	if(tTotal <= 0):
+		return output
+	if(tTotal > 4):
+		tS = 1
+	if(tSuspended < 0):
+		for i in range(int(tTotal/tS)+1):
+			pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal))
+			if(i > 0):
+				val = "%0.f" % (float(i)*tS*1000)
+			else:
+				val = ""
+			output += timescale.format(pos, val)
+	else:
+		tSuspend = tSuspended - t0
+		divTotal = int(tTotal/tS) + 1
+		divSuspend = int(tSuspend/tS)
+		s0 = (tSuspend - tS*divSuspend)*100/tTotal
+		for i in range(divTotal):
+			pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0)
+			if((i == 0) and (s0 < 3)):
+				val = ""
+			elif(i == divSuspend):
+				val = "S/R"
+			else:
+				val = "%0.f" % (float(i-divSuspend)*tS*1000)
+			output += timescale.format(pos, val)
+	output += '</div>\n'
+	return output
+
+# Function: createHTML
+# Description:
+#	 Create the output html file.
+def createHTML():
+	global sysvals, data
+
+	data.normalizeTime()
+
+	# html function templates
+	headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
+	html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n<div id="dmesgzoombox" class="zoombox">\n'
+	html_timeline = '<div id="{0}" class="timeline" style="height:{1}px">\n'
+	html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
+	html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
+	html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
+	html_timetotal = '<table class="time1">\n<tr>'\
+		'<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\
+		'<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\
+		'</tr>\n</table>\n'
+	html_timegroups = '<table class="time2">\n<tr>'\
+		'<td class="green">Kernel Suspend: {0} ms</td>'\
+		'<td class="purple">Firmware Suspend: {1} ms</td>'\
+		'<td class="purple">Firmware Resume: {2} ms</td>'\
+		'<td class="yellow">Kernel Resume: {3} ms</td>'\
+		'</tr>\n</table>\n'
+
+	# device timeline (dmesg)
+	if(data.usedmesg):
+		data.vprint("Creating Device Timeline...")
+		devtl = Timeline()
+
+		# Generate the header for this timeline
+		t0 = data.start
+		tMax = data.end
+		tTotal = tMax - t0
+		if(tTotal == 0):
+			print("ERROR: No timeline data")
+			sys.exit()
+		suspend_time = "%.0f"%(-data.start*1000)
+		resume_time = "%.0f"%(data.end*1000)
+		if data.fwValid:
+			devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total")
+			sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000)
+			sftime = "%.3f"%(data.fwSuspend / 1000000.0)
+			rftime = "%.3f"%(data.fwResume / 1000000.0)
+			rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000)
+			devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime)
+		else:
+			devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel")
+
+		# determine the maximum number of rows we need to draw
+		timelinerows = 0
+		for phase in data.dmesg:
+			list = data.dmesg[phase]['list']
+			rows = setTimelineRows(list, list)
+			data.dmesg[phase]['row'] = rows
+			if(rows > timelinerows):
+				timelinerows = rows
+
+		# calculate the timeline height and create its bounding box
+		devtl.setRows(timelinerows + 1)
+		devtl.html['timeline'] += html_zoombox;
+		devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height);
+
+		# draw the colored boxes for each of the phases
+		for b in data.dmesg:
+			phase = data.dmesg[b]
+			left = "%.3f" % (((phase['start']-data.start)*100)/tTotal)
+			width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal)
+			devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "")
+
+		# draw the time scale, try to make the number of labels readable
+		devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended)
+		devtl.html['timeline'] += devtl.html['scale']
+		for b in data.dmesg:
+			phaselist = data.dmesg[b]['list']
+			for d in phaselist:
+				name = d
+				if(d in data.altdevname):
+					name = data.altdevname[d]
+				dev = phaselist[d]
+				height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
+				top = "%.3f" % ((dev['row']*height) + devtl.scaleH)
+				left = "%.3f" % (((dev['start']-data.start)*100)/tTotal)
+				width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal)
+				len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000)
+				color = "rgba(204,204,204,0.5)"
+				devtl.html['timeline'] += html_device.format(dev['id'], name+len+b, left, top, "%.3f"%height, width, name)
+
+		# timeline is finished
+		devtl.html['timeline'] += "</div>\n</div>\n"
+
+		# draw a legend which describes the phases by color
+		devtl.html['legend'] = "<div class=\"legend\">\n"
+		pdelta = 100.0/data.phases.__len__()
+		pmargin = pdelta / 4.0
+		for phase in data.phases:
+			order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
+			name = string.replace(phase, "_", " &nbsp;")
+			devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name)
+		devtl.html['legend'] += "</div>\n"
+
+	hf = open(sysvals.htmlfile, 'w')
+	thread_height = 0
+
+	# write the html header first (html head, css code, everything up to the start of body)
+	html_header = "<!DOCTYPE html>\n<html>\n<head>\n\
+	<meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\
+	<title>AnalyzeSuspend</title>\n\
+	<style type='text/css'>\n\
+		body {overflow-y: scroll;}\n\
+		.stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
+		.callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
+		.callgraph article * {padding-left: 28px;}\n\
+		h1 {color:black;font: bold 30px Times;}\n\
+		table {width:100%;}\n\
+		.gray {background-color:rgba(80,80,80,0.1);}\n\
+		.green {background-color:rgba(204,255,204,0.4);}\n\
+		.purple {background-color:rgba(128,0,128,0.2);}\n\
+		.yellow {background-color:rgba(255,255,204,0.4);}\n\
+		.time1 {font: 22px Arial;border:1px solid;}\n\
+		.time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
+		td {text-align: center;}\n\
+		.tdhl {color: red;}\n\
+		.hide {display: none;}\n\
+		.pf {display: none;}\n\
+		.pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version=\"1.0\" standalone=\"no\"?><svg xmlns=\"http://www.w3.org/2000/svg\" height=\"18\" width=\"18\" version=\"1.1\"><circle cx=\"9\" cy=\"9\" r=\"8\" stroke=\"black\" stroke-width=\"1\" fill=\"white\"/><rect x=\"4\" y=\"8\" width=\"10\" height=\"2\" style=\"fill:black;stroke-width:0\"/><rect x=\"8\" y=\"4\" width=\"2\" height=\"10\" style=\"fill:black;stroke-width:0\"/></svg>\') no-repeat left center;}\n\
+		.pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version=\"1.0\" standalone=\"no\"?><svg xmlns=\"http://www.w3.org/2000/svg\" height=\"18\" width=\"18\" version=\"1.1\"><circle cx=\"9\" cy=\"9\" r=\"8\" stroke=\"black\" stroke-width=\"1\" fill=\"white\"/><rect x=\"4\" y=\"8\" width=\"10\" height=\"2\" style=\"fill:black;stroke-width:0\"/></svg>\') no-repeat left center;}\n\
+		.pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
+		.zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
+		.timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
+		.thread {position: absolute; height: "+"%.3f"%thread_height+"%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
+		.thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
+		.phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
+		.t {position: absolute; top: 0%; height: 100%; border-right:1px solid black;}\n\
+		.legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
+		.legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
+		button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
+	</style>\n</head>\n<body>\n"
+	hf.write(html_header)
+
+	# write the test title and general info header
+	if(data.stamp['time'] != ""):
+		hf.write(headline_stamp.format(data.stamp['host'],
+			data.stamp['kernel'], data.stamp['mode'], data.stamp['time']))