1#!/usr/bin/python
   2#
   3# Tool for analyzing suspend/resume timing
   4# Copyright (c) 2013, Intel Corporation.
   5#
   6# This program is free software; you can redistribute it and/or modify it
   7# under the terms and conditions of the GNU General Public License,
   8# version 2, as published by the Free Software Foundation.
   9#
  10# This program is distributed in the hope it will be useful, but WITHOUT
  11# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  12# FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
  13# more details.
  14#
  15# You should have received a copy of the GNU General Public License along with
  16# this program; if not, write to the Free Software Foundation, Inc.,
  17# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
  18#
  19# Authors:
  20#	 Todd Brandt <todd.e.brandt@linux.intel.com>
  21#
  22# Description:
  23#	 This tool is designed to assist kernel and OS developers in optimizing
  24#	 their linux stack's suspend/resume time. Using a kernel image built
  25#	 with a few extra options enabled, the tool will execute a suspend and
  26#	 will capture dmesg and ftrace data until resume is complete. This data
  27#	 is transformed into a device timeline and a callgraph to give a quick
  28#	 and detailed view of which devices and callbacks are taking the most
  29#	 time in suspend/resume. The output is a single html file which can be
  30#	 viewed in firefox or chrome.
  31#
  32#	 The following kernel build options are required:
  33#		 CONFIG_PM_DEBUG=y
  34#		 CONFIG_PM_SLEEP_DEBUG=y
  35#		 CONFIG_FTRACE=y
  36#		 CONFIG_FUNCTION_TRACER=y
  37#		 CONFIG_FUNCTION_GRAPH_TRACER=y
  38#
 
  39#	 The following additional kernel parameters are required:
  40#		 (e.g. in file /etc/default/grub)
  41#		 GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
  42#
  43
 
 
  44import sys
  45import time
  46import os
  47import string
  48import re
  49import array
  50import platform
  51import datetime
  52import struct
  53
  54# -- classes --
  55
 
 
 
 
  56class SystemValues:
  57	testdir = "."
  58	tpath = "/sys/kernel/debug/tracing/"
  59	mempath = "/dev/mem"
  60	powerfile = "/sys/power/state"
  61	suspendmode = "mem"
  62	prefix = "test"
  63	teststamp = ""
  64	dmesgfile = ""
  65	ftracefile = ""
  66	htmlfile = ""
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
  67	rtcwake = False
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
  68	def setOutputFile(self):
  69		if((self.htmlfile == "") and (self.dmesgfile != "")):
  70			m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile)
  71			if(m):
  72				self.htmlfile = m.group("name")+".html"
  73		if((self.htmlfile == "") and (self.ftracefile != "")):
  74			m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile)
  75			if(m):
  76				self.htmlfile = m.group("name")+".html"
  77		if(self.htmlfile == ""):
  78			self.htmlfile = "output.html"
  79	def initTestOutput(self):
  80		hostname = platform.node()
  81		if(hostname != ""):
  82			self.prefix = hostname
  83		v = os.popen("cat /proc/version").read().strip()
  84		kver = string.split(v)[2]
  85		self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip()
  86		self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver
  87		self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt"
  88		self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt"
  89		self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html"
 
 
 
 
 
 
 
 
 
 
 
  90		os.mkdir(self.testdir)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
  91
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
  92class Data:
  93	altdevname = dict()
  94	usedmesg = False
  95	useftrace = False
  96	notestrun = False
  97	verbose = False
  98	phases = []
  99	dmesg = {} # root data structure
 100	start = 0.0
 101	end = 0.0
 102	stamp = {'time': "", 'host': "", 'mode': ""}
 103	id = 0
 104	tSuspended = 0.0
 105	fwValid = False
 106	fwSuspend = 0
 107	fwResume = 0
 108	def initialize(self):
 109		self.dmesg = { # dmesg log data
 110			'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
 111								'row': 0, 'color': "#CCFFCC", 'order': 0},
 112			  'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
 113								'row': 0, 'color': "green", 'order': 1},
 
 
 
 
 
 
 
 
 114			  'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
 115								'row': 0, 'color': "#00FFFF", 'order': 2},
 116				'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
 117								'row': 0, 'color': "blue", 'order': 3},
 118				 'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
 119								'row': 0, 'color': "red", 'order': 4},
 120			   'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
 121								'row': 0, 'color': "orange", 'order': 5},
 122			   'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
 123								'row': 0, 'color': "yellow", 'order': 6},
 124			 'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
 125								'row': 0, 'color': "#FFFFCC", 'order': 7}
 
 
 126		}
 127		self.phases = self.sortedPhases()
 128	def normalizeTime(self):
 129		tSus = tRes = self.tSuspended
 130		if self.fwValid:
 131			tSus -= -self.fwSuspend / 1000000000.0
 132			tRes -= self.fwResume / 1000000000.0
 133		self.tSuspended = 0.0
 134		self.start -= tSus
 135		self.end -= tRes
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 136		for phase in self.phases:
 137			zero = tRes
 138			if "suspend" in phase:
 139				zero = tSus
 140			p = self.dmesg[phase]
 141			p['start'] -= zero
 142			p['end'] -= zero
 143			list = p['list']
 144			for name in list:
 145				d = list[name]
 146				d['start'] -= zero
 147				d['end'] -= zero
 148				if('ftrace' in d):
 149					cg = d['ftrace']
 150					cg.start -= zero
 151					cg.end -= zero
 152					for line in cg.list:
 153						line.time -= zero
 154		if self.fwValid:
 155			fws = -self.fwSuspend / 1000000000.0
 156			fwr = self.fwResume / 1000000000.0
 157			list = dict()
 158			self.id += 1
 159			devid = "dc%d" % self.id
 160			list["firmware-suspend"] = \
 161				{'start': fws, 'end': 0, 'pid': 0, 'par': "",
 162				'length': -fws, 'row': 0, 'id': devid };
 163			self.id += 1
 164			devid = "dc%d" % self.id
 165			list["firmware-resume"] = \
 166				{'start': 0, 'end': fwr, 'pid': 0, 'par': "",
 167				'length': fwr, 'row': 0, 'id': devid };
 168			self.dmesg['BIOS'] = \
 169				{'list': list, 'start': fws, 'end': fwr,
 170				'row': 0, 'color': "purple", 'order': 4}
 171			self.dmesg['resume_cpu']['order'] += 1
 172			self.dmesg['resume_noirq']['order'] += 1
 173			self.dmesg['resume_early']['order'] += 1
 174			self.dmesg['resume_general']['order'] += 1
 175			self.phases = self.sortedPhases()
 176	def vprint(self, msg):
 177		if(self.verbose):
 178			print(msg)
 
 
 
 
 
 
 
 
 
 
 
 
 179	def dmesgSortVal(self, phase):
 180		return self.dmesg[phase]['order']
 181	def sortedPhases(self):
 182		return sorted(self.dmesg, key=self.dmesgSortVal)
 183	def sortedDevices(self, phase):
 184		list = self.dmesg[phase]['list']
 185		slist = []
 186		tmp = dict()
 187		for devname in list:
 188			dev = list[devname]
 189			tmp[dev['start']] = devname
 190		for t in sorted(tmp):
 191			slist.append(tmp[t])
 192		return slist
 193	def fixupInitcalls(self, phase, end):
 194		# if any calls never returned, clip them at system resume end
 195		phaselist = self.dmesg[phase]['list']
 196		for devname in phaselist:
 197			dev = phaselist[devname]
 198			if(dev['end'] < 0):
 199				dev['end'] = end
 200				self.vprint("%s (%s): callback didn't return" % (devname, phase))
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 201	def fixupInitcallsThatDidntReturn(self):
 202		# if any calls never returned, clip them at system resume end
 203		for phase in self.phases:
 204			self.fixupInitcalls(phase, self.dmesg['resume_general']['end'])
 205			if(phase == "resume_general"):
 206				break
 207	def newAction(self, phase, name, pid, parent, start, end):
 208		self.id += 1
 209		devid = "dc%d" % self.id
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 210		list = self.dmesg[phase]['list']
 211		length = -1.0
 212		if(start >= 0 and end >= 0):
 213			length = end - start
 214		list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
 215					  'length': length, 'row': 0, 'id': devid }
 216	def deviceIDs(self, devlist, phase):
 217		idlist = []
 218		for p in self.phases:
 219			if(p[0] != phase[0]):
 220				continue
 221			list = data.dmesg[p]['list']
 222			for devname in list:
 223				if devname in devlist:
 224					idlist.append(list[devname]['id'])
 225		return idlist
 226	def deviceParentID(self, devname, phase):
 227		pdev = ""
 228		pdevid = ""
 229		for p in self.phases:
 230			if(p[0] != phase[0]):
 231				continue
 232			list = data.dmesg[p]['list']
 233			if devname in list:
 234				pdev = list[devname]['par']
 235		for p in self.phases:
 236			if(p[0] != phase[0]):
 237				continue
 238			list = data.dmesg[p]['list']
 239			if pdev in list:
 240				return list[pdev]['id']
 241		return pdev
 242	def deviceChildrenIDs(self, devname, phase):
 243		devlist = []
 244		for p in self.phases:
 245			if(p[0] != phase[0]):
 246				continue
 247			list = data.dmesg[p]['list']
 248			for child in list:
 249				if(list[child]['par'] == devname):
 250					devlist.append(child)
 
 
 
 
 
 
 251		return self.deviceIDs(devlist, phase)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 252
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 253class FTraceLine:
 254	time = 0.0
 255	length = 0.0
 256	fcall = False
 257	freturn = False
 258	fevent = False
 259	depth = 0
 260	name = ""
 
 261	def __init__(self, t, m, d):
 262		self.time = float(t)
 263		# check to see if this is a trace event
 264		em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m)
 265		if(em):
 266			self.name = em.group("msg")
 
 
 
 
 
 
 
 
 
 
 
 
 267			self.fevent = True
 268			return
 269		# convert the duration to seconds
 270		if(d):
 271			self.length = float(d)/1000000
 272		# the indentation determines the depth
 273		match = re.match(r"^(?P<d> *)(?P<o>.*)$", m)
 274		if(not match):
 275			return
 276		self.depth = self.getDepth(match.group('d'))
 277		m = match.group('o')
 278		# function return
 279		if(m[0] == '}'):
 280			self.freturn = True
 281			if(len(m) > 1):
 282				# includes comment with function name
 283				match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m)
 284				if(match):
 285					self.name = match.group('n')
 286		# function call
 287		else:
 288			self.fcall = True
 289			# function call with children
 290			if(m[-1] == '{'):
 291				match = re.match(r"^(?P<n>.*) *\(.*", m)
 292				if(match):
 293					self.name = match.group('n')
 294			# function call with no children (leaf)
 295			elif(m[-1] == ';'):
 296				self.freturn = True
 297				match = re.match(r"^(?P<n>.*) *\(.*", m)
 298				if(match):
 299					self.name = match.group('n')
 300			# something else (possibly a trace marker)
 301			else:
 302				self.name = m
 303	def getDepth(self, str):
 304		return len(str)/2
 
 
 
 
 
 
 
 
 
 
 305
 
 
 
 
 
 
 306class FTraceCallGraph:
 307	start = -1.0
 308	end = -1.0
 309	list = []
 310	invalid = False
 311	depth = 0
 312	def __init__(self):
 313		self.start = -1.0
 314		self.end = -1.0
 315		self.list = []
 316		self.depth = 0
 317	def setDepth(self, line):
 318		if(line.fcall and not line.freturn):
 319			line.depth = self.depth
 320			self.depth += 1
 321		elif(line.freturn and not line.fcall):
 322			self.depth -= 1
 323			line.depth = self.depth
 324		else:
 325			line.depth = self.depth
 326	def addLine(self, line, match):
 327		if(not self.invalid):
 328			self.setDepth(line)
 329		if(line.depth == 0 and line.freturn):
 
 
 330			self.end = line.time
 331			self.list.append(line)
 332			return True
 333		if(self.invalid):
 334			return False
 335		if(len(self.list) >= 1000000 or self.depth < 0):
 336		   first = self.list[0]
 337		   self.list = []
 338		   self.list.append(first)
 339		   self.invalid = True
 340		   id = "task %s cpu %s" % (match.group("pid"), match.group("cpu"))
 341		   window = "(%f - %f)" % (self.start, line.time)
 342		   data.vprint("Too much data for "+id+" "+window+", ignoring this callback")
 343		   return False
 
 
 
 
 
 
 
 
 344		self.list.append(line)
 345		if(self.start < 0):
 346			self.start = line.time
 347		return False
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 348	def sanityCheck(self):
 349		stack = dict()
 350		cnt = 0
 351		for l in self.list:
 352			if(l.fcall and not l.freturn):
 353				stack[l.depth] = l
 354				cnt += 1
 355			elif(l.freturn and not l.fcall):
 356				if(not stack[l.depth]):
 357					return False
 358				stack[l.depth].length = l.length
 359				stack[l.depth] = 0
 360				l.length = 0
 361				cnt -= 1
 362		if(cnt == 0):
 363			return True
 364		return False
 365	def debugPrint(self, filename):
 366		if(filename == "stdout"):
 367			print("[%f - %f]") % (self.start, self.end)
 368			for l in self.list:
 369				if(l.freturn and l.fcall):
 370					print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
 
 371				elif(l.freturn):
 372					print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
 
 373				else:
 374					print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
 375			print(" ")
 
 376		else:
 377			fp = open(filename, 'w')
 378			print(filename)
 379			for l in self.list:
 380				if(l.freturn and l.fcall):
 381					fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
 
 382				elif(l.freturn):
 383					fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
 
 384				else:
 385					fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
 
 386			fp.close()
 387
 
 
 
 
 
 388class Timeline:
 389	html = {}
 390	scaleH = 0.0 # height of the timescale row as a percent of the timeline height
 391	rowH = 0.0 # height of each row in percent of the timeline height
 392	row_height_pixels = 30
 393	maxrows = 0
 394	height = 0
 395	def __init__(self):
 396		self.html = {
 397			'timeline': "",
 398			'legend': "",
 399			'scale': ""
 400		}
 401	def setRows(self, rows):
 402		self.maxrows = int(rows)
 403		self.scaleH = 100.0/float(self.maxrows)
 404		self.height = self.maxrows*self.row_height_pixels
 405		r = float(self.maxrows - 1)
 406		if(r < 1.0):
 407			r = 1.0
 408		self.rowH = (100.0 - self.scaleH)/r
 409
 410# -- global objects --
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 411
 412sysvals = SystemValues()
 413data = Data()
 414
 415# -- functions --
 
 
 
 
 
 
 
 
 416
 417# Function: initFtrace
 418# Description:
 419#	 Configure ftrace to capture a function trace during suspend/resume
 420def initFtrace():
 421	global sysvals
 422
 423	print("INITIALIZING FTRACE...")
 424	# turn trace off
 425	os.system("echo 0 > "+sysvals.tpath+"tracing_on")
 426	# set the trace clock to global
 427	os.system("echo global > "+sysvals.tpath+"trace_clock")
 428	# set trace buffer to a huge value
 429	os.system("echo nop > "+sysvals.tpath+"current_tracer")
 430	os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb")
 431	# clear the trace buffer
 432	os.system("echo \"\" > "+sysvals.tpath+"trace")
 433	# set trace type
 434	os.system("echo function_graph > "+sysvals.tpath+"current_tracer")
 435	os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter")
 436	# set trace format options
 437	os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options")
 438	os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options")
 439	# focus only on device suspend and resume
 440	os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function")
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 441
 442# Function: verifyFtrace
 443# Description:
 444#	 Check that ftrace is working on the system
 
 
 445def verifyFtrace():
 446	global sysvals
 447	files = ["available_filter_functions", "buffer_size_kb",
 448			 "current_tracer", "set_ftrace_filter",
 449			 "trace", "trace_marker"]
 
 
 
 
 
 
 
 
 450	for f in files:
 451		if(os.path.exists(sysvals.tpath+f) == False):
 452			return False
 
 
 
 
 
 453	return True
 454
 455def parseStamp(line):
 456	global data, sysvals
 457	stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\
 458				"(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\
 459				" (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$"
 460	m = re.match(stampfmt, line)
 461	if(m):
 462		dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")),
 463			int(m.group("d")), int(m.group("H")), int(m.group("M")),
 464			int(m.group("S")))
 465		data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p")
 466		data.stamp['host'] = m.group("host")
 467		data.stamp['mode'] = m.group("mode")
 468		data.stamp['kernel'] = m.group("kernel")
 469		sysvals.suspendmode = data.stamp['mode']
 470
 471# Function: analyzeTraceLog
 472# Description:
 473#	 Analyse an ftrace log output file generated from this app during
 474#	 the execution phase. Create an "ftrace" structure in memory for
 475#	 subsequent formatting in the html output file
 476def analyzeTraceLog():
 477	global sysvals, data
 478
 479	# the ftrace data is tied to the dmesg data
 480	if(not data.usedmesg):
 481		return
 482
 483	# read through the ftrace and parse the data
 484	data.vprint("Analyzing the ftrace data...")
 485	ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\
 486					   " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\
 487					   "[ +!]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)"
 488	ftemp = dict()
 489	inthepipe = False
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 490	tf = open(sysvals.ftracefile, 'r')
 491	count = 0
 492	for line in tf:
 493		count = count + 1
 494		# grab the time stamp if it's valid
 495		if(count == 1):
 496			parseStamp(line)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 497			continue
 498		# parse only valid lines
 499		m = re.match(ftrace_line_fmt, line)
 500		if(not m):
 501			continue
 502		m_time = m.group("time")
 503		m_pid = m.group("pid")
 504		m_msg = m.group("msg")
 505		m_dur = m.group("dur")
 
 
 
 
 506		if(m_time and m_pid and m_msg):
 507			t = FTraceLine(m_time, m_msg, m_dur)
 508			pid = int(m_pid)
 509		else:
 510			continue
 511		# the line should be a call, return, or event
 512		if(not t.fcall and not t.freturn and not t.fevent):
 513			continue
 514		# only parse the ftrace data during suspend/resume
 515		if(not inthepipe):
 
 516			# look for the suspend start marker
 517			if(t.fevent):
 518				if(t.name == "SUSPEND START"):
 519					data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count))
 520					inthepipe = True
 521				continue
 522		else:
 523			# look for the resume end marker
 524			if(t.fevent):
 525				if(t.name == "RESUME COMPLETE"):
 526					data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count))
 527					inthepipe = False
 528					break
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 529				continue
 530			# create a callgraph object for the data
 531			if(pid not in ftemp):
 532				ftemp[pid] = FTraceCallGraph()
 
 533			# when the call is finished, see which device matches it
 534			if(ftemp[pid].addLine(t, m)):
 535				if(not ftemp[pid].sanityCheck()):
 536					id = "task %s cpu %s" % (pid, m.group("cpu"))
 537					data.vprint("Sanity check failed for "+id+", ignoring this callback")
 538					continue
 539				callstart = ftemp[pid].start
 540				callend = ftemp[pid].end
 541				for p in data.phases:
 542					if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']):
 543						list = data.dmesg[p]['list']
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 544						for devname in list:
 545							dev = list[devname]
 546							if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']):
 547								data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid))
 548								dev['ftrace'] = ftemp[pid]
 
 549						break
 550				ftemp[pid] = FTraceCallGraph()
 551	tf.close()
 552
 553# Function: sortKernelLog
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 554# Description:
 555#	 The dmesg output log sometimes comes with with lines that have
 556#	 timestamps out of order. This could cause issues since a call
 557#	 could accidentally end up in the wrong phase
 558def sortKernelLog():
 559	global sysvals, data
 
 
 
 
 
 
 
 
 
 
 560	lf = open(sysvals.dmesgfile, 'r')
 561	dmesglist = []
 562	count = 0
 563	for line in lf:
 564		line = line.replace("\r\n", "")
 565		if(count == 0):
 566			parseStamp(line)
 567		elif(count == 1):
 568			m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line)
 569			if(m):
 570				data.fwSuspend = int(m.group("s"))
 571				data.fwResume = int(m.group("r"))
 572				if(data.fwSuspend > 0 or data.fwResume > 0):
 573					data.fwValid = True
 574		if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)):
 575			dmesglist.append(line)
 576		count += 1
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 577	lf.close()
 578	last = ""
 579
 580	# fix lines with the same time stamp and function with the call and return swapped
 581	for line in dmesglist:
 582		mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling  (?P<f>.*)\+ @ .*, parent: .*", line)
 583		mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last)
 584		if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))):
 585			i = dmesglist.index(last)
 586			j = dmesglist.index(line)
 587			dmesglist[i] = line
 588			dmesglist[j] = last
 589		last = line
 590	return dmesglist
 
 
 
 
 
 
 
 
 
 591
 592# Function: analyzeKernelLog
 593# Description:
 
 594#	 Analyse a dmesg log output file generated from this app during
 595#	 the execution phase. Create a set of device structures in memory
 596#	 for subsequent formatting in the html output file
 597def analyzeKernelLog():
 598	global sysvals, data
 
 
 
 
 
 
 599
 600	print("PROCESSING DATA")
 601	data.vprint("Analyzing the dmesg data...")
 602	if(os.path.exists(sysvals.dmesgfile) == False):
 603		print("ERROR: %s doesn't exist") % sysvals.dmesgfile
 604		return False
 605
 606	lf = sortKernelLog()
 607	phase = "suspend_runtime"
 
 608
 
 609	dm = {
 610		'suspend_general': r"PM: Syncing filesystems.*",
 611		  'suspend_early': r"PM: suspend of devices complete after.*",
 612		  'suspend_noirq': r"PM: late suspend of devices complete after.*",
 613		    'suspend_cpu': r"PM: noirq suspend of devices complete after.*",
 614		     'resume_cpu': r"ACPI: Low-level resume complete.*",
 615		   'resume_noirq': r"ACPI: Waking up from system sleep state.*",
 616		   'resume_early': r"PM: noirq resume of devices complete after.*",
 617		 'resume_general': r"PM: early resume of devices complete after.*",
 618		'resume_complete': r".*Restarting tasks \.\.\..*",
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 619	}
 620	if(sysvals.suspendmode == "standby"):
 621		dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
 622	elif(sysvals.suspendmode == "disk"):
 623		dm['suspend_early'] = r"PM: freeze of devices complete after.*"
 624		dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*"
 625		dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*"
 626		dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
 627		dm['resume_early'] = r"PM: noirq restore of devices complete after.*"
 628		dm['resume_general'] = r"PM: early restore of devices complete after.*"
 629
 630	action_start = 0.0
 631	for line in lf:
 
 
 
 632		# -- preprocessing --
 633		# parse each dmesg line into the time and message
 634		m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)
 635		if(m):
 636			ktime = float(m.group("ktime"))
 637			msg = m.group("msg")
 
 
 
 
 
 
 
 
 
 
 638		else:
 639			print line
 640			continue
 641
 
 
 
 
 
 
 
 
 642		# -- phase changes --
 643		# suspend_general start
 644		if(re.match(dm['suspend_general'], msg)):
 645			phase = "suspend_general"
 
 
 
 
 
 
 646			data.dmesg[phase]['start'] = ktime
 647			data.start = ktime
 648			# action start: syncing filesystems
 649			action_start = ktime
 650		# suspend_early start
 651		elif(re.match(dm['suspend_early'], msg)):
 652			data.dmesg["suspend_general"]['end'] = ktime
 653			phase = "suspend_early"
 654			data.dmesg[phase]['start'] = ktime
 655		# suspend_noirq start
 656		elif(re.match(dm['suspend_noirq'], msg)):
 657			data.dmesg["suspend_early"]['end'] = ktime
 658			phase = "suspend_noirq"
 659			data.dmesg[phase]['start'] = ktime
 660		# suspend_cpu start
 661		elif(re.match(dm['suspend_cpu'], msg)):
 662			data.dmesg["suspend_noirq"]['end'] = ktime
 663			phase = "suspend_cpu"
 664			data.dmesg[phase]['start'] = ktime
 665		# resume_cpu start
 666		elif(re.match(dm['resume_cpu'], msg)):
 667			data.tSuspended = ktime
 668			data.dmesg["suspend_cpu"]['end'] = ktime
 669			phase = "resume_cpu"
 
 
 
 
 
 
 670			data.dmesg[phase]['start'] = ktime
 671		# resume_noirq start
 672		elif(re.match(dm['resume_noirq'], msg)):
 673			data.dmesg["resume_cpu"]['end'] = ktime
 674			phase = "resume_noirq"
 675			data.dmesg[phase]['start'] = ktime
 676			# action end: ACPI resume
 677			data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime)
 678		# resume_early start
 679		elif(re.match(dm['resume_early'], msg)):
 680			data.dmesg["resume_noirq"]['end'] = ktime
 681			phase = "resume_early"
 682			data.dmesg[phase]['start'] = ktime
 683		# resume_general start
 684		elif(re.match(dm['resume_general'], msg)):
 685			data.dmesg["resume_early"]['end'] = ktime
 686			phase = "resume_general"
 687			data.dmesg[phase]['start'] = ktime
 688		# resume complete start
 689		elif(re.match(dm['resume_complete'], msg)):
 690			data.dmesg["resume_general"]['end'] = ktime
 691			data.end = ktime
 692			phase = "resume_runtime"
 
 
 
 
 
 693			break
 694
 695		# -- device callbacks --
 696		if(phase in data.phases):
 697			# device init call
 698			if(re.match(r"calling  (?P<f>.*)\+ @ .*, parent: .*", msg)):
 699				sm = re.match(r"calling  (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg);
 700				f = sm.group("f")
 701				n = sm.group("n")
 702				p = sm.group("p")
 
 703				if(f and n and p):
 704					data.newAction(phase, f, int(n), p, ktime, -1)
 705			# device init return
 706			elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)):
 707				sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg);
 708				f = sm.group("f")
 709				t = sm.group("t")
 
 
 710				list = data.dmesg[phase]['list']
 711				if(f in list):
 712					dev = list[f]
 713					dev['length'] = int(t)
 714					dev['end'] = ktime
 715					data.vprint("%15s [%f - %f] %s(%d) %s" %
 716						(phase, dev['start'], dev['end'], f, dev['pid'], dev['par']))
 717
 718		# -- phase specific actions --
 719		if(phase == "suspend_general"):
 720			if(re.match(r"PM: Preparing system for mem sleep.*", msg)):
 721				data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime)
 722			elif(re.match(r"Freezing user space processes .*", msg)):
 723				action_start = ktime
 724			elif(re.match(r"Freezing remaining freezable tasks.*", msg)):
 725				data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime)
 726				action_start = ktime
 727			elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)):
 728				data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime)
 729		elif(phase == "suspend_cpu"):
 730			m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg)
 731			if(m):
 732				cpu = "CPU"+m.group("cpu")
 733				data.newAction(phase, cpu, -1, "", action_start, ktime)
 734				action_start = ktime
 735			elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)):
 736				action_start = ktime
 737			elif(re.match(r"Disabling non-boot CPUs .*", msg)):
 738				data.newAction(phase, "ACPI", -1, "", action_start, ktime)
 739				action_start = ktime
 740		elif(phase == "resume_cpu"):
 741			m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg)
 742			if(m):
 743				cpu = "CPU"+m.group("cpu")
 744				data.newAction(phase, cpu, -1, "", action_start, ktime)
 745				action_start = ktime
 746			elif(re.match(r"Enabling non-boot CPUs .*", msg)):
 747				action_start = ktime
 
 
 
 
 
 748
 749	# fill in any missing phases
 750	lp = "suspend_general"
 751	for p in data.phases:
 752		if(p == "suspend_general"):
 753			continue
 
 
 
 754		if(data.dmesg[p]['start'] < 0):
 755			data.dmesg[p]['start'] = data.dmesg[lp]['end']
 756			if(p == "resume_cpu"):
 757				data.tSuspended = data.dmesg[lp]['end']
 
 
 758		if(data.dmesg[p]['end'] < 0):
 759			data.dmesg[p]['end'] = data.dmesg[p]['start']
 760		lp = p
 761
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 762	data.fixupInitcallsThatDidntReturn()
 763	return True
 764
 765# Function: setTimelineRows
 766# Description:
 767#	 Organize the device or thread lists into the smallest
 768#	 number of rows possible, with no entry overlapping
 769# Arguments:
 770#	 list: the list to sort (dmesg or ftrace)
 771#	 sortedkeys: sorted key list to use
 
 
 772def setTimelineRows(list, sortedkeys):
 773	global data
 774
 775	# clear all rows and set them to undefined
 776	remaining = len(list)
 777	rowdata = dict()
 778	row = 0
 779	for item in list:
 780		list[item]['row'] = -1
 781
 782	# try to pack each row with as many ranges as possible
 783	while(remaining > 0):
 784		if(row not in rowdata):
 785			rowdata[row] = []
 786		for item in sortedkeys:
 787			if(list[item]['row'] < 0):
 788				s = list[item]['start']
 789				e = list[item]['end']
 790				valid = True
 791				for ritem in rowdata[row]:
 792					rs = ritem['start']
 793					re = ritem['end']
 794					if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))):
 
 795						valid = False
 796						break
 797				if(valid):
 798					rowdata[row].append(list[item])
 799					list[item]['row'] = row
 800					remaining -= 1
 801		row += 1
 802	return row
 803
 804# Function: createTimeScale
 805# Description:
 806#	 Create timescale lines for the dmesg and ftrace timelines
 807# Arguments:
 808#	 t0: start time (suspend begin)
 809#	 tMax: end time (resume end)
 810#	 tSuspend: time when suspend occurs
 
 
 811def createTimeScale(t0, tMax, tSuspended):
 812	global data
 813	timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n"
 814	output = '<div id="timescale">\n'
 815
 816	# set scale for timeline
 817	tTotal = tMax - t0
 818	tS = 0.1
 819	if(tTotal <= 0):
 820		return output
 821	if(tTotal > 4):
 822		tS = 1
 823	if(tSuspended < 0):
 824		for i in range(int(tTotal/tS)+1):
 825			pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal))
 826			if(i > 0):
 827				val = "%0.f" % (float(i)*tS*1000)
 828			else:
 829				val = ""
 830			output += timescale.format(pos, val)
 831	else:
 832		tSuspend = tSuspended - t0
 833		divTotal = int(tTotal/tS) + 1
 834		divSuspend = int(tSuspend/tS)
 835		s0 = (tSuspend - tS*divSuspend)*100/tTotal
 836		for i in range(divTotal):
 837			pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0)
 838			if((i == 0) and (s0 < 3)):
 839				val = ""
 840			elif(i == divSuspend):
 841				val = "S/R"
 842			else:
 843				val = "%0.f" % (float(i-divSuspend)*tS*1000)
 844			output += timescale.format(pos, val)
 845	output += '</div>\n'
 846	return output
 847
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 848# Function: createHTML
 849# Description:
 850#	 Create the output html file.
 851def createHTML():
 852	global sysvals, data
 
 
 
 
 853
 854	data.normalizeTime()
 
 855
 
 
 
 856	# html function templates
 857	headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
 858	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'
 859	html_timeline = '<div id="{0}" class="timeline" style="height:{1}px">\n'
 
 
 860	html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
 
 861	html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
 
 862	html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
 863	html_timetotal = '<table class="time1">\n<tr>'\
 864		'<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\
 865		'<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\
 
 
 
 
 
 866		'</tr>\n</table>\n'
 867	html_timegroups = '<table class="time2">\n<tr>'\
 868		'<td class="green">Kernel Suspend: {0} ms</td>'\
 869		'<td class="purple">Firmware Suspend: {1} ms</td>'\
 870		'<td class="purple">Firmware Resume: {2} ms</td>'\
 871		'<td class="yellow">Kernel Resume: {3} ms</td>'\
 872		'</tr>\n</table>\n'
 873
 874	# device timeline (dmesg)
 875	if(data.usedmesg):
 876		data.vprint("Creating Device Timeline...")
 877		devtl = Timeline()
 878
 879		# Generate the header for this timeline
 880		t0 = data.start
 881		tMax = data.end
 882		tTotal = tMax - t0
 883		if(tTotal == 0):
 884			print("ERROR: No timeline data")
 885			sys.exit()
 886		suspend_time = "%.0f"%(-data.start*1000)
 887		resume_time = "%.0f"%(data.end*1000)
 888		if data.fwValid:
 889			devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total")
 890			sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000)
 891			sftime = "%.3f"%(data.fwSuspend / 1000000.0)
 892			rftime = "%.3f"%(data.fwResume / 1000000.0)
 893			rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000)
 894			devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 895		else:
 896			devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel")
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 897
 898		# determine the maximum number of rows we need to draw
 899		timelinerows = 0
 
 900		for phase in data.dmesg:
 901			list = data.dmesg[phase]['list']
 902			rows = setTimelineRows(list, list)
 903			data.dmesg[phase]['row'] = rows
 904			if(rows > timelinerows):
 905				timelinerows = rows
 906
 907		# calculate the timeline height and create its bounding box
 908		devtl.setRows(timelinerows + 1)
 909		devtl.html['timeline'] += html_zoombox;
 910		devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height);
 
 
 
 911
 912		# draw the colored boxes for each of the phases
 
 913		for b in data.dmesg:
 914			phase = data.dmesg[b]
 915			left = "%.3f" % (((phase['start']-data.start)*100)/tTotal)
 916			width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal)
 917			devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "")
 918
 919		# draw the time scale, try to make the number of labels readable
 920		devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended)
 921		devtl.html['timeline'] += devtl.html['scale']
 
 
 
 
 922		for b in data.dmesg:
 923			phaselist = data.dmesg[b]['list']
 924			for d in phaselist:
 925				name = d
 926				if(d in data.altdevname):
 927					name = data.altdevname[d]
 928				dev = phaselist[d]
 
 
 
 
 929				height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
 930				top = "%.3f" % ((dev['row']*height) + devtl.scaleH)
 931				left = "%.3f" % (((dev['start']-data.start)*100)/tTotal)
 932				width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal)
 933				len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000)
 934				color = "rgba(204,204,204,0.5)"
 935				devtl.html['timeline'] += html_device.format(dev['id'], name+len+b, left, top, "%.3f"%height, width, name)
 936
 937		# timeline is finished
 938		devtl.html['timeline'] += "</div>\n</div>\n"
 939
 940		# draw a legend which describes the phases by color
 941		devtl.html['legend'] = "<div class=\"legend\">\n"
 942		pdelta = 100.0/data.phases.__len__()
 943		pmargin = pdelta / 4.0
 944		for phase in data.phases:
 945			order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
 946			name = string.replace(phase, "_", " &nbsp;")
 947			devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name)
 948		devtl.html['legend'] += "</div>\n"
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 949
 950	hf = open(sysvals.htmlfile, 'w')
 951	thread_height = 0
 952
 953	# write the html header first (html head, css code, everything up to the start of body)
 954	html_header = "<!DOCTYPE html>\n<html>\n<head>\n\
 955	<meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\
 956	<title>AnalyzeSuspend</title>\n\
 957	<style type='text/css'>\n\
 958		body {overflow-y: scroll;}\n\
 959		.stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
 960		.callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
 961		.callgraph article * {padding-left: 28px;}\n\
 962		h1 {color:black;font: bold 30px Times;}\n\
 
 
 
 
 
 963		table {width:100%;}\n\
 964		.gray {background-color:rgba(80,80,80,0.1);}\n\
 965		.green {background-color:rgba(204,255,204,0.4);}\n\
 966		.purple {background-color:rgba(128,0,128,0.2);}\n\
 967		.yellow {background-color:rgba(255,255,204,0.4);}\n\
 968		.time1 {font: 22px Arial;border:1px solid;}\n\
 969		.time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
 970		td {text-align: center;}\n\
 
 
 971		.tdhl {color: red;}\n\
 972		.hide {display: none;}\n\
 973		.pf {display: none;}\n\
 974		.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\
 975		.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\
 976		.pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
 977		.zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
 978		.timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
 979		.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\
 980		.thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
 
 
 981		.phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
 982		.t {position: absolute; top: 0%; height: 100%; border-right:1px solid black;}\n\
 
 983		.legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
 984		.legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
 985		button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
 986	</style>\n</head>\n<body>\n"
 
 
 987	hf.write(html_header)
 988
 989	# write the test title and general info header
 990	if(data.stamp['time'] != ""):
 991		hf.write(headline_stamp.format(data.stamp['host'],
 992			data.stamp['kernel'], data.stamp['mode'], data.stamp['time']))
 993
 994	# write the dmesg data (device timeline)
 995	if(data.usedmesg):
 996		hf.write(devtl.html['timeline'])
 997		hf.write(devtl.html['legend'])
 998		hf.write('<div id="devicedetail"></div>\n')
 999		hf.write('<div id="devicetree"></div>\n')
 
 
 
 
 
 
 
 
 
 
 
 
1000
1001	# write the ftrace data (callgraph)
1002	if(data.useftrace):
 
1003		hf.write('<section id="callgraphs" class="callgraph">\n')
1004		# write out the ftrace data converted to html
1005		html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
1006		html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
1007		html_func_end = '</article>\n'
1008		html_func_leaf = '<article>{0} {1}</article>\n'
1009		num = 0
1010		for p in data.phases:
1011			list = data.dmesg[p]['list']
1012			for devname in data.sortedDevices(p):
1013				if('ftrace' not in list[devname]):
1014					continue
1015				name = devname
1016				if(devname in data.altdevname):
1017					name = data.altdevname[devname]
1018				devid = list[devname]['id']
1019				cg = list[devname]['ftrace']
1020				flen = "(%.3f ms)" % ((cg.end - cg.start)*1000)
1021				hf.write(html_func_top.format(devid, data.dmesg[p]['color'], num, name+" "+p, flen))
 
 
1022				num += 1
1023				for line in cg.list:
1024					if(line.length < 0.000000001):
1025						flen = ""
1026					else:
1027						flen = "(%.3f ms)" % (line.length*1000)
 
1028					if(line.freturn and line.fcall):
1029						hf.write(html_func_leaf.format(line.name, flen))
1030					elif(line.freturn):
1031						hf.write(html_func_end)
1032					else:
1033						hf.write(html_func_start.format(num, line.name, flen))
1034						num += 1
1035				hf.write(html_func_end)
1036		hf.write("\n\n    </section>\n")
1037	# write the footer and close
1038	addScriptCode(hf)
1039	hf.write("</body>\n</html>\n")
1040	hf.close()
1041	return True
1042
1043def addScriptCode(hf):
1044	global data
1045
1046	t0 = (data.start - data.tSuspended) * 1000
1047	tMax = (data.end - data.tSuspended) * 1000
 
 
 
 
1048	# create an array in javascript memory with the device details
1049	detail = '	var bounds = [%f,%f];\n' % (t0, tMax)
1050	detail += '	var d = [];\n'
1051	dfmt = '	d["%s"] = { n:"%s", p:"%s", c:[%s] };\n';
1052	for p in data.dmesg:
1053		list = data.dmesg[p]['list']
1054		for d in list:
1055			parent = data.deviceParentID(d, p)
1056			idlist = data.deviceChildrenIDs(d, p)
1057			idstr = ""
1058			for i in idlist:
1059				if(idstr == ""):
1060					idstr += '"'+i+'"'
1061				else:
1062					idstr += ', '+'"'+i+'"'
1063			detail += dfmt % (list[d]['id'], d, parent, idstr)
1064
1065	# add the code which will manipulate the data in the browser
1066	script_code = \
1067	'<script type="text/javascript">\n'+detail+\
1068	'	var filter = [];\n'\
1069	'	var table = [];\n'\
1070	'	function deviceParent(devid) {\n'\
1071	'		var devlist = [];\n'\
1072	'		if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
1073	'		if(d[devid].p in d)\n'\
1074	'			devlist = deviceParent(d[devid].p);\n'\
1075	'		else if(d[devid].p != "")\n'\
1076	'			devlist = [d[devid].p];\n'\
1077	'		devlist[devlist.length] = d[devid].n;\n'\
1078	'		return devlist;\n'\
1079	'	}\n'\
1080	'	function deviceChildren(devid, column, row) {\n'\
1081	'		if(!(devid in d)) return;\n'\
1082	'		if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
1083	'		var cell = {name: d[devid].n, span: 1};\n'\
1084	'		var span = 0;\n'\
1085	'		if(column >= table.length) table[column] = [];\n'\
1086	'		table[column][row] = cell;\n'\
1087	'		for(var i = 0; i < d[devid].c.length; i++) {\n'\
1088	'			var cid = d[devid].c[i];\n'\
1089	'			span += deviceChildren(cid, column+1, row+span);\n'\
1090	'		}\n'\
1091	'		if(span == 0) span = 1;\n'\
1092	'		table[column][row].span = span;\n'\
1093	'		return span;\n'\
1094	'	}\n'\
1095	'	function deviceTree(devid, resume) {\n'\
1096	'		var html = "<table border=1>";\n'\
1097	'		filter = [];\n'\
1098	'		table = [];\n'\
1099	'		plist = deviceParent(devid);\n'\
1100	'		var devidx = plist.length - 1;\n'\
1101	'		for(var i = 0; i < devidx; i++)\n'\
1102	'			table[i] = [{name: plist[i], span: 1}];\n'\
1103	'		deviceChildren(devid, devidx, 0);\n'\
1104	'		for(var i = 0; i < devidx; i++)\n'\
1105	'			table[i][0].span = table[devidx][0].span;\n'\
1106	'		for(var row = 0; row < table[0][0].span; row++) {\n'\
1107	'			html += "<tr>";\n'\
1108	'			for(var col = 0; col < table.length; col++)\n'\
1109	'				if(row in table[col]) {\n'\
1110	'					var cell = table[col][row];\n'\
1111	'					var args = "";\n'\
1112	'					if(cell.span > 1)\n'\
1113	'						args += " rowspan="+cell.span;\n'\
1114	'					if((col == devidx) && (row == 0))\n'\
1115	'						args += " class=tdhl";\n'\
1116	'					if(resume)\n'\
1117	'						html += "<td"+args+">"+cell.name+" &rarr;</td>";\n'\
1118	'					else\n'\
1119	'						html += "<td"+args+">&larr; "+cell.name+"</td>";\n'\
1120	'				}\n'\
1121	'			html += "</tr>";\n'\
1122	'		}\n'\
1123	'		html += "</table>";\n'\
1124	'		return html;\n'\
1125	'	}\n'\
1126	'	function zoomTimeline() {\n'\
1127	'		var timescale = document.getElementById("timescale");\n'\
1128	'		var dmesg = document.getElementById("dmesg");\n'\
1129	'		var zoombox = document.getElementById("dmesgzoombox");\n'\
1130	'		var val = parseFloat(dmesg.style.width);\n'\
1131	'		var newval = 100;\n'\
1132	'		var sh = window.outerWidth / 2;\n'\
1133	'		if(this.id == "zoomin") {\n'\
1134	'			newval = val * 1.2;\n'\
1135	'			if(newval > 40000) newval = 40000;\n'\
1136	'			dmesg.style.width = newval+"%";\n'\
1137	'			zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
1138	'		} else if (this.id == "zoomout") {\n'\
1139	'			newval = val / 1.2;\n'\
1140	'			if(newval < 100) newval = 100;\n'\
1141	'			dmesg.style.width = newval+"%";\n'\
1142	'			zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
1143	'		} else {\n'\
1144	'			zoombox.scrollLeft = 0;\n'\
1145	'			dmesg.style.width = "100%";\n'\
1146	'		}\n'\
1147	'		var html = "";\n'\
1148	'		var t0 = bounds[0];\n'\
1149	'		var tMax = bounds[1];\n'\
1150	'		var tTotal = tMax - t0;\n'\
1151	'		var wTotal = tTotal * 100.0 / newval;\n'\
1152	'		for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\
1153	'		if(tS < 1) tS = 1;\n'\
1154	'		for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
1155	'			var pos = (tMax - s) * 100.0 / tTotal;\n'\
1156	'			var name = (s == 0)?"S/R":(s+"ms");\n'\
1157	'			html += \"<div class=\\\"t\\\" style=\\\"right:\"+pos+\"%\\\">\"+name+\"</div>\";\n'\
1158	'		}\n'\
1159	'		timescale.innerHTML = html;\n'\
1160	'	}\n'\
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1161	'	function deviceDetail() {\n'\
1162	'		var devtitle = document.getElementById("devicedetail");\n'\
1163	'		devtitle.innerHTML = "<h1>"+this.title+"</h1>";\n'\
1164	'		var devtree = document.getElementById("devicetree");\n'\
1165	'		devtree.innerHTML = deviceTree(this.id, (this.title.indexOf("resume") >= 0));\n'\
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1166	'		var cglist = document.getElementById("callgraphs");\n'\
1167	'		if(!cglist) return;\n'\
1168	'		var cg = cglist.getElementsByClassName("atop");\n'\
1169	'		for (var i = 0; i < cg.length; i++) {\n'\
1170	'			if(filter.indexOf(cg[i].id) >= 0) {\n'\
1171	'				cg[i].style.display = "block";\n'\
1172	'			} else {\n'\
1173	'				cg[i].style.display = "none";\n'\
1174	'			}\n'\
1175	'		}\n'\
1176	'	}\n'\
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1177	'	window.addEventListener("load", function () {\n'\
1178	'		var dmesg = document.getElementById("dmesg");\n'\
1179	'		dmesg.style.width = "100%"\n'\
1180	'		document.getElementById("zoomin").onclick = zoomTimeline;\n'\
1181	'		document.getElementById("zoomout").onclick = zoomTimeline;\n'\
1182	'		document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
 
 
 
1183	'		var dev = dmesg.getElementsByClassName("thread");\n'\
1184	'		for (var i = 0; i < dev.length; i++) {\n'\
1185	'			dev[i].onclick = deviceDetail;\n'\
 
 
1186	'		}\n'\
1187	'		zoomTimeline();\n'\
1188	'	});\n'\
1189	'</script>\n'
1190	hf.write(script_code);
1191
1192# Function: executeSuspend
1193# Description:
1194#	 Execute system suspend through the sysfs interface
 
1195def executeSuspend():
1196	global sysvals, data
1197
1198	detectUSB()
1199	pf = open(sysvals.powerfile, 'w')
1200	# clear the kernel ring buffer just as we start
1201	os.system("dmesg -C")
1202	# start ftrace
1203	if(data.useftrace):
1204		print("START TRACING")
1205		os.system("echo 1 > "+sysvals.tpath+"tracing_on")
1206		os.system("echo SUSPEND START > "+sysvals.tpath+"trace_marker")
1207	# initiate suspend
1208	if(sysvals.rtcwake):
1209		print("SUSPEND START")
1210		os.system("rtcwake -s 10 -m "+sysvals.suspendmode)
1211	else:
1212		print("SUSPEND START (press a key to resume)")
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1213		pf.write(sysvals.suspendmode)
1214	# execution will pause here
1215	pf.close()
1216	# return from suspend
1217	print("RESUME COMPLETE")
1218	# stop ftrace
1219	if(data.useftrace):
1220		os.system("echo RESUME COMPLETE > "+sysvals.tpath+"trace_marker")
1221		os.system("echo 0 > "+sysvals.tpath+"tracing_on")
1222		print("CAPTURING FTRACE")
1223		os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.ftracefile)
1224		os.system("cat "+sysvals.tpath+"trace >> "+sysvals.ftracefile)
1225	# grab a copy of the dmesg output
1226	print("CAPTURING DMESG")
1227	os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.dmesgfile)
1228	os.system("dmesg -c >> "+sysvals.dmesgfile)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1229
1230# Function: detectUSB
1231# Description:
1232#	 Detect all the USB hosts and devices currently connected
1233def detectUSB():
1234	global sysvals, data
1235
1236	for dirname, dirnames, filenames in os.walk("/sys/devices"):
1237		if(re.match(r".*/usb[0-9]*.*", dirname) and
1238			"idVendor" in filenames and "idProduct" in filenames):
1239			vid = os.popen("cat %s/idVendor 2>/dev/null" % dirname).read().replace('\n', '')
1240			pid = os.popen("cat %s/idProduct 2>/dev/null" % dirname).read().replace('\n', '')
1241			product = os.popen("cat %s/product 2>/dev/null" % dirname).read().replace('\n', '')
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1242			name = dirname.split('/')[-1]
1243			if(len(product) > 0):
1244				data.altdevname[name] = "%s [%s]" % (product, name)
 
1245			else:
1246				data.altdevname[name] = "%s:%s [%s]" % (vid, pid, name)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1247
 
 
 
 
 
1248def getModes():
1249	global sysvals
1250	modes = ""
1251	if(os.path.exists(sysvals.powerfile)):
1252		fp = open(sysvals.powerfile, 'r')
1253		modes = string.split(fp.read())
1254		fp.close()
 
 
 
 
 
1255	return modes
1256
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1257# Function: statusCheck
1258# Description:
1259#	 Verify that the requested command and options will work
1260def statusCheck(dryrun):
1261	global sysvals, data
1262	res = dict()
1263
1264	if(data.notestrun):
1265		print("SUCCESS: The command should run!")
1266		return
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1267
1268	# check we have root access
1269	check = "YES"
1270	if(os.environ['USER'] != "root"):
1271		if(not dryrun):
1272			doError("root access is required", False)
1273		check = "NO"
1274	res["    have root access:     "] = check
 
 
 
 
 
 
 
 
 
1275
1276	# check sysfs is mounted
1277	check = "YES"
1278	if(not os.path.exists(sysvals.powerfile)):
1279		if(not dryrun):
1280			doError("sysfs must be mounted", False)
1281		check = "NO"
1282	res["    is sysfs mounted:     "] = check
 
 
 
 
 
 
1283
1284	# check target mode is a valid mode
1285	check = "YES"
1286	modes = getModes()
1287	if(sysvals.suspendmode not in modes):
1288		if(not dryrun):
1289			doError("%s is not a value power mode" % sysvals.suspendmode, False)
1290		check = "NO"
1291	res["    is "+sysvals.suspendmode+" a power mode: "] = check
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1292
1293	# check if ftrace is available
1294	if(data.useftrace):
1295		check = "YES"
1296		if(not verifyFtrace()):
1297			if(not dryrun):
1298				doError("ftrace is not configured", False)
1299			check = "NO"
1300		res["    is ftrace usable:     "] = check
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1301
1302	# check if rtcwake
1303	if(sysvals.rtcwake):
1304		check = "YES"
1305		version = os.popen("rtcwake -V 2>/dev/null").read()
1306		if(not version.startswith("rtcwake")):
1307			if(not dryrun):
1308				doError("rtcwake is not installed", False)
1309			check = "NO"
1310		res["    is rtcwake usable:    "] = check
1311
1312	if(dryrun):
1313		status = True
1314		print("Checking if system can run the current command:")
1315		for r in res:
1316			print("%s\t%s" % (r, res[r]))
1317			if(res[r] != "YES"):
1318				status = False
1319		if(status):
1320			print("SUCCESS: The command should run!")
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1321		else:
1322			print("FAILURE: The command won't run!")
 
 
 
 
 
 
 
1323
 
 
 
 
 
1324def printHelp():
1325	global sysvals
1326	modes = getModes()
1327
1328	print("")
1329	print("AnalyzeSuspend")
1330	print("Usage: sudo analyze_suspend.py <options>")
1331	print("")
1332	print("Description:")
1333	print("  Initiates a system suspend/resume while capturing dmesg")
1334	print("  and (optionally) ftrace data to analyze device timing")
1335	print("")
1336	print("  Generates output files in subdirectory: suspend-mmddyy-HHMMSS")
1337	print("   HTML output:                    <hostname>_<mode>.html")
1338	print("   raw dmesg output:               <hostname>_<mode>_dmesg.txt")
1339	print("   raw ftrace output (with -f):    <hostname>_<mode>_ftrace.txt")
1340	print("")
1341	print("Options:")
1342	print("  [general]")
1343	print("    -h        Print this help text")
1344	print("    -verbose  Print extra information during execution and analysis")
1345	print("    -status   Test to see if the system is enabled to run this tool")
1346	print("    -modes    List available suspend modes")
1347	print("    -m mode   Mode to initiate for suspend %s (default: %s)") % (modes, sysvals.suspendmode)
1348	print("    -rtcwake  Use rtcwake to autoresume after 10 seconds (default: disabled)")
1349	print("    -f        Use ftrace to create device callgraphs (default: disabled)")
1350	print("  [re-analyze data from previous runs]")
1351	print("    -dmesg dmesgfile      Create HTML timeline from dmesg file")
1352	print("    -ftrace ftracefile    Create HTML callgraph from ftrace file")
1353	print("")
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1354	return True
1355
1356def doError(msg, help):
1357	print("ERROR: %s") % msg
1358	if(help == True):
1359		printHelp()
1360	sys.exit()
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
1361
1362# -- script main --
1363# loop through the command line arguments
1364cmd = ""
1365args = iter(sys.argv[1:])
1366for arg in args:
1367	if(arg == "-m"):
1368		try:
1369			val = args.next()
1370		except:
1371			doError("No mode supplied", True)
1372		sysvals.suspendmode = val
1373	elif(arg == "-f"):
1374		data.useftrace = True
1375	elif(arg == "-modes"):
1376		cmd = "modes"
1377	elif(arg == "-status"):
1378		cmd = "status"
1379	elif(arg == "-verbose"):
1380		data.verbose = True
1381	elif(arg == "-rtcwake"):
1382		sysvals.rtcwake = True
1383	elif(arg == "-dmesg"):
1384		try:
1385			val = args.next()
1386		except:
1387			doError("No dmesg file supplied", True)
1388		data.notestrun = True
1389		data.usedmesg = True
1390		sysvals.dmesgfile = val
1391	elif(arg == "-ftrace"):
1392		try:
1393			val = args.next()
1394		except:
1395			doError("No ftrace file supplied", True)
1396		data.notestrun = True
1397		data.useftrace = True
1398		sysvals.ftracefile = val
1399	elif(arg == "-h"):
1400		printHelp()
1401		sys.exit()
1402	else:
1403		doError("Invalid argument: "+arg, True)
1404
1405# just run a utility command and exit
1406if(cmd != ""):
1407	if(cmd == "status"):
1408		statusCheck(True)
1409	elif(cmd == "modes"):
1410		modes = getModes()
1411		print modes
1412	sys.exit()
1413
1414data.initialize()
 
 
 
1415
1416# if instructed, re-analyze existing data files
1417if(data.notestrun):
1418	sysvals.setOutputFile()
1419	data.vprint("Output file: %s" % sysvals.htmlfile)
1420	if(sysvals.dmesgfile != ""):
1421		analyzeKernelLog()
1422	if(sysvals.ftracefile != ""):
1423		analyzeTraceLog()
1424	createHTML()
1425	sys.exit()
1426
1427# verify that we can run a test
1428data.usedmesg = True
1429statusCheck(False)
1430
1431# prepare for the test
1432if(data.useftrace):
1433	initFtrace()
1434sysvals.initTestOutput()
1435
1436data.vprint("Output files:\n    %s" % sysvals.dmesgfile)
1437if(data.useftrace):
1438	data.vprint("    %s" % sysvals.ftracefile)
1439data.vprint("    %s" % sysvals.htmlfile)
1440
1441# execute the test
1442executeSuspend()
1443analyzeKernelLog()
1444if(data.useftrace):
1445	analyzeTraceLog()
1446createHTML()