~hc/RK356X_SDK_RELEASE.git

..	..	@@ -1,4 +1,5 @@
1		-#!/usr/bin/python2
	1	+#!/usr/bin/env python3
	2	+# SPDX-License-Identifier: GPL-2.0-only
2	3	#
3	4	# Tool for analyzing suspend/resume timing
4	5	# Copyright (c) 2013, Intel Corporation.
..	..	@@ -17,9 +18,9 @@
17	18	#
18	19	# Links:
19	20	# Home Page
20		-# https://01.org/suspendresume
	21	+# https://01.org/pm-graph
21	22	# Source repo
22		-# git@github.com:01org/pm-graph
	23	+# git@github.com:intel/pm-graph
23	24	#
24	25	# Description:
25	26	# This tool is designed to assist kernel and OS developers in optimizing
..	..	@@ -32,6 +33,7 @@
32	33	# viewed in firefox or chrome.
33	34	#
34	35	# The following kernel build options are required:
	36	+# CONFIG_DEVMEM=y
35	37	# CONFIG_PM_DEBUG=y
36	38	# CONFIG_PM_SLEEP_DEBUG=y
37	39	# CONFIG_FTRACE=y
..	..	@@ -54,12 +56,22 @@
54	56	import string
55	57	import re
56	58	import platform
57		-from datetime import datetime
	59	+import signal
	60	+import codecs
	61	+from datetime import datetime, timedelta
58	62	import struct
59		-import ConfigParser
	63	+import configparser
60	64	import gzip
61	65	from threading import Thread
62	66	from subprocess import call, Popen, PIPE
	67	+import base64
	68	+
	69	+def pprint(msg):
	70	+ print(msg)
	71	+ sys.stdout.flush()
	72	+
	73	+def ascii(text):
	74	+ return text.decode('ascii', 'ignore')
63	75
64	76	# ----------------- CLASSES --------------------
65	77
..	..	@@ -69,22 +81,25 @@
69	81	# store system values and test parameters
70	82	class SystemValues:
71	83	title = 'SleepGraph'
72		- version = '5.1'
	84	+ version = '5.7'
73	85	ansi = False
74	86	rs = 0
75		- display = 0
	87	+ display = ''
76	88	gzip = False
77	89	sync = False
	90	+ wifi = False
78	91	verbose = False
79	92	testlog = True
80		- dmesglog = False
	93	+ dmesglog = True
81	94	ftracelog = False
	95	+ tstat = True
82	96	mindevlen = 0.0
83	97	mincglen = 0.0
84	98	cgphase = ''
85	99	cgtest = -1
86	100	cgskip = ''
87		- multitest = {'run': False, 'count': 0, 'delay': 0}
	101	+ maxfail = 0
	102	+ multitest = {'run': False, 'count': 1000000, 'delay': 0}
88	103	max_graph_depth = 0
89	104	callloopmaxgap = 0.0001
90	105	callloopmaxlen = 0.005
..	..	@@ -99,8 +114,11 @@
99	114	tpath = '/sys/kernel/debug/tracing/'
100	115	fpdtpath = '/sys/firmware/acpi/tables/FPDT'
101	116	epath = '/sys/kernel/debug/tracing/events/power/'
	117	+ pmdpath = '/sys/power/pm_debug_messages'
102	118	traceevents = [
103	119	'suspend_resume',
	120	+ 'wakeup_source_activate',
	121	+ 'wakeup_source_deactivate',
104	122	'device_pm_callback_end',
105	123	'device_pm_callback_start'
106	124	]
..	..	@@ -109,8 +127,10 @@
109	127	mempath = '/dev/mem'
110	128	powerfile = '/sys/power/state'
111	129	mempowerfile = '/sys/power/mem_sleep'
	130	+ diskpowerfile = '/sys/power/disk'
112	131	suspendmode = 'mem'
113	132	memmode = ''
	133	+ diskmode = ''
114	134	hostname = 'localhost'
115	135	prefix = 'test'
116	136	teststamp = ''
..	..	@@ -130,6 +150,8 @@
130	150	x2delay = 0
131	151	skiphtml = False
132	152	usecallgraph = False
	153	+ ftopfunc = 'pm_suspend'
	154	+ ftop = False
133	155	usetraceevents = False
134	156	usetracemarkers = True
135	157	usekprobes = True
..	..	@@ -137,17 +159,19 @@
137	159	useprocmon = False
138	160	notestrun = False
139	161	cgdump = False
	162	+ devdump = False
140	163	mixedphaseheight = True
141	164	devprops = dict()
	165	+ platinfo = []
142	166	predelay = 0
143	167	postdelay = 0
144		- procexecfmt = 'ps - (?P<ps>.*)$'
145		- devpropfmt = '# Device Properties: .*'
146		- tracertypefmt = '# tracer: (?P<t>.*)'
147		- firmwarefmt = '# fwsuspend (?P<s>[0-9]) fwresume (?P<r>[0-9])$'
	168	+ pmdebug = ''
	169	+ tmstart = 'SUSPEND START %Y%m%d-%H:%M:%S.%f'
	170	+ tmend = 'RESUME COMPLETE %Y%m%d-%H:%M:%S.%f'
148	171	tracefuncs = {
149	172	'sys_sync': {},
150		- '__pm_notifier_call_chain': {},
	173	+ 'ksys_sync': {},
	174	+ 'pm_notifier_call_chain_robust': {},
151	175	'pm_prepare_console': {},
152	176	'pm_notifier_call_chain': {},
153	177	'freeze_processes': {},
..	..	@@ -159,6 +183,15 @@
159	183	'acpi_hibernation_leave': {},
160	184	'acpi_pm_freeze': {},
161	185	'acpi_pm_thaw': {},
	186	+ 'acpi_s2idle_end': {},
	187	+ 'acpi_s2idle_sync': {},
	188	+ 'acpi_s2idle_begin': {},
	189	+ 'acpi_s2idle_prepare': {},
	190	+ 'acpi_s2idle_prepare_late': {},
	191	+ 'acpi_s2idle_wake': {},
	192	+ 'acpi_s2idle_wakeup': {},
	193	+ 'acpi_s2idle_restore': {},
	194	+ 'acpi_s2idle_restore_early': {},
162	195	'hibernate_preallocate_memory': {},
163	196	'create_basic_memory_bitmaps': {},
164	197	'swsusp_write': {},
..	..	@@ -187,18 +220,25 @@
187	220	dev_tracefuncs = {
188	221	# general wait/delay/sleep
189	222	'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
190		- 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
191	223	'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
192	224	'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
193	225	'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
194	226	'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
195	227	'acpi_os_stall': {'ub': 1},
	228	+ 'rt_mutex_slowlock': {'ub': 1},
196	229	# ACPI
197	230	'acpi_resume_power_resources': {},
198		- 'acpi_ps_parse_aml': {},
	231	+ 'acpi_ps_execute_method': { 'args_x86_64': {
	232	+ 'fullpath':'+0(+40(%di)):string',
	233	+ }},
	234	+ # mei_me
	235	+ 'mei_reset': {},
199	236	# filesystem
200	237	'ext4_sync_fs': {},
201	238	# 80211
	239	+ 'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} },
	240	+ 'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} },
	241	+ 'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} },
202	242	'iwlagn_mac_start': {},
203	243	'iwlagn_alloc_bcast_station': {},
204	244	'iwl_trans_pcie_start_hw': {},
..	..	@@ -236,11 +276,24 @@
236	276	'intel_opregion_init': {},
237	277	'intel_fbdev_set_suspend': {},
238	278	}
	279	+ infocmds = [
	280	+ [0, 'kparams', 'cat', '/proc/cmdline'],
	281	+ [0, 'mcelog', 'mcelog'],
	282	+ [0, 'pcidevices', 'lspci', '-tv'],
	283	+ [0, 'usbdevices', 'lsusb', '-t'],
	284	+ [1, 'interrupts', 'cat', '/proc/interrupts'],
	285	+ [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'],
	286	+ [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'],
	287	+ [2, 'suspendstats', 'sh', '-c', 'grep -v invalid /sys/power/suspend_stats/*'],
	288	+ [2, 'cpuidle', 'sh', '-c', 'grep -v invalid /sys/devices/system/cpu/cpu/cpuidle/state/s2idle/*'],
	289	+ [2, 'battery', 'sh', '-c', 'grep -v invalid /sys/class/power_supply//'],
	290	+ ]
239	291	cgblacklist = []
240	292	kprobes = dict()
241	293	timeformat = '%.3f'
242	294	cmdline = '%s %s' % \
243	295	(os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
	296	+ sudouser = ''
244	297	def __init__(self):
245	298	self.archargs = 'args_'+platform.machine()
246	299	self.hostname = platform.node()
..	..	@@ -256,36 +309,70 @@
256	309	if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
257	310	self.ansi = True
258	311	self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
	312	+ if os.getuid() == 0 and 'SUDO_USER' in os.environ and \
	313	+ os.environ['SUDO_USER']:
	314	+ self.sudouser = os.environ['SUDO_USER']
	315	+ def resetlog(self):
	316	+ self.logmsg = ''
	317	+ self.platinfo = []
259	318	def vprint(self, msg):
260	319	self.logmsg += msg+'\n'
261		- if(self.verbose):
262		- print(msg)
	320	+ if self.verbose or msg.startswith('WARNING:'):
	321	+ pprint(msg)
	322	+ def signalHandler(self, signum, frame):
	323	+ if not self.result:
	324	+ return
	325	+ signame = self.signames[signum] if signum in self.signames else 'UNKNOWN'
	326	+ msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno)
	327	+ self.outputResult({'error':msg})
	328	+ sys.exit(3)
	329	+ def signalHandlerInit(self):
	330	+ capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT',
	331	+ 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM']
	332	+ self.signames = dict()
	333	+ for i in capture:
	334	+ s = 'SIG'+i
	335	+ try:
	336	+ signum = getattr(signal, s)
	337	+ signal.signal(signum, self.signalHandler)
	338	+ except:
	339	+ continue
	340	+ self.signames[signum] = s
263	341	def rootCheck(self, fatal=True):
264	342	if(os.access(self.powerfile, os.W_OK)):
265	343	return True
266	344	if fatal:
267	345	msg = 'This command requires sysfs mount and root access'
268		- print('ERROR: %s\n') % msg
	346	+ pprint('ERROR: %s\n' % msg)
269	347	self.outputResult({'error':msg})
270		- sys.exit()
	348	+ sys.exit(1)
271	349	return False
272	350	def rootUser(self, fatal=False):
273	351	if 'USER' in os.environ and os.environ['USER'] == 'root':
274	352	return True
275	353	if fatal:
276	354	msg = 'This command must be run as root'
277		- print('ERROR: %s\n') % msg
	355	+ pprint('ERROR: %s\n' % msg)
278	356	self.outputResult({'error':msg})
279		- sys.exit()
	357	+ sys.exit(1)
280	358	return False
	359	+ def usable(self, file):
	360	+ return (os.path.exists(file) and os.path.getsize(file) > 0)
281	361	def getExec(self, cmd):
282		- dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
283		- '/usr/local/sbin', '/usr/local/bin']
284		- for path in dirlist:
	362	+ try:
	363	+ fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout
	364	+ out = ascii(fp.read()).strip()
	365	+ fp.close()
	366	+ except:
	367	+ out = ''
	368	+ if out:
	369	+ return out
	370	+ for path in ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
	371	+ '/usr/local/sbin', '/usr/local/bin']:
285	372	cmdfull = os.path.join(path, cmd)
286	373	if os.path.exists(cmdfull):
287	374	return cmdfull
288		- return ''
	375	+ return out
289	376	def setPrecision(self, num):
290	377	if num < 0 or num > 6:
291	378	return
..	..	@@ -296,6 +383,7 @@
296	383	args['date'] = n.strftime('%y%m%d')
297	384	args['time'] = n.strftime('%H%M%S')
298	385	args['hostname'] = args['host'] = self.hostname
	386	+ args['mode'] = self.suspendmode
299	387	return value.format(**args)
300	388	def setOutputFile(self):
301	389	if self.dmesgfile != '':
..	..	@@ -307,21 +395,22 @@
307	395	if(m):
308	396	self.htmlfile = m.group('name')+'.html'
309	397	def systemInfo(self, info):
310		- p = c = m = b = ''
	398	+ p = m = ''
311	399	if 'baseboard-manufacturer' in info:
312	400	m = info['baseboard-manufacturer']
313	401	elif 'system-manufacturer' in info:
314	402	m = info['system-manufacturer']
315		- if 'baseboard-product-name' in info:
316		- p = info['baseboard-product-name']
317		- elif 'system-product-name' in info:
	403	+ if 'system-product-name' in info:
318	404	p = info['system-product-name']
319		- if 'processor-version' in info:
320		- c = info['processor-version']
321		- if 'bios-version' in info:
322		- b = info['bios-version']
323		- self.sysstamp = '# sysinfo \| man:%s \| plat:%s \| cpu:%s \| bios:%s \| numcpu:%d \| memsz:%d \| memfr:%d' % \
324		- (m, p, c, b, self.cpucount, self.memtotal, self.memfree)
	405	+ elif 'baseboard-product-name' in info:
	406	+ p = info['baseboard-product-name']
	407	+ if m[:5].lower() == 'intel' and 'baseboard-product-name' in info:
	408	+ p = info['baseboard-product-name']
	409	+ c = info['processor-version'] if 'processor-version' in info else ''
	410	+ b = info['bios-version'] if 'bios-version' in info else ''
	411	+ r = info['bios-release-date'] if 'bios-release-date' in info else ''
	412	+ self.sysstamp = '# sysinfo \| man:%s \| plat:%s \| cpu:%s \| bios:%s \| biosdate:%s \| numcpu:%d \| memsz:%d \| memfr:%d' % \
	413	+ (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree)
325	414	def printSystemInfo(self, fatal=False):
326	415	self.rootCheck(True)
327	416	out = dmidecode(self.mempath, fatal)
..	..	@@ -329,10 +418,10 @@
329	418	return
330	419	fmt = '%-24s: %s'
331	420	for name in sorted(out):
332		- print fmt % (name, out[name])
333		- print fmt % ('cpucount', ('%d' % self.cpucount))
334		- print fmt % ('memtotal', ('%d kB' % self.memtotal))
335		- print fmt % ('memfree', ('%d kB' % self.memfree))
	421	+ print(fmt % (name, out[name]))
	422	+ print(fmt % ('cpucount', ('%d' % self.cpucount)))
	423	+ print(fmt % ('memtotal', ('%d kB' % self.memtotal)))
	424	+ print(fmt % ('memfree', ('%d kB' % self.memfree)))
336	425	def cpuInfo(self):
337	426	self.cpucount = 0
338	427	fp = open('/proc/cpuinfo', 'r')
..	..	@@ -352,7 +441,7 @@
352	441	def initTestOutput(self, name):
353	442	self.prefix = self.hostname
354	443	v = open('/proc/version', 'r').read().strip()
355		- kver = string.split(v)[2]
	444	+ kver = v.split()[2]
356	445	fmt = name+'-%m%d%y-%H%M%S'
357	446	testtime = datetime.now().strftime(fmt)
358	447	self.teststamp = \
..	..	@@ -367,7 +456,8 @@
367	456	self.htmlfile = \
368	457	self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
369	458	if not os.path.isdir(self.testdir):
370		- os.mkdir(self.testdir)
	459	+ os.makedirs(self.testdir)
	460	+ self.sudoUserchown(self.testdir)
371	461	def getValueList(self, value):
372	462	out = []
373	463	for i in value.split(','):
..	..	@@ -378,6 +468,12 @@
378	468	self.devicefilter = self.getValueList(value)
379	469	def setCallgraphFilter(self, value):
380	470	self.cgfilter = self.getValueList(value)
	471	+ def skipKprobes(self, value):
	472	+ for k in self.getValueList(value):
	473	+ if k in self.tracefuncs:
	474	+ del self.tracefuncs[k]
	475	+ if k in self.dev_tracefuncs:
	476	+ del self.dev_tracefuncs[k]
381	477	def setCallgraphBlacklist(self, file):
382	478	self.cgblacklist = self.listFromFile(file)
383	479	def rtcWakeAlarmOn(self):
..	..	@@ -397,7 +493,7 @@
397	493	fp = Popen('dmesg', stdout=PIPE).stdout
398	494	ktime = '0'
399	495	for line in fp:
400		- line = line.replace('\r\n', '')
	496	+ line = ascii(line).replace('\r\n', '')
401	497	idx = line.find('[')
402	498	if idx > 1:
403	499	line = line[idx:]
..	..	@@ -406,12 +502,12 @@
406	502	ktime = m.group('ktime')
407	503	fp.close()
408	504	self.dmesgstart = float(ktime)
409		- def getdmesg(self, fwdata=[]):
410		- op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata)
	505	+ def getdmesg(self, testdata):
	506	+ op = self.writeDatafileHeader(self.dmesgfile, testdata)
411	507	# store all new dmesg lines since initdmesg was called
412	508	fp = Popen('dmesg', stdout=PIPE).stdout
413	509	for line in fp:
414		- line = line.replace('\r\n', '')
	510	+ line = ascii(line).replace('\r\n', '')
415	511	idx = line.find('[')
416	512	if idx > 1:
417	513	line = line[idx:]
..	..	@@ -443,13 +539,13 @@
443	539	call('cat '+self.tpath+'available_filter_functions', shell=True)
444	540	return
445	541	master = self.listFromFile(self.tpath+'available_filter_functions')
446		- for i in self.tracefuncs:
	542	+ for i in sorted(self.tracefuncs):
447	543	if 'func' in self.tracefuncs[i]:
448	544	i = self.tracefuncs[i]['func']
449	545	if i in master:
450		- print i
	546	+ print(i)
451	547	else:
452		- print self.colorText(i)
	548	+ print(self.colorText(i))
453	549	def setFtraceFilterFunctions(self, list):
454	550	master = self.listFromFile(self.tpath+'available_filter_functions')
455	551	flist = ''
..	..	@@ -535,7 +631,7 @@
535	631	if len(self.kprobes) < 1:
536	632	return
537	633	if output:
538		- print(' kprobe functions in this kernel:')
	634	+ pprint(' kprobe functions in this kernel:')
539	635	# first test each kprobe
540	636	rejects = []
541	637	# sort kprobes: trace, ub-dev, custom, dev
..	..	@@ -557,7 +653,7 @@
557	653	else:
558	654	kpl[2].append(name)
559	655	if output:
560		- print(' %s: %s' % (name, res))
	656	+ pprint(' %s: %s' % (name, res))
561	657	kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
562	658	# remove all failed ones from the list
563	659	for name in rejects:
..	..	@@ -570,8 +666,8 @@
570	666	self.fsetVal(kprobeevents, 'kprobe_events')
571	667	if output:
572	668	check = self.fgetVal('kprobe_events')
573		- linesack = (len(check.split('\n')) - 1) / 2
574		- print(' kprobe functions enabled: %d/%d' % (linesack, linesout))
	669	+ linesack = (len(check.split('\n')) - 1) // 2
	670	+ pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout))
575	671	self.fsetVal('1', 'events/kprobes/enable')
576	672	def testKprobe(self, kname, kprobe):
577	673	self.fsetVal('0', 'events/kprobes/enable')
..	..	@@ -588,19 +684,19 @@
588	684	if linesack < linesout:
589	685	return False
590	686	return True
591		- def setVal(self, val, file, mode='w'):
	687	+ def setVal(self, val, file):
592	688	if not os.path.exists(file):
593	689	return False
594	690	try:
595		- fp = open(file, mode, 0)
596		- fp.write(val)
	691	+ fp = open(file, 'wb', 0)
	692	+ fp.write(val.encode())
597	693	fp.flush()
598	694	fp.close()
599	695	except:
600	696	return False
601	697	return True
602		- def fsetVal(self, val, path, mode='w'):
603		- return self.setVal(val, self.tpath+path, mode)
	698	+ def fsetVal(self, val, path):
	699	+ return self.setVal(val, self.tpath+path)
604	700	def getVal(self, file):
605	701	res = ''
606	702	if not os.path.exists(file):
..	..	@@ -619,6 +715,8 @@
619	715	self.fsetVal('0', 'events/kprobes/enable')
620	716	self.fsetVal('', 'kprobe_events')
621	717	self.fsetVal('1024', 'buffer_size_kb')
	718	+ if self.pmdebug:
	719	+ self.setVal(self.pmdebug, self.pmdpath)
622	720	def setupAllKprobes(self):
623	721	for name in self.tracefuncs:
624	722	self.defaultKprobe(name, self.tracefuncs[name])
..	..	@@ -635,12 +733,18 @@
635	733	if name == f:
636	734	return True
637	735	return False
638		- def initFtrace(self):
639		- self.printSystemInfo(False)
640		- print('INITIALIZING FTRACE...')
	736	+ def initFtrace(self, quiet=False):
	737	+ if not quiet:
	738	+ sysvals.printSystemInfo(False)
	739	+ pprint('INITIALIZING FTRACE...')
641	740	# turn trace off
642	741	self.fsetVal('0', 'tracing_on')
643	742	self.cleanupFtrace()
	743	+ # pm debug messages
	744	+ pv = self.getVal(self.pmdpath)
	745	+ if pv != '1':
	746	+ self.setVal('1', self.pmdpath)
	747	+ self.pmdebug = pv
644	748	# set the trace clock to global
645	749	self.fsetVal('global', 'trace_clock')
646	750	self.fsetVal('nop', 'current_tracer')
..	..	@@ -649,16 +753,18 @@
649	753	if self.bufsize > 0:
650	754	tgtsize = self.bufsize
651	755	elif self.usecallgraph or self.usedevsrc:
652		- tgtsize = min(self.memfree, 310241024)
	756	+ bmax = (110241024) if self.suspendmode in ['disk', 'command'] \
	757	+ else (310241024)
	758	+ tgtsize = min(self.memfree, bmax)
653	759	else:
654	760	tgtsize = 65536
655		- while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
	761	+ while not self.fsetVal('%d' % (tgtsize // cpus), 'buffer_size_kb'):
656	762	# if the size failed to set, lower it and keep trying
657	763	tgtsize -= 65536
658	764	if tgtsize < 65536:
659	765	tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
660	766	break
661		- print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)
	767	+ self.vprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus))
662	768	# initialize the callgraph trace
663	769	if(self.usecallgraph):
664	770	# set trace type
..	..	@@ -683,7 +789,10 @@
683	789	cf.append(self.tracefuncs[fn]['func'])
684	790	else:
685	791	cf.append(fn)
686		- self.setFtraceFilterFunctions(cf)
	792	+ if self.ftop:
	793	+ self.setFtraceFilterFunctions([self.ftopfunc])
	794	+ else:
	795	+ self.setFtraceFilterFunctions(cf)
687	796	# initialize the kprobe trace
688	797	elif self.usekprobes:
689	798	for name in self.tracefuncs:
..	..	@@ -691,7 +800,8 @@
691	800	if self.usedevsrc:
692	801	for name in self.dev_tracefuncs:
693	802	self.defaultKprobe(name, self.dev_tracefuncs[name])
694		- print('INITIALIZING KPROBES...')
	803	+ if not quiet:
	804	+ pprint('INITIALIZING KPROBES...')
695	805	self.addKprobes(self.verbose)
696	806	if(self.usetraceevents):
697	807	# turn trace events on
..	..	@@ -728,19 +838,25 @@
728	838	if not self.ansi:
729	839	return str
730	840	return '\x1B[%d;40m%s\x1B[m' % (color, str)
731		- def writeDatafileHeader(self, filename, fwdata=[]):
	841	+ def writeDatafileHeader(self, filename, testdata):
732	842	fp = self.openlog(filename, 'w')
733	843	fp.write('%s\n%s\n# command \| %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
734		- if(self.suspendmode == 'mem' or self.suspendmode == 'command'):
735		- for fw in fwdata:
	844	+ for test in testdata:
	845	+ if 'fw' in test:
	846	+ fw = test['fw']
736	847	if(fw):
737	848	fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
	849	+ if 'turbo' in test:
	850	+ fp.write('# turbostat %s\n' % test['turbo'])
	851	+ if 'wifi' in test:
	852	+ fp.write('# wifi %s\n' % test['wifi'])
	853	+ if test['error'] or len(testdata) > 1:
	854	+ fp.write('# enter_sleep_error %s\n' % test['error'])
738	855	return fp
739		- def sudouser(self, dir):
740		- if os.path.exists(dir) and os.getuid() == 0 and \
741		- 'SUDO_USER' in os.environ:
	856	+ def sudoUserchown(self, dir):
	857	+ if os.path.exists(dir) and self.sudouser:
742	858	cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
743		- call(cmd.format(os.environ['SUDO_USER'], dir), shell=True)
	859	+ call(cmd.format(self.sudouser, dir), shell=True)
744	860	def outputResult(self, testdata, num=0):
745	861	if not self.result:
746	862	return
..	..	@@ -762,7 +878,7 @@
762	878	if 'bugurl' in testdata:
763	879	fp.write('url%s: %s\n' % (n, testdata['bugurl']))
764	880	fp.close()
765		- self.sudouser(self.result)
	881	+ self.sudoUserchown(self.result)
766	882	def configFile(self, file):
767	883	dir = os.path.dirname(os.path.realpath(__file__))
768	884	if os.path.exists(file):
..	..	@@ -776,14 +892,315 @@
776	892	isgz = self.gzip
777	893	if mode == 'r':
778	894	try:
779		- with gzip.open(filename, mode+'b') as fp:
	895	+ with gzip.open(filename, mode+'t') as fp:
780	896	test = fp.read(64)
781	897	isgz = True
782	898	except:
783	899	isgz = False
784	900	if isgz:
785		- return gzip.open(filename, mode+'b')
	901	+ return gzip.open(filename, mode+'t')
786	902	return open(filename, mode)
	903	+ def b64unzip(self, data):
	904	+ try:
	905	+ out = codecs.decode(base64.b64decode(data), 'zlib').decode()
	906	+ except:
	907	+ out = data
	908	+ return out
	909	+ def b64zip(self, data):
	910	+ out = base64.b64encode(codecs.encode(data.encode(), 'zlib')).decode()
	911	+ return out
	912	+ def platforminfo(self, cmdafter):
	913	+ # add platform info on to a completed ftrace file
	914	+ if not os.path.exists(self.ftracefile):
	915	+ return False
	916	+ footer = '#\n'
	917	+
	918	+ # add test command string line if need be
	919	+ if self.suspendmode == 'command' and self.testcommand:
	920	+ footer += '# platform-testcmd: %s\n' % (self.testcommand)
	921	+
	922	+ # get a list of target devices from the ftrace file
	923	+ props = dict()
	924	+ tp = TestProps()
	925	+ tf = self.openlog(self.ftracefile, 'r')
	926	+ for line in tf:
	927	+ if tp.stampInfo(line, self):
	928	+ continue
	929	+ # parse only valid lines, if this is not one move on
	930	+ m = re.match(tp.ftrace_line_fmt, line)
	931	+ if(not m or 'device_pm_callback_start' not in line):
	932	+ continue
	933	+ m = re.match('.: (?P<drv>.) (?P<d>.), parent: (?P<p>.), .', m.group('msg'));
	934	+ if(not m):
	935	+ continue
	936	+ dev = m.group('d')
	937	+ if dev not in props:
	938	+ props[dev] = DevProps()
	939	+ tf.close()
	940	+
	941	+ # now get the syspath for each target device
	942	+ for dirname, dirnames, filenames in os.walk('/sys/devices'):
	943	+ if(re.match('.*/power', dirname) and 'async' in filenames):
	944	+ dev = dirname.split('/')[-2]
	945	+ if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
	946	+ props[dev].syspath = dirname[:-6]
	947	+
	948	+ # now fill in the properties for our target devices
	949	+ for dev in sorted(props):
	950	+ dirname = props[dev].syspath
	951	+ if not dirname or not os.path.exists(dirname):
	952	+ continue
	953	+ with open(dirname+'/power/async') as fp:
	954	+ text = fp.read()
	955	+ props[dev].isasync = False
	956	+ if 'enabled' in text:
	957	+ props[dev].isasync = True
	958	+ fields = os.listdir(dirname)
	959	+ if 'product' in fields:
	960	+ with open(dirname+'/product', 'rb') as fp:
	961	+ props[dev].altname = ascii(fp.read())
	962	+ elif 'name' in fields:
	963	+ with open(dirname+'/name', 'rb') as fp:
	964	+ props[dev].altname = ascii(fp.read())
	965	+ elif 'model' in fields:
	966	+ with open(dirname+'/model', 'rb') as fp:
	967	+ props[dev].altname = ascii(fp.read())
	968	+ elif 'description' in fields:
	969	+ with open(dirname+'/description', 'rb') as fp:
	970	+ props[dev].altname = ascii(fp.read())
	971	+ elif 'id' in fields:
	972	+ with open(dirname+'/id', 'rb') as fp:
	973	+ props[dev].altname = ascii(fp.read())
	974	+ elif 'idVendor' in fields and 'idProduct' in fields:
	975	+ idv, idp = '', ''
	976	+ with open(dirname+'/idVendor', 'rb') as fp:
	977	+ idv = ascii(fp.read()).strip()
	978	+ with open(dirname+'/idProduct', 'rb') as fp:
	979	+ idp = ascii(fp.read()).strip()
	980	+ props[dev].altname = '%s:%s' % (idv, idp)
	981	+ if props[dev].altname:
	982	+ out = props[dev].altname.strip().replace('\n', ' ')\
	983	+ .replace(',', ' ').replace(';', ' ')
	984	+ props[dev].altname = out
	985	+
	986	+ # add a devinfo line to the bottom of ftrace
	987	+ out = ''
	988	+ for dev in sorted(props):
	989	+ out += props[dev].out(dev)
	990	+ footer += '# platform-devinfo: %s\n' % self.b64zip(out)
	991	+
	992	+ # add a line for each of these commands with their outputs
	993	+ for name, cmdline, info in cmdafter:
	994	+ footer += '# platform-%s: %s \| %s\n' % (name, cmdline, self.b64zip(info))
	995	+
	996	+ with self.openlog(self.ftracefile, 'a') as fp:
	997	+ fp.write(footer)
	998	+ return True
	999	+ def commonPrefix(self, list):
	1000	+ if len(list) < 2:
	1001	+ return ''
	1002	+ prefix = list[0]
	1003	+ for s in list[1:]:
	1004	+ while s[:len(prefix)] != prefix and prefix:
	1005	+ prefix = prefix[:len(prefix)-1]
	1006	+ if not prefix:
	1007	+ break
	1008	+ if '/' in prefix and prefix[-1] != '/':
	1009	+ prefix = prefix[0:prefix.rfind('/')+1]
	1010	+ return prefix
	1011	+ def dictify(self, text, format):
	1012	+ out = dict()
	1013	+ header = True if format == 1 else False
	1014	+ delim = ' ' if format == 1 else ':'
	1015	+ for line in text.split('\n'):
	1016	+ if header:
	1017	+ header, out['@'] = False, line
	1018	+ continue
	1019	+ line = line.strip()
	1020	+ if delim in line:
	1021	+ data = line.split(delim, 1)
	1022	+ num = re.search(r'[\d]+', data[1])
	1023	+ if format == 2 and num:
	1024	+ out[data[0].strip()] = num.group()
	1025	+ else:
	1026	+ out[data[0].strip()] = data[1]
	1027	+ return out
	1028	+ def cmdinfo(self, begin, debug=False):
	1029	+ out = []
	1030	+ if begin:
	1031	+ self.cmd1 = dict()
	1032	+ for cargs in self.infocmds:
	1033	+ delta, name = cargs[0], cargs[1]
	1034	+ cmdline, cmdpath = ' '.join(cargs[2:]), self.getExec(cargs[2])
	1035	+ if not cmdpath or (begin and not delta):
	1036	+ continue
	1037	+ try:
	1038	+ fp = Popen([cmdpath]+cargs[3:], stdout=PIPE, stderr=PIPE).stdout
	1039	+ info = ascii(fp.read()).strip()
	1040	+ fp.close()
	1041	+ except:
	1042	+ continue
	1043	+ if not debug and begin:
	1044	+ self.cmd1[name] = self.dictify(info, delta)
	1045	+ elif not debug and delta and name in self.cmd1:
	1046	+ before, after = self.cmd1[name], self.dictify(info, delta)
	1047	+ dinfo = ('\t%s\n' % before['@']) if '@' in before else ''
	1048	+ prefix = self.commonPrefix(list(before.keys()))
	1049	+ for key in sorted(before):
	1050	+ if key in after and before[key] != after[key]:
	1051	+ title = key.replace(prefix, '')
	1052	+ if delta == 2:
	1053	+ dinfo += '\t%s : %s -> %s\n' % \
	1054	+ (title, before[key].strip(), after[key].strip())
	1055	+ else:
	1056	+ dinfo += '%10s (start) : %s\n%10s (after) : %s\n' % \
	1057	+ (title, before[key], title, after[key])
	1058	+ dinfo = '\tnothing changed' if not dinfo else dinfo.rstrip()
	1059	+ out.append((name, cmdline, dinfo))
	1060	+ else:
	1061	+ out.append((name, cmdline, '\tnothing' if not info else info))
	1062	+ return out
	1063	+ def haveTurbostat(self):
	1064	+ if not self.tstat:
	1065	+ return False
	1066	+ cmd = self.getExec('turbostat')
	1067	+ if not cmd:
	1068	+ return False
	1069	+ fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr
	1070	+ out = ascii(fp.read()).strip()
	1071	+ fp.close()
	1072	+ if re.match('turbostat version .*', out):
	1073	+ self.vprint(out)
	1074	+ return True
	1075	+ return False
	1076	+ def turbostat(self):
	1077	+ cmd = self.getExec('turbostat')
	1078	+ rawout = keyline = valline = ''
	1079	+ fullcmd = '%s -q -S echo freeze > %s' % (cmd, self.powerfile)
	1080	+ fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE).stderr
	1081	+ for line in fp:
	1082	+ line = ascii(line)
	1083	+ rawout += line
	1084	+ if keyline and valline:
	1085	+ continue
	1086	+ if re.match('(?i)Avg_MHz.*', line):
	1087	+ keyline = line.strip().split()
	1088	+ elif keyline:
	1089	+ valline = line.strip().split()
	1090	+ fp.close()
	1091	+ if not keyline or not valline or len(keyline) != len(valline):
	1092	+ errmsg = 'unrecognized turbostat output:\n'+rawout.strip()
	1093	+ self.vprint(errmsg)
	1094	+ if not self.verbose:
	1095	+ pprint(errmsg)
	1096	+ return ''
	1097	+ if self.verbose:
	1098	+ pprint(rawout.strip())
	1099	+ out = []
	1100	+ for key in keyline:
	1101	+ idx = keyline.index(key)
	1102	+ val = valline[idx]
	1103	+ out.append('%s=%s' % (key, val))
	1104	+ return '\|'.join(out)
	1105	+ def wifiDetails(self, dev):
	1106	+ try:
	1107	+ info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip()
	1108	+ except:
	1109	+ return dev
	1110	+ vals = [dev]
	1111	+ for prop in info.split('\n'):
	1112	+ if prop.startswith('DRIVER=') or prop.startswith('PCI_ID='):
	1113	+ vals.append(prop.split('=')[-1])
	1114	+ return ':'.join(vals)
	1115	+ def checkWifi(self, dev=''):
	1116	+ try:
	1117	+ w = open('/proc/net/wireless', 'r').read().strip()
	1118	+ except:
	1119	+ return ''
	1120	+ for line in reversed(w.split('\n')):
	1121	+ m = re.match(' (?P<dev>.): (?P<stat>[0-9a-f]) .', w.split('\n')[-1])
	1122	+ if not m or (dev and dev != m.group('dev')):
	1123	+ continue
	1124	+ return m.group('dev')
	1125	+ return ''
	1126	+ def pollWifi(self, dev, timeout=60):
	1127	+ start = time.time()
	1128	+ while (time.time() - start) < timeout:
	1129	+ w = self.checkWifi(dev)
	1130	+ if w:
	1131	+ return '%s reconnected %.2f' % \
	1132	+ (self.wifiDetails(dev), max(0, time.time() - start))
	1133	+ time.sleep(0.01)
	1134	+ return '%s timeout %d' % (self.wifiDetails(dev), timeout)
	1135	+ def errorSummary(self, errinfo, msg):
	1136	+ found = False
	1137	+ for entry in errinfo:
	1138	+ if re.match(entry['match'], msg):
	1139	+ entry['count'] += 1
	1140	+ if self.hostname not in entry['urls']:
	1141	+ entry['urls'][self.hostname] = [self.htmlfile]
	1142	+ elif self.htmlfile not in entry['urls'][self.hostname]:
	1143	+ entry['urls'][self.hostname].append(self.htmlfile)
	1144	+ found = True
	1145	+ break
	1146	+ if found:
	1147	+ return
	1148	+ arr = msg.split()
	1149	+ for j in range(len(arr)):
	1150	+ if re.match('^[0-9,\-\.]*$', arr[j]):
	1151	+ arr[j] = '[0-9,\-\.]*'
	1152	+ else:
	1153	+ arr[j] = arr[j]\
	1154	+ .replace('\\', '\\\\').replace(']', '\]').replace('[', '\[')\
	1155	+ .replace('.', '\.').replace('+', '\+').replace('', '\')\
	1156	+ .replace('(', '$').replace(')', '$').replace('}', '\}')\
	1157	+ .replace('{', '\{')
	1158	+ mstr = ' *'.join(arr)
	1159	+ entry = {
	1160	+ 'line': msg,
	1161	+ 'match': mstr,
	1162	+ 'count': 1,
	1163	+ 'urls': {self.hostname: [self.htmlfile]}
	1164	+ }
	1165	+ errinfo.append(entry)
	1166	+ def multistat(self, start, idx, finish):
	1167	+ if 'time' in self.multitest:
	1168	+ id = '%d Duration=%dmin' % (idx+1, self.multitest['time'])
	1169	+ else:
	1170	+ id = '%d/%d' % (idx+1, self.multitest['count'])
	1171	+ t = time.time()
	1172	+ if 'start' not in self.multitest:
	1173	+ self.multitest['start'] = self.multitest['last'] = t
	1174	+ self.multitest['total'] = 0.0
	1175	+ pprint('TEST (%s) START' % id)
	1176	+ return
	1177	+ dt = t - self.multitest['last']
	1178	+ if not start:
	1179	+ if idx == 0 and self.multitest['delay'] > 0:
	1180	+ self.multitest['total'] += self.multitest['delay']
	1181	+ pprint('TEST (%s) COMPLETE -- Duration %.1fs' % (id, dt))
	1182	+ return
	1183	+ self.multitest['total'] += dt
	1184	+ self.multitest['last'] = t
	1185	+ avg = self.multitest['total'] / idx
	1186	+ if 'time' in self.multitest:
	1187	+ left = finish - datetime.now()
	1188	+ left -= timedelta(microseconds=left.microseconds)
	1189	+ else:
	1190	+ left = timedelta(seconds=((self.multitest['count'] - idx) * int(avg)))
	1191	+ pprint('TEST (%s) START - Avg Duration %.1fs, Time left %s' % \
	1192	+ (id, avg, str(left)))
	1193	+ def multiinit(self, c, d):
	1194	+ sz, unit = 'count', 'm'
	1195	+ if c.endswith('d') or c.endswith('h') or c.endswith('m'):
	1196	+ sz, unit, c = 'time', c[-1], c[:-1]
	1197	+ self.multitest['run'] = True
	1198	+ self.multitest[sz] = getArgInt('multi: n d (exec count)', c, 1, 1000000, False)
	1199	+ self.multitest['delay'] = getArgInt('multi: n d (delay between tests)', d, 0, 3600, False)
	1200	+ if unit == 'd':
	1201	+ self.multitest[sz] *= 1440
	1202	+ elif unit == 'h':
	1203	+ self.multitest[sz] *= 60
787	1204
788	1205	sysvals = SystemValues()
789	1206	switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
..	..	@@ -800,15 +1217,16 @@
800	1217	# Simple class which holds property values collected
801	1218	# for all the devices used in the timeline.
802	1219	class DevProps:
803		- syspath = ''
804		- altname = ''
805		- async = True
806		- xtraclass = ''
807		- xtrainfo = ''
	1220	+ def __init__(self):
	1221	+ self.syspath = ''
	1222	+ self.altname = ''
	1223	+ self.isasync = True
	1224	+ self.xtraclass = ''
	1225	+ self.xtrainfo = ''
808	1226	def out(self, dev):
809		- return '%s,%s,%d;' % (dev, self.altname, self.async)
	1227	+ return '%s,%s,%d;' % (dev, self.altname, self.isasync)
810	1228	def debug(self, dev):
811		- print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)
	1229	+ pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.isasync))
812	1230	def altName(self, dev):
813	1231	if not self.altname or self.altname == dev:
814	1232	return dev
..	..	@@ -816,24 +1234,21 @@
816	1234	def xtraClass(self):
817	1235	if self.xtraclass:
818	1236	return ' '+self.xtraclass
819		- if not self.async:
	1237	+ if not self.isasync:
820	1238	return ' sync'
821	1239	return ''
822	1240	def xtraInfo(self):
823	1241	if self.xtraclass:
824	1242	return ' '+self.xtraclass
825		- if self.async:
826		- return ' async_device'
827		- return ' sync_device'
	1243	+ if self.isasync:
	1244	+ return ' (async)'
	1245	+ return ' (sync)'
828	1246
829	1247	# Class: DeviceNode
830	1248	# Description:
831	1249	# A container used to create a device hierachy, with a single root node
832	1250	# and a tree of child nodes. Used by Data.deviceTopology()
833	1251	class DeviceNode:
834		- name = ''
835		- children = 0
836		- depth = 0
837	1252	def __init__(self, nodename, nodedepth):
838	1253	self.name = nodename
839	1254	self.children = []
..	..	@@ -861,76 +1276,116 @@
861	1276	# }
862	1277	#
863	1278	class Data:
864		- dmesg = {} # root data structure
865		- phases = [] # ordered list of phases
866		- start = 0.0 # test start
867		- end = 0.0 # test end
868		- tSuspended = 0.0 # low-level suspend start
869		- tResumed = 0.0 # low-level resume start
870		- tKernSus = 0.0 # kernel level suspend start
871		- tKernRes = 0.0 # kernel level resume end
872		- tLow = 0.0 # time spent in low-level suspend (standby/freeze)
873		- fwValid = False # is firmware data available
874		- fwSuspend = 0 # time spent in firmware suspend
875		- fwResume = 0 # time spent in firmware resume
876		- dmesgtext = [] # dmesg text file in memory
877		- pstl = 0 # process timeline
878		- testnumber = 0
879		- idstr = ''
880		- html_device_id = 0
881		- stamp = 0
882		- outfile = ''
883		- devpids = []
884		- kerror = False
	1279	+ phasedef = {
	1280	+ 'suspend_prepare': {'order': 0, 'color': '#CCFFCC'},
	1281	+ 'suspend': {'order': 1, 'color': '#88FF88'},
	1282	+ 'suspend_late': {'order': 2, 'color': '#00AA00'},
	1283	+ 'suspend_noirq': {'order': 3, 'color': '#008888'},
	1284	+ 'suspend_machine': {'order': 4, 'color': '#0000FF'},
	1285	+ 'resume_machine': {'order': 5, 'color': '#FF0000'},
	1286	+ 'resume_noirq': {'order': 6, 'color': '#FF9900'},
	1287	+ 'resume_early': {'order': 7, 'color': '#FFCC00'},
	1288	+ 'resume': {'order': 8, 'color': '#FFFF88'},
	1289	+ 'resume_complete': {'order': 9, 'color': '#FFFFCC'},
	1290	+ }
	1291	+ errlist = {
	1292	+ 'HWERROR' : r'.\[ Hardware Error \].',
	1293	+ 'FWBUG' : r'.\[ Firmware Bug \].',
	1294	+ 'BUG' : r'(?i).\bBUG\b.',
	1295	+ 'ERROR' : r'(?i).\bERROR\b.',
	1296	+ 'WARNING' : r'(?i).\bWARNING\b.',
	1297	+ 'FAULT' : r'(?i).\bFAULT\b.',
	1298	+ 'FAIL' : r'(?i).\bFAILED\b.',
	1299	+ 'INVALID' : r'(?i).\bINVALID\b.',
	1300	+ 'CRASH' : r'(?i).\bCRASHED\b.',
	1301	+ 'TIMEOUT' : r'(?i).\bTIMEOUT\b.',
	1302	+ 'IRQ' : r'.\bgenirq: .',
	1303	+ 'TASKFAIL': r'.Freezing of tasks .*',
	1304	+ 'ACPI' : r'.\bACPI (?P<b>[A-Za-z]) Error[: ].*',
	1305	+ 'DISKFULL': r'.\bNo space left on device.',
	1306	+ 'USBERR' : r'.usb .device ., error [0-9-]',
	1307	+ 'ATAERR' : r' ata[0-9\.]: .failed.',
	1308	+ 'MEIERR' : r' mei.: .failed.',
	1309	+ 'TPMERR' : r'(?i) tpm tpm[0-9]: .error.*',
	1310	+ }
885	1311	def __init__(self, num):
886	1312	idchar = 'abcdefghij'
887		- self.pstl = dict()
	1313	+ self.start = 0.0 # test start
	1314	+ self.end = 0.0 # test end
	1315	+ self.hwstart = 0 # rtc test start
	1316	+ self.hwend = 0 # rtc test end
	1317	+ self.tSuspended = 0.0 # low-level suspend start
	1318	+ self.tResumed = 0.0 # low-level resume start
	1319	+ self.tKernSus = 0.0 # kernel level suspend start
	1320	+ self.tKernRes = 0.0 # kernel level resume end
	1321	+ self.fwValid = False # is firmware data available
	1322	+ self.fwSuspend = 0 # time spent in firmware suspend
	1323	+ self.fwResume = 0 # time spent in firmware resume
	1324	+ self.html_device_id = 0
	1325	+ self.stamp = 0
	1326	+ self.outfile = ''
	1327	+ self.kerror = False
	1328	+ self.wifi = dict()
	1329	+ self.turbostat = 0
	1330	+ self.enterfail = ''
	1331	+ self.currphase = ''
	1332	+ self.pstl = dict() # process timeline
888	1333	self.testnumber = num
889	1334	self.idstr = idchar[num]
890		- self.dmesgtext = []
891		- self.phases = []
892		- self.dmesg = { # fixed list of 10 phases
893		- 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
894		- 'row': 0, 'color': '#CCFFCC', 'order': 0},
895		- 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
896		- 'row': 0, 'color': '#88FF88', 'order': 1},
897		- 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
898		- 'row': 0, 'color': '#00AA00', 'order': 2},
899		- 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
900		- 'row': 0, 'color': '#008888', 'order': 3},
901		- 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
902		- 'row': 0, 'color': '#0000FF', 'order': 4},
903		- 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
904		- 'row': 0, 'color': '#FF0000', 'order': 5},
905		- 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
906		- 'row': 0, 'color': '#FF9900', 'order': 6},
907		- 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
908		- 'row': 0, 'color': '#FFCC00', 'order': 7},
909		- 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
910		- 'row': 0, 'color': '#FFFF88', 'order': 8},
911		- 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
912		- 'row': 0, 'color': '#FFFFCC', 'order': 9}
913		- }
914		- self.phases = self.sortedPhases()
915		- self.devicegroups = []
916		- for phase in self.phases:
917		- self.devicegroups.append([phase])
	1335	+ self.dmesgtext = [] # dmesg text file in memory
	1336	+ self.dmesg = dict() # root data structure
918	1337	self.errorinfo = {'suspend':[],'resume':[]}
	1338	+ self.tLow = [] # time spent in low-level suspends (standby/freeze)
	1339	+ self.devpids = []
	1340	+ self.devicegroups = 0
	1341	+ def sortedPhases(self):
	1342	+ return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order'])
	1343	+ def initDevicegroups(self):
	1344	+ # called when phases are all finished being added
	1345	+ for phase in sorted(self.dmesg.keys()):
	1346	+ if '*' in phase:
	1347	+ p = phase.split('*')
	1348	+ pnew = '%s%d' % (p[0], len(p))
	1349	+ self.dmesg[pnew] = self.dmesg.pop(phase)
	1350	+ self.devicegroups = []
	1351	+ for phase in self.sortedPhases():
	1352	+ self.devicegroups.append([phase])
	1353	+ def nextPhase(self, phase, offset):
	1354	+ order = self.dmesg[phase]['order'] + offset
	1355	+ for p in self.dmesg:
	1356	+ if self.dmesg[p]['order'] == order:
	1357	+ return p
	1358	+ return ''
	1359	+ def lastPhase(self, depth=1):
	1360	+ plist = self.sortedPhases()
	1361	+ if len(plist) < depth:
	1362	+ return ''
	1363	+ return plist[-1*depth]
	1364	+ def turbostatInfo(self):
	1365	+ tp = TestProps()
	1366	+ out = {'syslpi':'N/A','pkgpc10':'N/A'}
	1367	+ for line in self.dmesgtext:
	1368	+ m = re.match(tp.tstatfmt, line)
	1369	+ if not m:
	1370	+ continue
	1371	+ for i in m.group('t').split('\|'):
	1372	+ if 'SYS%LPI' in i:
	1373	+ out['syslpi'] = i.split('=')[-1]+'%'
	1374	+ elif 'pc10' in i:
	1375	+ out['pkgpc10'] = i.split('=')[-1]+'%'
	1376	+ break
	1377	+ return out
919	1378	def extractErrorInfo(self):
920		- elist = {
921		- 'HWERROR' : '.\[ Hardware Error \].',
922		- 'FWBUG' : '.\[ Firmware Bug \].',
923		- 'BUG' : '.BUG.',
924		- 'ERROR' : '.ERROR.',
925		- 'WARNING' : '.WARNING.',
926		- 'IRQ' : '.genirq: .',
927		- 'TASKFAIL': '.Freezing of tasks failed.',
928		- }
929		- lf = sysvals.openlog(sysvals.dmesgfile, 'r')
	1379	+ lf = self.dmesgtext
	1380	+ if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
	1381	+ lf = sysvals.openlog(sysvals.dmesgfile, 'r')
930	1382	i = 0
	1383	+ tp = TestProps()
931	1384	list = []
932	1385	for line in lf:
933	1386	i += 1
	1387	+ if tp.stampInfo(line, sysvals):
	1388	+ continue
934	1389	m = re.match('[ \t](\[ )(?P<ktime>[0-9\.])(\]) (?P<msg>.)', line)
935	1390	if not m:
936	1391	continue
..	..	@@ -939,24 +1394,38 @@
939	1394	continue
940	1395	dir = 'suspend' if t < self.tSuspended else 'resume'
941	1396	msg = m.group('msg')
942		- for err in elist:
943		- if re.match(elist[err], msg):
944		- list.append((err, dir, t, i, i))
	1397	+ if re.match('capability: warning: .*', msg):
	1398	+ continue
	1399	+ for err in self.errlist:
	1400	+ if re.match(self.errlist[err], msg):
	1401	+ list.append((msg, err, dir, t, i, i))
945	1402	self.kerror = True
946	1403	break
947		- for e in list:
948		- type, dir, t, idx1, idx2 = e
949		- sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t))
	1404	+ tp.msglist = []
	1405	+ for msg, type, dir, t, idx1, idx2 in list:
	1406	+ tp.msglist.append(msg)
950	1407	self.errorinfo[dir].append((type, t, idx1, idx2))
951	1408	if self.kerror:
952	1409	sysvals.dmesglog = True
953		- lf.close()
954		- def setStart(self, time):
	1410	+ if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
	1411	+ lf.close()
	1412	+ return tp
	1413	+ def setStart(self, time, msg=''):
955	1414	self.start = time
956		- def setEnd(self, time):
	1415	+ if msg:
	1416	+ try:
	1417	+ self.hwstart = datetime.strptime(msg, sysvals.tmstart)
	1418	+ except:
	1419	+ self.hwstart = 0
	1420	+ def setEnd(self, time, msg=''):
957	1421	self.end = time
	1422	+ if msg:
	1423	+ try:
	1424	+ self.hwend = datetime.strptime(msg, sysvals.tmend)
	1425	+ except:
	1426	+ self.hwend = 0
958	1427	def isTraceEventOutsideDeviceCalls(self, pid, time):
959		- for phase in self.phases:
	1428	+ for phase in self.sortedPhases():
960	1429	list = self.dmesg[phase]['list']
961	1430	for dev in list:
962	1431	d = list[dev]
..	..	@@ -964,16 +1433,10 @@
964	1433	time < d['end']):
965	1434	return False
966	1435	return True
967		- def phaseCollision(self, phase, isbegin, line):
968		- key = 'end'
969		- if isbegin:
970		- key = 'start'
971		- if self.dmesg[phase][key] >= 0:
972		- sysvals.vprint('IGNORE: %s' % line.strip())
973		- return True
974		- return False
975	1436	def sourcePhase(self, start):
976		- for phase in self.phases:
	1437	+ for phase in self.sortedPhases():
	1438	+ if 'machine' in phase:
	1439	+ continue
977	1440	pend = self.dmesg[phase]['end']
978	1441	if start <= pend:
979	1442	return phase
..	..	@@ -1004,14 +1467,15 @@
1004	1467	return tgtdev
1005	1468	def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
1006	1469	# try to place the call in a device
1007		- tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device')
	1470	+ phases = self.sortedPhases()
	1471	+ tgtdev = self.sourceDevice(phases, start, end, pid, 'device')
1008	1472	# calls with device pids that occur outside device bounds are dropped
1009	1473	# TODO: include these somehow
1010	1474	if not tgtdev and pid in self.devpids:
1011	1475	return False
1012	1476	# try to place the call in a thread
1013	1477	if not tgtdev:
1014		- tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread')
	1478	+ tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')
1015	1479	# create new thread blocks, expand as new calls are found
1016	1480	if not tgtdev:
1017	1481	if proc == '<...>':
..	..	@@ -1053,7 +1517,7 @@
1053	1517	def overflowDevices(self):
1054	1518	# get a list of devices that extend beyond the end of this test run
1055	1519	devlist = []
1056		- for phase in self.phases:
	1520	+ for phase in self.sortedPhases():
1057	1521	list = self.dmesg[phase]['list']
1058	1522	for devname in list:
1059	1523	dev = list[devname]
..	..	@@ -1064,7 +1528,7 @@
1064	1528	# merge any devices that overlap devlist
1065	1529	for dev in devlist:
1066	1530	devname = dev['name']
1067		- for phase in self.phases:
	1531	+ for phase in self.sortedPhases():
1068	1532	list = self.dmesg[phase]['list']
1069	1533	if devname not in list:
1070	1534	continue
..	..	@@ -1079,7 +1543,7 @@
1079	1543	del list[devname]
1080	1544	def usurpTouchingThread(self, name, dev):
1081	1545	# the caller test has priority of this thread, give it to him
1082		- for phase in self.phases:
	1546	+ for phase in self.sortedPhases():
1083	1547	list = self.dmesg[phase]['list']
1084	1548	if name in list:
1085	1549	tdev = list[name]
..	..	@@ -1093,7 +1557,7 @@
1093	1557	break
1094	1558	def stitchTouchingThreads(self, testlist):
1095	1559	# merge any threads between tests that touch
1096		- for phase in self.phases:
	1560	+ for phase in self.sortedPhases():
1097	1561	list = self.dmesg[phase]['list']
1098	1562	for devname in list:
1099	1563	dev = list[devname]
..	..	@@ -1103,7 +1567,7 @@
1103	1567	data.usurpTouchingThread(devname, dev)
1104	1568	def optimizeDevSrc(self):
1105	1569	# merge any src call loops to reduce timeline size
1106		- for phase in self.phases:
	1570	+ for phase in self.sortedPhases():
1107	1571	list = self.dmesg[phase]['list']
1108	1572	for dev in list:
1109	1573	if 'src' not in list[dev]:
..	..	@@ -1141,7 +1605,7 @@
1141	1605	self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
1142	1606	self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
1143	1607	self.end = self.trimTimeVal(self.end, t0, dT, left)
1144		- for phase in self.phases:
	1608	+ for phase in self.sortedPhases():
1145	1609	p = self.dmesg[phase]
1146	1610	p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
1147	1611	p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
..	..	@@ -1150,6 +1614,7 @@
1150	1614	d = list[name]
1151	1615	d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
1152	1616	d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
	1617	+ d['length'] = d['end'] - d['start']
1153	1618	if('ftrace' in d):
1154	1619	cg = d['ftrace']
1155	1620	cg.start = self.trimTimeVal(cg.start, t0, dT, left)
..	..	@@ -1159,6 +1624,8 @@
1159	1624	if('src' in d):
1160	1625	for e in d['src']:
1161	1626	e.time = self.trimTimeVal(e.time, t0, dT, left)
	1627	+ e.end = self.trimTimeVal(e.end, t0, dT, left)
	1628	+ e.length = e.end - e.time
1162	1629	for dir in ['suspend', 'resume']:
1163	1630	list = []
1164	1631	for e in self.errorinfo[dir]:
..	..	@@ -1166,55 +1633,80 @@
1166	1633	tm = self.trimTimeVal(tm, t0, dT, left)
1167	1634	list.append((type, tm, idx1, idx2))
1168	1635	self.errorinfo[dir] = list
1169		- def normalizeTime(self, tZero):
	1636	+ def trimFreezeTime(self, tZero):
1170	1637	# trim out any standby or freeze clock time
1171		- if(self.tSuspended != self.tResumed):
1172		- if(self.tResumed > tZero):
1173		- self.trimTime(self.tSuspended, \
1174		- self.tResumed-self.tSuspended, True)
1175		- else:
1176		- self.trimTime(self.tSuspended, \
1177		- self.tResumed-self.tSuspended, False)
	1638	+ lp = ''
	1639	+ for phase in self.sortedPhases():
	1640	+ if 'resume_machine' in phase and 'suspend_machine' in lp:
	1641	+ tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start']
	1642	+ tL = tR - tS
	1643	+ if tL > 0:
	1644	+ left = True if tR > tZero else False
	1645	+ self.trimTime(tS, tL, left)
	1646	+ if 'trying' in self.dmesg[lp] and self.dmesg[lp]['trying'] >= 0.001:
	1647	+ tTry = round(self.dmesg[lp]['trying'] * 1000)
	1648	+ text = '%.0f (-%.0f waking)' % (tL * 1000, tTry)
	1649	+ else:
	1650	+ text = '%.0f' % (tL * 1000)
	1651	+ self.tLow.append(text)
	1652	+ lp = phase
	1653	+ def getMemTime(self):
	1654	+ if not self.hwstart or not self.hwend:
	1655	+ return
	1656	+ stime = (self.tSuspended - self.start) * 1000000
	1657	+ rtime = (self.end - self.tResumed) * 1000000
	1658	+ hws = self.hwstart + timedelta(microseconds=stime)
	1659	+ hwr = self.hwend - timedelta(microseconds=rtime)
	1660	+ self.tLow.append('%.0f'%((hwr - hws).total_seconds() * 1000))
1178	1661	def getTimeValues(self):
1179		- sktime = (self.dmesg['suspend_machine']['end'] - \
1180		- self.tKernSus) * 1000
1181		- rktime = (self.dmesg['resume_complete']['end'] - \
1182		- self.dmesg['resume_machine']['start']) * 1000
	1662	+ sktime = (self.tSuspended - self.tKernSus) * 1000
	1663	+ rktime = (self.tKernRes - self.tResumed) * 1000
1183	1664	return (sktime, rktime)
1184		- def setPhase(self, phase, ktime, isbegin):
	1665	+ def setPhase(self, phase, ktime, isbegin, order=-1):
1185	1666	if(isbegin):
	1667	+ # phase start over current phase
	1668	+ if self.currphase:
	1669	+ if 'resume_machine' not in self.currphase:
	1670	+ sysvals.vprint('WARNING: phase %s failed to end' % self.currphase)
	1671	+ self.dmesg[self.currphase]['end'] = ktime
	1672	+ phases = self.dmesg.keys()
	1673	+ color = self.phasedef[phase]['color']
	1674	+ count = len(phases) if order < 0 else order
	1675	+ # create unique name for every new phase
	1676	+ while phase in phases:
	1677	+ phase += '*'
	1678	+ self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0,
	1679	+ 'row': 0, 'color': color, 'order': count}
1186	1680	self.dmesg[phase]['start'] = ktime
	1681	+ self.currphase = phase
1187	1682	else:
	1683	+ # phase end without a start
	1684	+ if phase not in self.currphase:
	1685	+ if self.currphase:
	1686	+ sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))
	1687	+ else:
	1688	+ sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)
	1689	+ return phase
	1690	+ phase = self.currphase
1188	1691	self.dmesg[phase]['end'] = ktime
1189		- def dmesgSortVal(self, phase):
1190		- return self.dmesg[phase]['order']
1191		- def sortedPhases(self):
1192		- return sorted(self.dmesg, key=self.dmesgSortVal)
	1692	+ self.currphase = ''
	1693	+ return phase
1193	1694	def sortedDevices(self, phase):
1194	1695	list = self.dmesg[phase]['list']
1195		- slist = []
1196		- tmp = dict()
1197		- for devname in list:
1198		- dev = list[devname]
1199		- if dev['length'] == 0:
1200		- continue
1201		- tmp[dev['start']] = devname
1202		- for t in sorted(tmp):
1203		- slist.append(tmp[t])
1204		- return slist
	1696	+ return sorted(list, key=lambda k:list[k]['start'])
1205	1697	def fixupInitcalls(self, phase):
1206	1698	# if any calls never returned, clip them at system resume end
1207	1699	phaselist = self.dmesg[phase]['list']
1208	1700	for devname in phaselist:
1209	1701	dev = phaselist[devname]
1210	1702	if(dev['end'] < 0):
1211		- for p in self.phases:
	1703	+ for p in self.sortedPhases():
1212	1704	if self.dmesg[p]['end'] > dev['start']:
1213	1705	dev['end'] = self.dmesg[p]['end']
1214	1706	break
1215	1707	sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
1216	1708	def deviceFilter(self, devicefilter):
1217		- for phase in self.phases:
	1709	+ for phase in self.sortedPhases():
1218	1710	list = self.dmesg[phase]['list']
1219	1711	rmlist = []
1220	1712	for name in list:
..	..	@@ -1229,7 +1721,7 @@
1229	1721	del list[name]
1230	1722	def fixupInitcallsThatDidntReturn(self):
1231	1723	# if any calls never returned, clip them at system resume end
1232		- for phase in self.phases:
	1724	+ for phase in self.sortedPhases():
1233	1725	self.fixupInitcalls(phase)
1234	1726	def phaseOverlap(self, phases):
1235	1727	rmgroups = []
..	..	@@ -1248,17 +1740,18 @@
1248	1740	self.devicegroups.append(newgroup)
1249	1741	def newActionGlobal(self, name, start, end, pid=-1, color=''):
1250	1742	# which phase is this device callback or action in
	1743	+ phases = self.sortedPhases()
1251	1744	targetphase = 'none'
1252	1745	htmlclass = ''
1253	1746	overlap = 0.0
1254		- phases = []
1255		- for phase in self.phases:
	1747	+ myphases = []
	1748	+ for phase in phases:
1256	1749	pstart = self.dmesg[phase]['start']
1257	1750	pend = self.dmesg[phase]['end']
1258	1751	# see if the action overlaps this phase
1259	1752	o = max(0, min(end, pend) - max(start, pstart))
1260	1753	if o > 0:
1261		- phases.append(phase)
	1754	+ myphases.append(phase)
1262	1755	# set the target phase to the one that overlaps most
1263	1756	if o > overlap:
1264	1757	if overlap > 0 and phase == 'post_resume':
..	..	@@ -1267,19 +1760,19 @@
1267	1760	overlap = o
1268	1761	# if no target phase was found, pin it to the edge
1269	1762	if targetphase == 'none':
1270		- p0start = self.dmesg[self.phases[0]]['start']
	1763	+ p0start = self.dmesg[phases[0]]['start']
1271	1764	if start <= p0start:
1272		- targetphase = self.phases[0]
	1765	+ targetphase = phases[0]
1273	1766	else:
1274		- targetphase = self.phases[-1]
	1767	+ targetphase = phases[-1]
1275	1768	if pid == -2:
1276	1769	htmlclass = ' bg'
1277	1770	elif pid == -3:
1278	1771	htmlclass = ' ps'
1279		- if len(phases) > 1:
	1772	+ if len(myphases) > 1:
1280	1773	htmlclass = ' bg'
1281		- self.phaseOverlap(phases)
1282		- if targetphase in self.phases:
	1774	+ self.phaseOverlap(myphases)
	1775	+ if targetphase in phases:
1283	1776	newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1284	1777	return (targetphase, newname)
1285	1778	return False
..	..	@@ -1291,7 +1784,7 @@
1291	1784	length = -1.0
1292	1785	if(start >= 0 and end >= 0):
1293	1786	length = end - start
1294		- if pid == -2:
	1787	+ if pid == -2 or name not in sysvals.tracefuncs.keys():
1295	1788	i = 2
1296	1789	origname = name
1297	1790	while(name in list):
..	..	@@ -1304,6 +1797,15 @@
1304	1797	if color:
1305	1798	list[name]['color'] = color
1306	1799	return name
	1800	+ def findDevice(self, phase, name):
	1801	+ list = self.dmesg[phase]['list']
	1802	+ mydev = ''
	1803	+ for devname in sorted(list):
	1804	+ if name == devname or re.match('^%s\[(?P<num>[0-9]*)\]$' % name, devname):
	1805	+ mydev = devname
	1806	+ if mydev:
	1807	+ return list[mydev]
	1808	+ return False
1307	1809	def deviceChildren(self, devname, phase):
1308	1810	devlist = []
1309	1811	list = self.dmesg[phase]['list']
..	..	@@ -1311,21 +1813,45 @@
1311	1813	if(list[child]['par'] == devname):
1312	1814	devlist.append(child)
1313	1815	return devlist
	1816	+ def maxDeviceNameSize(self, phase):
	1817	+ size = 0
	1818	+ for name in self.dmesg[phase]['list']:
	1819	+ if len(name) > size:
	1820	+ size = len(name)
	1821	+ return size
1314	1822	def printDetails(self):
1315	1823	sysvals.vprint('Timeline Details:')
1316	1824	sysvals.vprint(' test start: %f' % self.start)
1317	1825	sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
1318		- for phase in self.phases:
1319		- dc = len(self.dmesg[phase]['list'])
1320		- sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \
1321		- self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
	1826	+ tS = tR = False
	1827	+ for phase in self.sortedPhases():
	1828	+ devlist = self.dmesg[phase]['list']
	1829	+ dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end']
	1830	+ if not tS and ps >= self.tSuspended:
	1831	+ sysvals.vprint(' machine suspended: %f' % self.tSuspended)
	1832	+ tS = True
	1833	+ if not tR and ps >= self.tResumed:
	1834	+ sysvals.vprint(' machine resumed: %f' % self.tResumed)
	1835	+ tR = True
	1836	+ sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc))
	1837	+ if sysvals.devdump:
	1838	+ sysvals.vprint(''.join('-' for i in range(80)))
	1839	+ maxname = '%d' % self.maxDeviceNameSize(phase)
	1840	+ fmt = '%3d) %'+maxname+'s - %f - %f'
	1841	+ c = 1
	1842	+ for name in sorted(devlist):
	1843	+ s = devlist[name]['start']
	1844	+ e = devlist[name]['end']
	1845	+ sysvals.vprint(fmt % (c, name, s, e))
	1846	+ c += 1
	1847	+ sysvals.vprint(''.join('-' for i in range(80)))
1322	1848	sysvals.vprint(' kernel resume end: %f' % self.tKernRes)
1323	1849	sysvals.vprint(' test end: %f' % self.end)
1324	1850	def deviceChildrenAllPhases(self, devname):
1325	1851	devlist = []
1326		- for phase in self.phases:
	1852	+ for phase in self.sortedPhases():
1327	1853	list = self.deviceChildren(devname, phase)
1328		- for dev in list:
	1854	+ for dev in sorted(list):
1329	1855	if dev not in devlist:
1330	1856	devlist.append(dev)
1331	1857	return devlist
..	..	@@ -1344,7 +1870,7 @@
1344	1870	if node.name:
1345	1871	info = ''
1346	1872	drv = ''
1347		- for phase in self.phases:
	1873	+ for phase in self.sortedPhases():
1348	1874	list = self.dmesg[phase]['list']
1349	1875	if node.name in list:
1350	1876	s = list[node.name]['start']
..	..	@@ -1365,16 +1891,16 @@
1365	1891	def rootDeviceList(self):
1366	1892	# list of devices graphed
1367	1893	real = []
1368		- for phase in self.dmesg:
	1894	+ for phase in self.sortedPhases():
1369	1895	list = self.dmesg[phase]['list']
1370		- for dev in list:
	1896	+ for dev in sorted(list):
1371	1897	if list[dev]['pid'] >= 0 and dev not in real:
1372	1898	real.append(dev)
1373	1899	# list of top-most root devices
1374	1900	rootlist = []
1375		- for phase in self.dmesg:
	1901	+ for phase in self.sortedPhases():
1376	1902	list = self.dmesg[phase]['list']
1377		- for dev in list:
	1903	+ for dev in sorted(list):
1378	1904	pdev = list[dev]['par']
1379	1905	pid = list[dev]['pid']
1380	1906	if(pid < 0 or re.match('[0-9]-[0-9]\.[0-9][\.0-9]\:[\.0-9]*$', pdev)):
..	..	@@ -1455,9 +1981,9 @@
1455	1981	def createProcessUsageEvents(self):
1456	1982	# get an array of process names
1457	1983	proclist = []
1458		- for t in self.pstl:
	1984	+ for t in sorted(self.pstl):
1459	1985	pslist = self.pstl[t]
1460		- for ps in pslist:
	1986	+ for ps in sorted(pslist):
1461	1987	if ps not in proclist:
1462	1988	proclist.append(ps)
1463	1989	# get a list of data points for suspend and resume
..	..	@@ -1478,10 +2004,31 @@
1478	2004	c = self.addProcessUsageEvent(ps, tres)
1479	2005	if c > 0:
1480	2006	sysvals.vprint('%25s (res): %d' % (ps, c))
	2007	+ def handleEndMarker(self, time, msg=''):
	2008	+ dm = self.dmesg
	2009	+ self.setEnd(time, msg)
	2010	+ self.initDevicegroups()
	2011	+ # give suspend_prepare an end if needed
	2012	+ if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0:
	2013	+ dm['suspend_prepare']['end'] = time
	2014	+ # assume resume machine ends at next phase start
	2015	+ if 'resume_machine' in dm and dm['resume_machine']['end'] < 0:
	2016	+ np = self.nextPhase('resume_machine', 1)
	2017	+ if np:
	2018	+ dm['resume_machine']['end'] = dm[np]['start']
	2019	+ # if kernel resume end not found, assume its the end marker
	2020	+ if self.tKernRes == 0.0:
	2021	+ self.tKernRes = time
	2022	+ # if kernel suspend start not found, assume its the end marker
	2023	+ if self.tKernSus == 0.0:
	2024	+ self.tKernSus = time
	2025	+ # set resume complete to end at end marker
	2026	+ if 'resume_complete' in dm:
	2027	+ dm['resume_complete']['end'] = time
1481	2028	def debugPrint(self):
1482		- for p in self.phases:
	2029	+ for p in self.sortedPhases():
1483	2030	list = self.dmesg[p]['list']
1484		- for devname in list:
	2031	+ for devname in sorted(list):
1485	2032	dev = list[devname]
1486	2033	if 'ftrace' in dev:
1487	2034	dev['ftrace'].debugPrint(' [%s]' % devname)
..	..	@@ -1490,9 +2037,9 @@
1490	2037	# Description:
1491	2038	# A container for kprobe function data we want in the dev timeline
1492	2039	class DevFunction:
1493		- row = 0
1494		- count = 1
1495	2040	def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
	2041	+ self.row = 0
	2042	+ self.count = 1
1496	2043	self.name = name
1497	2044	self.args = args
1498	2045	self.caller = caller
..	..	@@ -1546,16 +2093,15 @@
1546	2093	# suspend_resume: phase or custom exec block data
1547	2094	# device_pm_callback: device callback info
1548	2095	class FTraceLine:
1549		- time = 0.0
1550		- length = 0.0
1551		- fcall = False
1552		- freturn = False
1553		- fevent = False
1554		- fkprobe = False
1555		- depth = 0
1556		- name = ''
1557		- type = ''
1558	2096	def __init__(self, t, m='', d=''):
	2097	+ self.length = 0.0
	2098	+ self.fcall = False
	2099	+ self.freturn = False
	2100	+ self.fevent = False
	2101	+ self.fkprobe = False
	2102	+ self.depth = 0
	2103	+ self.name = ''
	2104	+ self.type = ''
1559	2105	self.time = float(t)
1560	2106	if not m and not d:
1561	2107	return
..	..	@@ -1633,20 +2179,20 @@
1633	2179	return len(str)/2
1634	2180	def debugPrint(self, info=''):
1635	2181	if self.isLeaf():
1636		- print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
	2182	+ pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
1637	2183	self.depth, self.name, self.length*1000000, info))
1638	2184	elif self.freturn:
1639		- print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
	2185	+ pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
1640	2186	self.depth, self.name, self.length*1000000, info))
1641	2187	else:
1642		- print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
	2188	+ pprint(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
1643	2189	self.depth, self.name, self.length*1000000, info))
1644	2190	def startMarker(self):
1645	2191	# Is this the starting line of a suspend?
1646	2192	if not self.fevent:
1647	2193	return False
1648	2194	if sysvals.usetracemarkers:
1649		- if(self.name == 'SUSPEND START'):
	2195	+ if(self.name.startswith('SUSPEND START')):
1650	2196	return True
1651	2197	return False
1652	2198	else:
..	..	@@ -1659,7 +2205,7 @@
1659	2205	if not self.fevent:
1660	2206	return False
1661	2207	if sysvals.usetracemarkers:
1662		- if(self.name == 'RESUME COMPLETE'):
	2208	+ if(self.name.startswith('RESUME COMPLETE')):
1663	2209	return True
1664	2210	return False
1665	2211	else:
..	..	@@ -1675,19 +2221,13 @@
1675	2221	# Each instance is tied to a single device in a single phase, and is
1676	2222	# comprised of an ordered list of FTraceLine objects
1677	2223	class FTraceCallGraph:
1678		- id = ''
1679		- start = -1.0
1680		- end = -1.0
1681		- list = []
1682		- invalid = False
1683		- depth = 0
1684		- pid = 0
1685		- name = ''
1686		- partial = False
1687	2224	vfname = 'missing_function_name'
1688		- ignore = False
1689		- sv = 0
1690	2225	def __init__(self, pid, sv):
	2226	+ self.id = ''
	2227	+ self.invalid = False
	2228	+ self.name = ''
	2229	+ self.partial = False
	2230	+ self.ignore = False
1691	2231	self.start = -1.0
1692	2232	self.end = -1.0
1693	2233	self.list = []
..	..	@@ -1786,7 +2326,7 @@
1786	2326	if warning and ('[make leaf]', line) not in info:
1787	2327	info.append(('', line))
1788	2328	if warning:
1789		- print 'WARNING: ftrace data missing, corrections made:'
	2329	+ pprint('WARNING: ftrace data missing, corrections made:')
1790	2330	for i in info:
1791	2331	t, obj = i
1792	2332	if obj:
..	..	@@ -1846,10 +2386,10 @@
1846	2386	id = 'task %s' % (self.pid)
1847	2387	window = '(%f - %f)' % (self.start, line.time)
1848	2388	if(self.depth < 0):
1849		- print('Data misalignment for '+id+\
	2389	+ pprint('Data misalignment for '+id+\
1850	2390	' (buffer overflow), ignoring this callback')
1851	2391	else:
1852		- print('Too much data for '+id+\
	2392	+ pprint('Too much data for '+id+\
1853	2393	' '+window+', ignoring this callback')
1854	2394	def slice(self, dev):
1855	2395	minicg = FTraceCallGraph(dev['pid'], self.sv)
..	..	@@ -1902,7 +2442,7 @@
1902	2442	elif l.isReturn():
1903	2443	if(l.depth not in stack):
1904	2444	if self.sv.verbose:
1905		- print 'Post Process Error: Depth missing'
	2445	+ pprint('Post Process Error: Depth missing')
1906	2446	l.debugPrint()
1907	2447	return False
1908	2448	# calculate call length from call/return lines
..	..	@@ -1919,7 +2459,7 @@
1919	2459	return True
1920	2460	elif(cnt < 0):
1921	2461	if self.sv.verbose:
1922		- print 'Post Process Error: Depth is less than 0'
	2462	+ pprint('Post Process Error: Depth is less than 0')
1923	2463	return False
1924	2464	# trace ended before call tree finished
1925	2465	return self.repair(cnt)
..	..	@@ -1943,11 +2483,11 @@
1943	2483	dev['ftrace'] = cg
1944	2484	found = devname
1945	2485	return found
1946		- for p in data.phases:
	2486	+ for p in data.sortedPhases():
1947	2487	if(data.dmesg[p]['start'] <= self.start and
1948	2488	self.start <= data.dmesg[p]['end']):
1949	2489	list = data.dmesg[p]['list']
1950		- for devname in list:
	2490	+ for devname in sorted(list, key=lambda k:list[k]['start']):
1951	2491	dev = list[devname]
1952	2492	if(pid == dev['pid'] and
1953	2493	self.start <= dev['start'] and
..	..	@@ -1966,7 +2506,7 @@
1966	2506	if fs < data.start or fe > data.end:
1967	2507	return
1968	2508	phase = ''
1969		- for p in data.phases:
	2509	+ for p in data.sortedPhases():
1970	2510	if(data.dmesg[p]['start'] <= self.start and
1971	2511	self.start < data.dmesg[p]['end']):
1972	2512	phase = p
..	..	@@ -1978,20 +2518,20 @@
1978	2518	phase, myname = out
1979	2519	data.dmesg[phase]['list'][myname]['ftrace'] = self
1980	2520	def debugPrint(self, info=''):
1981		- print('%s pid=%d [%f - %f] %.3f us') % \
	2521	+ pprint('%s pid=%d [%f - %f] %.3f us' % \
1982	2522	(self.name, self.pid, self.start, self.end,
1983		- (self.end - self.start)*1000000)
	2523	+ (self.end - self.start)*1000000))
1984	2524	for l in self.list:
1985	2525	if l.isLeaf():
1986		- print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
	2526	+ pprint('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
1987	2527	l.depth, l.name, l.length*1000000, info))
1988	2528	elif l.freturn:
1989		- print('%f (%02d): %s} (%.3f us)%s' % (l.time, \
	2529	+ pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \
1990	2530	l.depth, l.name, l.length*1000000, info))
1991	2531	else:
1992		- print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
	2532	+ pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
1993	2533	l.depth, l.name, l.length*1000000, info))
1994		- print(' ')
	2534	+ pprint(' ')
1995	2535
1996	2536	class DevItem:
1997	2537	def __init__(self, test, phase, dev):
..	..	@@ -2008,27 +2548,24 @@
2008	2548	# A container for a device timeline which calculates
2009	2549	# all the html properties to display it correctly
2010	2550	class Timeline:
2011		- html = ''
2012		- height = 0 # total timeline height
2013		- scaleH = 20 # timescale (top) row height
2014		- rowH = 30 # device row height
2015		- bodyH = 0 # body height
2016		- rows = 0 # total timeline rows
2017		- rowlines = dict()
2018		- rowheight = dict()
2019	2551	html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
2020	2552	html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
2021	2553	html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'
2022	2554	html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
2023	2555	html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}"> {2}</div>\n'
2024	2556	def __init__(self, rowheight, scaleheight):
2025		- self.rowH = rowheight
2026		- self.scaleH = scaleheight
2027	2557	self.html = ''
	2558	+ self.height = 0 # total timeline height
	2559	+ self.scaleH = scaleheight # timescale (top) row height
	2560	+ self.rowH = rowheight # device row height
	2561	+ self.bodyH = 0 # body height
	2562	+ self.rows = 0 # total timeline rows
	2563	+ self.rowlines = dict()
	2564	+ self.rowheight = dict()
2028	2565	def createHeader(self, sv, stamp):
2029	2566	if(not stamp['time']):
2030	2567	return
2031		- self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \
	2568	+ self.html += '<div class="version"><a href="https://01.org/pm-graph">%s v%s</a></div>' \
2032	2569	% (sv.title, sv.version)
2033	2570	if sv.logmsg and sv.testlog:
2034	2571	self.html += '<button id="showtest" class="logbtn btnfmt">log</button>'
..	..	@@ -2192,7 +2729,7 @@
2192	2729	# if there is 1 line per row, draw them the standard way
2193	2730	for t, p in standardphases:
2194	2731	for i in sorted(self.rowheight[t][p]):
2195		- self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p])
	2732	+ self.rowheight[t][p][i] = float(self.bodyH)/len(self.rowlines[t][p])
2196	2733	def createZoomBox(self, mode='command', testcount=1):
2197	2734	# Create bounding box, add buttons
2198	2735	html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
..	..	@@ -2251,31 +2788,40 @@
2251	2788	# Description:
2252	2789	# A list of values describing the properties of these test runs
2253	2790	class TestProps:
2254		- stamp = ''
2255		- sysinfo = ''
2256		- cmdline = ''
2257		- kparams = ''
2258		- S0i3 = False
2259		- fwdata = []
2260	2791	stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
2261	2792	'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
2262	2793	' (?P<host>.) (?P<mode>.) (?P<kernel>.*)$'
	2794	+ wififmt = '^# wifi (?P<d>\S) (?P<s>\S) (?P<t>[0-9\.]+).'
	2795	+ tstatfmt = '^# turbostat (?P<t>\S*)'
	2796	+ testerrfmt = '^# enter_sleep_error (?P<e>.*)'
2263	2797	sysinfofmt = '^# sysinfo .*'
2264	2798	cmdlinefmt = '^# command \\| (?P<cmd>.*)'
2265	2799	kparamsfmt = '^# kparams \\| (?P<kp>.*)'
	2800	+ devpropfmt = '# Device Properties: .*'
	2801	+ pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9]): (?P<info>.)'
	2802	+ tracertypefmt = '# tracer: (?P<t>.*)'
	2803	+ firmwarefmt = '# fwsuspend (?P<s>[0-9]) fwresume (?P<r>[0-9])$'
	2804	+ procexecfmt = 'ps - (?P<ps>.*)$'
2266	2805	ftrace_line_fmt_fg = \
2267	2806	'^ (?P<time>[0-9\.]) \\| (?P<cpu>[0-9]*)\)'+\
2268	2807	' (?P<proc>.)-(?P<pid>[0-9]) \\|'+\
2269	2808	'[ +!#\@$](?P<dur>[0-9\.]) .\\| (?P<msg>.*)'
2270	2809	ftrace_line_fmt_nop = \
2271	2810	' (?P<proc>.)-(?P<pid>[0-9]) \[(?P<cpu>[0-9])\] '+\
2272		- '(?P<flags>.{4}) (?P<time>[0-9\.]): *'+\
	2811	+ '(?P<flags>\S) (?P<time>[0-9\.]): '+\
2273	2812	'(?P<msg>.*)'
2274		- ftrace_line_fmt = ftrace_line_fmt_nop
2275		- cgformat = False
2276		- data = 0
2277		- ktemp = dict()
	2813	+ machinesuspend = 'machine_suspend\[.*'
2278	2814	def __init__(self):
	2815	+ self.stamp = ''
	2816	+ self.sysinfo = ''
	2817	+ self.cmdline = ''
	2818	+ self.testerror = []
	2819	+ self.turbostat = []
	2820	+ self.wifi = []
	2821	+ self.fwdata = []
	2822	+ self.ftrace_line_fmt = self.ftrace_line_fmt_nop
	2823	+ self.cgformat = False
	2824	+ self.data = 0
2279	2825	self.ktemp = dict()
2280	2826	def setTracerType(self, tracer):
2281	2827	if(tracer == 'function_graph'):
..	..	@@ -2285,8 +2831,45 @@
2285	2831	self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2286	2832	else:
2287	2833	doError('Invalid tracer format: [%s]' % tracer)
	2834	+ def stampInfo(self, line, sv):
	2835	+ if re.match(self.stampfmt, line):
	2836	+ self.stamp = line
	2837	+ return True
	2838	+ elif re.match(self.sysinfofmt, line):
	2839	+ self.sysinfo = line
	2840	+ return True
	2841	+ elif re.match(self.tstatfmt, line):
	2842	+ self.turbostat.append(line)
	2843	+ return True
	2844	+ elif re.match(self.wififmt, line):
	2845	+ self.wifi.append(line)
	2846	+ return True
	2847	+ elif re.match(self.testerrfmt, line):
	2848	+ self.testerror.append(line)
	2849	+ return True
	2850	+ elif re.match(self.firmwarefmt, line):
	2851	+ self.fwdata.append(line)
	2852	+ return True
	2853	+ elif(re.match(self.devpropfmt, line)):
	2854	+ self.parseDevprops(line, sv)
	2855	+ return True
	2856	+ elif(re.match(self.pinfofmt, line)):
	2857	+ self.parsePlatformInfo(line, sv)
	2858	+ return True
	2859	+ m = re.match(self.cmdlinefmt, line)
	2860	+ if m:
	2861	+ self.cmdline = m.group('cmd')
	2862	+ return True
	2863	+ m = re.match(self.tracertypefmt, line)
	2864	+ if(m):
	2865	+ self.setTracerType(m.group('t'))
	2866	+ return True
	2867	+ return False
2288	2868	def parseStamp(self, data, sv):
	2869	+ # global test data
2289	2870	m = re.match(self.stampfmt, self.stamp)
	2871	+ if not self.stamp or not m:
	2872	+ doError('data does not include the expected stamp')
2290	2873	data.stamp = {'time': '', 'host': '', 'mode': ''}
2291	2874	dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
2292	2875	int(m.group('d')), int(m.group('H')), int(m.group('M')),
..	..	@@ -2305,9 +2888,13 @@
2305	2888	data.stamp[key] = val
2306	2889	sv.hostname = data.stamp['host']
2307	2890	sv.suspendmode = data.stamp['mode']
	2891	+ if sv.suspendmode == 'freeze':
	2892	+ self.machinesuspend = 'timekeeping_freeze\[.*'
	2893	+ else:
	2894	+ self.machinesuspend = 'machine_suspend\[.*'
2308	2895	if sv.suspendmode == 'command' and sv.ftracefile != '':
2309	2896	modes = ['on', 'freeze', 'standby', 'mem', 'disk']
2310		- fp = sysvals.openlog(sv.ftracefile, 'r')
	2897	+ fp = sv.openlog(sv.ftracefile, 'r')
2311	2898	for line in fp:
2312	2899	m = re.match('.* machine_suspend\[(?P<mode>.*)\]', line)
2313	2900	if m and m.group('mode') in ['1', '2', '3', '4']:
..	..	@@ -2315,38 +2902,94 @@
2315	2902	data.stamp['mode'] = sv.suspendmode
2316	2903	break
2317	2904	fp.close()
2318		- m = re.match(self.cmdlinefmt, self.cmdline)
2319		- if m:
2320		- sv.cmdline = m.group('cmd')
2321		- if self.kparams:
2322		- m = re.match(self.kparamsfmt, self.kparams)
2323		- if m:
2324		- sv.kparams = m.group('kp')
	2905	+ sv.cmdline = self.cmdline
2325	2906	if not sv.stamp:
2326	2907	sv.stamp = data.stamp
	2908	+ # firmware data
	2909	+ if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber:
	2910	+ m = re.match(self.firmwarefmt, self.fwdata[data.testnumber])
	2911	+ if m:
	2912	+ data.fwSuspend, data.fwResume = int(m.group('s')), int(m.group('r'))
	2913	+ if(data.fwSuspend > 0 or data.fwResume > 0):
	2914	+ data.fwValid = True
	2915	+ # turbostat data
	2916	+ if len(self.turbostat) > data.testnumber:
	2917	+ m = re.match(self.tstatfmt, self.turbostat[data.testnumber])
	2918	+ if m:
	2919	+ data.turbostat = m.group('t')
	2920	+ # wifi data
	2921	+ if len(self.wifi) > data.testnumber:
	2922	+ m = re.match(self.wififmt, self.wifi[data.testnumber])
	2923	+ if m:
	2924	+ data.wifi = {'dev': m.group('d'), 'stat': m.group('s'),
	2925	+ 'time': float(m.group('t'))}
	2926	+ data.stamp['wifi'] = m.group('d')
	2927	+ # sleep mode enter errors
	2928	+ if len(self.testerror) > data.testnumber:
	2929	+ m = re.match(self.testerrfmt, self.testerror[data.testnumber])
	2930	+ if m:
	2931	+ data.enterfail = m.group('e')
	2932	+ def devprops(self, data):
	2933	+ props = dict()
	2934	+ devlist = data.split(';')
	2935	+ for dev in devlist:
	2936	+ f = dev.split(',')
	2937	+ if len(f) < 3:
	2938	+ continue
	2939	+ dev = f[0]
	2940	+ props[dev] = DevProps()
	2941	+ props[dev].altname = f[1]
	2942	+ if int(f[2]):
	2943	+ props[dev].isasync = True
	2944	+ else:
	2945	+ props[dev].isasync = False
	2946	+ return props
	2947	+ def parseDevprops(self, line, sv):
	2948	+ idx = line.index(': ') + 2
	2949	+ if idx >= len(line):
	2950	+ return
	2951	+ props = self.devprops(line[idx:])
	2952	+ if sv.suspendmode == 'command' and 'testcommandstring' in props:
	2953	+ sv.testcommand = props['testcommandstring'].altname
	2954	+ sv.devprops = props
	2955	+ def parsePlatformInfo(self, line, sv):
	2956	+ m = re.match(self.pinfofmt, line)
	2957	+ if not m:
	2958	+ return
	2959	+ name, info = m.group('val'), m.group('info')
	2960	+ if name == 'devinfo':
	2961	+ sv.devprops = self.devprops(sv.b64unzip(info))
	2962	+ return
	2963	+ elif name == 'testcmd':
	2964	+ sv.testcommand = info
	2965	+ return
	2966	+ field = info.split('\|')
	2967	+ if len(field) < 2:
	2968	+ return
	2969	+ cmdline = field[0].strip()
	2970	+ output = sv.b64unzip(field[1].strip())
	2971	+ sv.platinfo.append([name, cmdline, output])
2327	2972
2328	2973	# Class: TestRun
2329	2974	# Description:
2330	2975	# A container for a suspend/resume test run. This is necessary as
2331	2976	# there could be more than one, and they need to be separate.
2332	2977	class TestRun:
2333		- ftemp = dict()
2334		- ttemp = dict()
2335		- data = 0
2336	2978	def __init__(self, dataobj):
2337	2979	self.data = dataobj
2338	2980	self.ftemp = dict()
2339	2981	self.ttemp = dict()
2340	2982
2341	2983	class ProcessMonitor:
2342		- proclist = dict()
2343		- running = False
	2984	+ def __init__(self):
	2985	+ self.proclist = dict()
	2986	+ self.running = False
2344	2987	def procstat(self):
2345	2988	c = ['cat /proc/[1-9]*/stat 2>/dev/null']
2346	2989	process = Popen(c, shell=True, stdout=PIPE)
2347	2990	running = dict()
2348	2991	for line in process.stdout:
2349		- data = line.split()
	2992	+ data = ascii(line).split()
2350	2993	pid = data[0]
2351	2994	name = re.sub('[()]', '', data[1])
2352	2995	user = int(data[13])
..	..	@@ -2390,8 +3033,8 @@
2390	3033	# Quickly determine if the ftrace log has all of the trace events,
2391	3034	# markers, and/or kprobes required for primary parsing.
2392	3035	def doesTraceLogHaveTraceEvents():
2393		- kpcheck = ['_cal: (', '_cpu_down()']
2394		- techeck = ['suspend_resume']
	3036	+ kpcheck = ['_cal: (', '_ret: (']
	3037	+ techeck = ['suspend_resume', 'device_pm_callback']
2395	3038	tmcheck = ['SUSPEND START', 'RESUME COMPLETE']
2396	3039	sysvals.usekprobes = False
2397	3040	fp = sysvals.openlog(sysvals.ftracefile, 'r')
..	..	@@ -2414,23 +3057,14 @@
2414	3057	check.remove(i)
2415	3058	tmcheck = check
2416	3059	fp.close()
2417		- if len(techeck) == 0:
2418		- sysvals.usetraceevents = True
2419		- else:
2420		- sysvals.usetraceevents = False
2421		- if len(tmcheck) == 0:
2422		- sysvals.usetracemarkers = True
2423		- else:
2424		- sysvals.usetracemarkers = False
	3060	+ sysvals.usetraceevents = True if len(techeck) < 2 else False
	3061	+ sysvals.usetracemarkers = True if len(tmcheck) == 0 else False
2425	3062
2426	3063	# Function: appendIncompleteTraceLog
2427	3064	# Description:
2428	3065	# [deprecated for kernel 3.15 or newer]
2429		-# Legacy support of ftrace outputs that lack the device_pm_callback
2430		-# and/or suspend_resume trace events. The primary data should be
2431		-# taken from dmesg, and this ftrace is used only for callgraph data
2432		-# or custom actions in the timeline. The data is appended to the Data
2433		-# objects provided.
	3066	+# Adds callgraph data which lacks trace event data. This is only
	3067	+# for timelines generated from 3.15 or older
2434	3068	# Arguments:
2435	3069	# testruns: the array of Data objects obtained from parseKernelLog
2436	3070	def appendIncompleteTraceLog(testruns):
..	..	@@ -2450,24 +3084,7 @@
2450	3084	for line in tf:
2451	3085	# remove any latent carriage returns
2452	3086	line = line.replace('\r\n', '')
2453		- # grab the stamp and sysinfo
2454		- if re.match(tp.stampfmt, line):
2455		- tp.stamp = line
2456		- continue
2457		- elif re.match(tp.sysinfofmt, line):
2458		- tp.sysinfo = line
2459		- continue
2460		- elif re.match(tp.cmdlinefmt, line):
2461		- tp.cmdline = line
2462		- continue
2463		- # determine the trace data type (required for further parsing)
2464		- m = re.match(sysvals.tracertypefmt, line)
2465		- if(m):
2466		- tp.setTracerType(m.group('t'))
2467		- continue
2468		- # device properties line
2469		- if(re.match(sysvals.devpropfmt, line)):
2470		- devProps(line)
	3087	+ if tp.stampInfo(line, sysvals):
2471	3088	continue
2472	3089	# parse only valid lines, if this is not one move on
2473	3090	m = re.match(tp.ftrace_line_fmt, line)
..	..	@@ -2493,100 +3110,20 @@
2493	3110	if(t.startMarker()):
2494	3111	data = testrun[testidx].data
2495	3112	tp.parseStamp(data, sysvals)
2496		- data.setStart(t.time)
	3113	+ data.setStart(t.time, t.name)
2497	3114	continue
2498	3115	if(not data):
2499	3116	continue
2500	3117	# find the end of resume
2501	3118	if(t.endMarker()):
2502		- data.setEnd(t.time)
	3119	+ data.setEnd(t.time, t.name)
2503	3120	testidx += 1
2504	3121	if(testidx >= testcnt):
2505	3122	break
2506	3123	continue
2507	3124	# trace event processing
2508	3125	if(t.fevent):
2509		- # general trace events have two types, begin and end
2510		- if(re.match('(?P<name>.*) begin$', t.name)):
2511		- isbegin = True
2512		- elif(re.match('(?P<name>.*) end$', t.name)):
2513		- isbegin = False
2514		- else:
2515		- continue
2516		- m = re.match('(?P<name>.)\[(?P<val>[0-9])\] .*', t.name)
2517		- if(m):
2518		- val = m.group('val')
2519		- if val == '0':
2520		- name = m.group('name')
2521		- else:
2522		- name = m.group('name')+'['+val+']'
2523		- else:
2524		- m = re.match('(?P<name>.) .', t.name)
2525		- name = m.group('name')
2526		- # special processing for trace events
2527		- if re.match('dpm_prepare\[.*', name):
2528		- continue
2529		- elif re.match('machine_suspend.*', name):
2530		- continue
2531		- elif re.match('suspend_enter\[.*', name):
2532		- if(not isbegin):
2533		- data.dmesg['suspend_prepare']['end'] = t.time
2534		- continue
2535		- elif re.match('dpm_suspend\[.*', name):
2536		- if(not isbegin):
2537		- data.dmesg['suspend']['end'] = t.time
2538		- continue
2539		- elif re.match('dpm_suspend_late\[.*', name):
2540		- if(isbegin):
2541		- data.dmesg['suspend_late']['start'] = t.time
2542		- else:
2543		- data.dmesg['suspend_late']['end'] = t.time
2544		- continue
2545		- elif re.match('dpm_suspend_noirq\[.*', name):
2546		- if(isbegin):
2547		- data.dmesg['suspend_noirq']['start'] = t.time
2548		- else:
2549		- data.dmesg['suspend_noirq']['end'] = t.time
2550		- continue
2551		- elif re.match('dpm_resume_noirq\[.*', name):
2552		- if(isbegin):
2553		- data.dmesg['resume_machine']['end'] = t.time
2554		- data.dmesg['resume_noirq']['start'] = t.time
2555		- else:
2556		- data.dmesg['resume_noirq']['end'] = t.time
2557		- continue
2558		- elif re.match('dpm_resume_early\[.*', name):
2559		- if(isbegin):
2560		- data.dmesg['resume_early']['start'] = t.time
2561		- else:
2562		- data.dmesg['resume_early']['end'] = t.time
2563		- continue
2564		- elif re.match('dpm_resume\[.*', name):
2565		- if(isbegin):
2566		- data.dmesg['resume']['start'] = t.time
2567		- else:
2568		- data.dmesg['resume']['end'] = t.time
2569		- continue
2570		- elif re.match('dpm_complete\[.*', name):
2571		- if(isbegin):
2572		- data.dmesg['resume_complete']['start'] = t.time
2573		- else:
2574		- data.dmesg['resume_complete']['end'] = t.time
2575		- continue
2576		- # skip trace events inside devices calls
2577		- if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2578		- continue
2579		- # global events (outside device calls) are simply graphed
2580		- if(isbegin):
2581		- # store each trace event in ttemp
2582		- if(name not in testrun[testidx].ttemp):
2583		- testrun[testidx].ttemp[name] = []
2584		- testrun[testidx].ttemp[name].append(\
2585		- {'begin': t.time, 'end': t.time})
2586		- else:
2587		- # finish off matching trace event in ttemp
2588		- if(name in testrun[testidx].ttemp):
2589		- testrun[testidx].ttemp[name][-1]['end'] = t.time
	3126	+ continue
2590	3127	# call/return processing
2591	3128	elif sysvals.usecallgraph:
2592	3129	# create a callgraph object for the data
..	..	@@ -2603,12 +3140,6 @@
2603	3140	tf.close()
2604	3141
2605	3142	for test in testrun:
2606		- # add the traceevent data to the device hierarchy
2607		- if(sysvals.usetraceevents):
2608		- for name in test.ttemp:
2609		- for event in test.ttemp[name]:
2610		- test.data.newActionGlobal(name, event['begin'], event['end'])
2611		-
2612	3143	# add the callgraph data to the device hierarchy
2613	3144	for pid in test.ftemp:
2614	3145	for cg in test.ftemp[pid]:
..	..	@@ -2621,7 +3152,7 @@
2621	3152	continue
2622	3153	callstart = cg.start
2623	3154	callend = cg.end
2624		- for p in test.data.phases:
	3155	+ for p in test.data.sortedPhases():
2625	3156	if(test.data.dmesg[p]['start'] <= callstart and
2626	3157	callstart <= test.data.dmesg[p]['end']):
2627	3158	list = test.data.dmesg[p]['list']
..	..	@@ -2648,45 +3179,25 @@
2648	3179	doError('%s does not exist' % sysvals.ftracefile)
2649	3180	if not live:
2650	3181	sysvals.setupAllKprobes()
2651		- tracewatch = []
	3182	+ ksuscalls = ['ksys_sync', 'pm_prepare_console']
	3183	+ krescalls = ['pm_restore_console']
	3184	+ tracewatch = ['irq_wakeup']
2652	3185	if sysvals.usekprobes:
2653	3186	tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2654		- 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
	3187	+ 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON',
	3188	+ 'CPU_OFF', 'acpi_suspend']
2655	3189
2656	3190	# extract the callgraph and traceevent data
	3191	+ s2idle_enter = hwsus = False
2657	3192	tp = TestProps()
2658		- testruns = []
2659		- testdata = []
2660		- testrun = 0
2661		- data = 0
	3193	+ testruns, testdata = [], []
	3194	+ testrun, data, limbo = 0, 0, True
2662	3195	tf = sysvals.openlog(sysvals.ftracefile, 'r')
2663	3196	phase = 'suspend_prepare'
2664	3197	for line in tf:
2665	3198	# remove any latent carriage returns
2666	3199	line = line.replace('\r\n', '')
2667		- # stamp and sysinfo lines
2668		- if re.match(tp.stampfmt, line):
2669		- tp.stamp = line
2670		- continue
2671		- elif re.match(tp.sysinfofmt, line):
2672		- tp.sysinfo = line
2673		- continue
2674		- elif re.match(tp.cmdlinefmt, line):
2675		- tp.cmdline = line
2676		- continue
2677		- # firmware line: pull out any firmware data
2678		- m = re.match(sysvals.firmwarefmt, line)
2679		- if(m):
2680		- tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2681		- continue
2682		- # tracer type line: determine the trace data type
2683		- m = re.match(sysvals.tracertypefmt, line)
2684		- if(m):
2685		- tp.setTracerType(m.group('t'))
2686		- continue
2687		- # device properties line
2688		- if(re.match(sysvals.devpropfmt, line)):
2689		- devProps(line)
	3200	+ if tp.stampInfo(line, sysvals):
2690	3201	continue
2691	3202	# ignore all other commented lines
2692	3203	if line[0] == '#':
..	..	@@ -2714,20 +3225,20 @@
2714	3225	continue
2715	3226	# find the start of suspend
2716	3227	if(t.startMarker()):
2717		- phase = 'suspend_prepare'
2718		- data = Data(len(testdata))
	3228	+ data, limbo = Data(len(testdata)), False
2719	3229	testdata.append(data)
2720	3230	testrun = TestRun(data)
2721	3231	testruns.append(testrun)
2722	3232	tp.parseStamp(data, sysvals)
2723		- data.setStart(t.time)
2724		- data.tKernSus = t.time
	3233	+ data.setStart(t.time, t.name)
	3234	+ data.first_suspend_prepare = True
	3235	+ phase = data.setPhase('suspend_prepare', t.time, True)
2725	3236	continue
2726		- if(not data):
	3237	+ if(not data or limbo):
2727	3238	continue
2728	3239	# process cpu exec line
2729	3240	if t.type == 'tracing_mark_write':
2730		- m = re.match(sysvals.procexecfmt, t.name)
	3241	+ m = re.match(tp.procexecfmt, t.name)
2731	3242	if(m):
2732	3243	proclist = dict()
2733	3244	for ps in m.group('ps').split(','):
..	..	@@ -2740,28 +3251,19 @@
2740	3251	continue
2741	3252	# find the end of resume
2742	3253	if(t.endMarker()):
2743		- data.setEnd(t.time)
2744		- if data.tKernRes == 0.0:
	3254	+ if data.tKernRes == 0:
2745	3255	data.tKernRes = t.time
2746		- if data.dmesg['resume_complete']['end'] < 0:
2747		- data.dmesg['resume_complete']['end'] = t.time
2748		- if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
2749		- data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2750		- if(data.tSuspended != 0 and data.tResumed != 0 and \
2751		- (data.fwSuspend > 0 or data.fwResume > 0)):
2752		- data.fwValid = True
	3256	+ data.handleEndMarker(t.time, t.name)
2753	3257	if(not sysvals.usetracemarkers):
2754	3258	# no trace markers? then quit and be sure to finish recording
2755	3259	# the event we used to trigger resume end
2756		- if(len(testrun.ttemp['thaw_processes']) > 0):
	3260	+ if('thaw_processes' in testrun.ttemp and len(testrun.ttemp['thaw_processes']) > 0):
2757	3261	# if an entry exists, assume this is its end
2758	3262	testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2759		- break
	3263	+ limbo = True
2760	3264	continue
2761	3265	# trace event processing
2762	3266	if(t.fevent):
2763		- if(phase == 'post_resume'):
2764		- data.setEnd(t.time)
2765	3267	if(t.type == 'suspend_resume'):
2766	3268	# suspend_resume trace events have two types, begin and end
2767	3269	if(re.match('(?P<name>.*) begin$', t.name)):
..	..	@@ -2770,102 +3272,88 @@
2770	3272	isbegin = False
2771	3273	else:
2772	3274	continue
2773		- m = re.match('(?P<name>.)\[(?P<val>[0-9])\] .*', t.name)
2774		- if(m):
2775		- val = m.group('val')
2776		- if val == '0':
2777		- name = m.group('name')
2778		- else:
2779		- name = m.group('name')+'['+val+']'
	3275	+ if '[' in t.name:
	3276	+ m = re.match('(?P<name>.)\[.', t.name)
2780	3277	else:
2781	3278	m = re.match('(?P<name>.) .', t.name)
2782		- name = m.group('name')
	3279	+ name = m.group('name')
2783	3280	# ignore these events
2784	3281	if(name.split('[')[0] in tracewatch):
2785	3282	continue
2786	3283	# -- phase changes --
2787	3284	# start of kernel suspend
2788	3285	if(re.match('suspend_enter\[.*', t.name)):
2789		- if(isbegin and data.start == data.tKernSus):
2790		- data.dmesg[phase]['start'] = t.time
	3286	+ if(isbegin and data.tKernSus == 0):
2791	3287	data.tKernSus = t.time
2792	3288	continue
2793	3289	# suspend_prepare start
2794	3290	elif(re.match('dpm_prepare\[.*', t.name)):
2795		- phase = 'suspend_prepare'
2796		- if(not isbegin):
2797		- data.dmesg[phase]['end'] = t.time
2798		- if data.dmesg[phase]['start'] < 0:
2799		- data.dmesg[phase]['start'] = data.start
	3291	+ if isbegin and data.first_suspend_prepare:
	3292	+ data.first_suspend_prepare = False
	3293	+ if data.tKernSus == 0:
	3294	+ data.tKernSus = t.time
	3295	+ continue
	3296	+ phase = data.setPhase('suspend_prepare', t.time, isbegin)
2800	3297	continue
2801	3298	# suspend start
2802	3299	elif(re.match('dpm_suspend\[.*', t.name)):
2803		- phase = 'suspend'
2804		- data.setPhase(phase, t.time, isbegin)
	3300	+ phase = data.setPhase('suspend', t.time, isbegin)
2805	3301	continue
2806	3302	# suspend_late start
2807	3303	elif(re.match('dpm_suspend_late\[.*', t.name)):
2808		- phase = 'suspend_late'
2809		- data.setPhase(phase, t.time, isbegin)
	3304	+ phase = data.setPhase('suspend_late', t.time, isbegin)
2810	3305	continue
2811	3306	# suspend_noirq start
2812	3307	elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2813		- if data.phaseCollision('suspend_noirq', isbegin, line):
2814		- continue
2815		- phase = 'suspend_noirq'
2816		- data.setPhase(phase, t.time, isbegin)
2817		- if(not isbegin):
2818		- phase = 'suspend_machine'
2819		- data.dmesg[phase]['start'] = t.time
	3308	+ phase = data.setPhase('suspend_noirq', t.time, isbegin)
2820	3309	continue
2821	3310	# suspend_machine/resume_machine
2822		- elif(re.match('machine_suspend\[.*', t.name)):
	3311	+ elif(re.match(tp.machinesuspend, t.name)):
	3312	+ lp = data.lastPhase()
2823	3313	if(isbegin):
2824		- phase = 'suspend_machine'
2825		- data.dmesg[phase]['end'] = t.time
2826		- data.tSuspended = t.time
	3314	+ hwsus = True
	3315	+ if lp.startswith('resume_machine'):
	3316	+ # trim out s2idle loops, track time trying to freeze
	3317	+ llp = data.lastPhase(2)
	3318	+ if llp.startswith('suspend_machine'):
	3319	+ if 'trying' not in data.dmesg[llp]:
	3320	+ data.dmesg[llp]['trying'] = 0
	3321	+ data.dmesg[llp]['trying'] += \
	3322	+ t.time - data.dmesg[lp]['start']
	3323	+ data.currphase = ''
	3324	+ del data.dmesg[lp]
	3325	+ continue
	3326	+ phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True)
	3327	+ data.setPhase(phase, t.time, False)
	3328	+ if data.tSuspended == 0:
	3329	+ data.tSuspended = t.time
2827	3330	else:
2828		- if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
2829		- data.dmesg['suspend_machine']['end'] = t.time
	3331	+ if lp.startswith('resume_machine'):
	3332	+ data.dmesg[lp]['end'] = t.time
	3333	+ continue
	3334	+ phase = data.setPhase('resume_machine', t.time, True)
	3335	+ if(sysvals.suspendmode in ['mem', 'disk']):
	3336	+ susp = phase.replace('resume', 'suspend')
	3337	+ if susp in data.dmesg:
	3338	+ data.dmesg[susp]['end'] = t.time
2830	3339	data.tSuspended = t.time
2831		- phase = 'resume_machine'
2832		- data.dmesg[phase]['start'] = t.time
2833	3340	data.tResumed = t.time
2834		- data.tLow = data.tResumed - data.tSuspended
2835		- continue
2836		- # acpi_suspend
2837		- elif(re.match('acpi_suspend\[.*', t.name)):
2838		- # acpi_suspend[0] S0i3
2839		- if(re.match('acpi_suspend\[0\] begin', t.name)):
2840		- if(sysvals.suspendmode == 'mem'):
2841		- tp.S0i3 = True
2842		- data.dmesg['suspend_machine']['end'] = t.time
2843		- data.tSuspended = t.time
2844	3341	continue
2845	3342	# resume_noirq start
2846	3343	elif(re.match('dpm_resume_noirq\[.*', t.name)):
2847		- if data.phaseCollision('resume_noirq', isbegin, line):
2848		- continue
2849		- phase = 'resume_noirq'
2850		- data.setPhase(phase, t.time, isbegin)
2851		- if(isbegin):
2852		- data.dmesg['resume_machine']['end'] = t.time
	3344	+ phase = data.setPhase('resume_noirq', t.time, isbegin)
2853	3345	continue
2854	3346	# resume_early start
2855	3347	elif(re.match('dpm_resume_early\[.*', t.name)):
2856		- phase = 'resume_early'
2857		- data.setPhase(phase, t.time, isbegin)
	3348	+ phase = data.setPhase('resume_early', t.time, isbegin)
2858	3349	continue
2859	3350	# resume start
2860	3351	elif(re.match('dpm_resume\[.*', t.name)):
2861		- phase = 'resume'
2862		- data.setPhase(phase, t.time, isbegin)
	3352	+ phase = data.setPhase('resume', t.time, isbegin)
2863	3353	continue
2864	3354	# resume complete start
2865	3355	elif(re.match('dpm_complete\[.*', t.name)):
2866		- phase = 'resume_complete'
2867		- if(isbegin):
2868		- data.dmesg[phase]['start'] = t.time
	3356	+ phase = data.setPhase('resume_complete', t.time, isbegin)
2869	3357	continue
2870	3358	# skip trace events inside devices calls
2871	3359	if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
..	..	@@ -2873,6 +3361,19 @@
2873	3361	# global events (outside device calls) are graphed
2874	3362	if(name not in testrun.ttemp):
2875	3363	testrun.ttemp[name] = []
	3364	+ # special handling for s2idle_enter
	3365	+ if name == 'machine_suspend':
	3366	+ if hwsus:
	3367	+ s2idle_enter = hwsus = False
	3368	+ elif s2idle_enter and not isbegin:
	3369	+ if(len(testrun.ttemp[name]) > 0):
	3370	+ testrun.ttemp[name][-1]['end'] = t.time
	3371	+ testrun.ttemp[name][-1]['loop'] += 1
	3372	+ elif not s2idle_enter and isbegin:
	3373	+ s2idle_enter = True
	3374	+ testrun.ttemp[name].append({'begin': t.time,
	3375	+ 'end': t.time, 'pid': pid, 'loop': 0})
	3376	+ continue
2876	3377	if(isbegin):
2877	3378	# create a new list entry
2878	3379	testrun.ttemp[name].append(\
..	..	@@ -2881,13 +3382,10 @@
2881	3382	if(len(testrun.ttemp[name]) > 0):
2882	3383	# if an entry exists, assume this is its end
2883	3384	testrun.ttemp[name][-1]['end'] = t.time
2884		- elif(phase == 'post_resume'):
2885		- # post resume events can just have ends
2886		- testrun.ttemp[name].append({
2887		- 'begin': data.dmesg[phase]['start'],
2888		- 'end': t.time})
2889	3385	# device callback start
2890	3386	elif(t.type == 'device_pm_callback_start'):
	3387	+ if phase not in data.dmesg:
	3388	+ continue
2891	3389	m = re.match('(?P<drv>.) (?P<d>.), parent: (?P<p>.), .*',\
2892	3390	t.name);
2893	3391	if(not m):
..	..	@@ -2901,13 +3399,14 @@
2901	3399	data.devpids.append(pid)
2902	3400	# device callback finish
2903	3401	elif(t.type == 'device_pm_callback_end'):
	3402	+ if phase not in data.dmesg:
	3403	+ continue
2904	3404	m = re.match('(?P<drv>.) (?P<d>.), err.*', t.name);
2905	3405	if(not m):
2906	3406	continue
2907	3407	n = m.group('d')
2908		- list = data.dmesg[phase]['list']
2909		- if(n in list):
2910		- dev = list[n]
	3408	+ dev = data.findDevice(phase, n)
	3409	+ if dev:
2911	3410	dev['length'] = t.time - dev['start']
2912	3411	dev['end'] = t.time
2913	3412	# kprobe event processing
..	..	@@ -2926,24 +3425,27 @@
2926	3425	tp.ktemp[key].append({
2927	3426	'pid': pid,
2928	3427	'begin': t.time,
2929		- 'end': t.time,
	3428	+ 'end': -1,
2930	3429	'name': displayname,
2931	3430	'cdata': kprobedata,
2932	3431	'proc': m_proc,
2933	3432	})
	3433	+ # start of kernel resume
	3434	+ if(data.tKernSus == 0 and phase == 'suspend_prepare' \
	3435	+ and kprobename in ksuscalls):
	3436	+ data.tKernSus = t.time
2934	3437	elif(t.freturn):
2935	3438	if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2936	3439	continue
2937		- e = tp.ktemp[key][-1]
2938		- if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2939		- tp.ktemp[key].pop()
2940		- else:
2941		- e['end'] = t.time
2942		- e['rdata'] = kprobedata
	3440	+ e = next((x for x in reversed(tp.ktemp[key]) if x['end'] < 0), 0)
	3441	+ if not e:
	3442	+ continue
	3443	+ e['end'] = t.time
	3444	+ e['rdata'] = kprobedata
2943	3445	# end of kernel resume
2944		- if(kprobename == 'pm_notifier_call_chain' or \
2945		- kprobename == 'pm_restore_console'):
2946		- data.dmesg[phase]['end'] = t.time
	3446	+ if(phase != 'suspend_prepare' and kprobename in krescalls):
	3447	+ if phase in data.dmesg:
	3448	+ data.dmesg[phase]['end'] = t.time
2947	3449	data.tKernRes = t.time
2948	3450
2949	3451	# callgraph processing
..	..	@@ -2961,10 +3463,15 @@
2961	3463	if(res == -1):
2962	3464	testrun.ftemp[key][-1].addLine(t)
2963	3465	tf.close()
	3466	+ if len(testdata) < 1:
	3467	+ sysvals.vprint('WARNING: ftrace start marker is missing')
	3468	+ if data and not data.devicegroups:
	3469	+ sysvals.vprint('WARNING: ftrace end marker is missing')
	3470	+ data.handleEndMarker(t.time, t.name)
2964	3471
2965	3472	if sysvals.suspendmode == 'command':
2966	3473	for test in testruns:
2967		- for p in test.data.phases:
	3474	+ for p in test.data.sortedPhases():
2968	3475	if p == 'suspend_prepare':
2969	3476	test.data.dmesg[p]['start'] = test.data.start
2970	3477	test.data.dmesg[p]['end'] = test.data.end
..	..	@@ -2973,12 +3480,19 @@
2973	3480	test.data.dmesg[p]['end'] = test.data.end
2974	3481	test.data.tSuspended = test.data.end
2975	3482	test.data.tResumed = test.data.end
2976		- test.data.tLow = 0
2977	3483	test.data.fwValid = False
2978	3484
2979	3485	# dev source and procmon events can be unreadable with mixed phase height
2980	3486	if sysvals.usedevsrc or sysvals.useprocmon:
2981	3487	sysvals.mixedphaseheight = False
	3488	+
	3489	+ # expand phase boundaries so there are no gaps
	3490	+ for data in testdata:
	3491	+ lp = data.sortedPhases()[0]
	3492	+ for p in data.sortedPhases():
	3493	+ if(p != lp and not ('machine' in p and 'machine' in lp)):
	3494	+ data.dmesg[lp]['end'] = data.dmesg[p]['start']
	3495	+ lp = p
2982	3496
2983	3497	for i in range(len(testruns)):
2984	3498	test = testruns[i]
..	..	@@ -2993,36 +3507,43 @@
2993	3507	# add the traceevent data to the device hierarchy
2994	3508	if(sysvals.usetraceevents):
2995	3509	# add actual trace funcs
2996		- for name in test.ttemp:
	3510	+ for name in sorted(test.ttemp):
2997	3511	for event in test.ttemp[name]:
2998		- data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
	3512	+ if event['end'] - event['begin'] <= 0:
	3513	+ continue
	3514	+ title = name
	3515	+ if name == 'machine_suspend' and 'loop' in event:
	3516	+ title = 's2idle_enter_%dx' % event['loop']
	3517	+ data.newActionGlobal(title, event['begin'], event['end'], event['pid'])
2999	3518	# add the kprobe based virtual tracefuncs as actual devices
3000		- for key in tp.ktemp:
	3519	+ for key in sorted(tp.ktemp):
3001	3520	name, pid = key
3002	3521	if name not in sysvals.tracefuncs:
3003	3522	continue
	3523	+ if pid not in data.devpids:
	3524	+ data.devpids.append(pid)
3004	3525	for e in tp.ktemp[key]:
3005	3526	kb, ke = e['begin'], e['end']
3006		- if kb == ke or tlb > kb or tle <= kb:
	3527	+ if ke - kb < 0.000001 or tlb > kb or tle <= kb:
3007	3528	continue
3008	3529	color = sysvals.kprobeColor(name)
3009	3530	data.newActionGlobal(e['name'], kb, ke, pid, color)
3010	3531	# add config base kprobes and dev kprobes
3011	3532	if sysvals.usedevsrc:
3012		- for key in tp.ktemp:
	3533	+ for key in sorted(tp.ktemp):
3013	3534	name, pid = key
3014	3535	if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs:
3015	3536	continue
3016	3537	for e in tp.ktemp[key]:
3017	3538	kb, ke = e['begin'], e['end']
3018		- if kb == ke or tlb > kb or tle <= kb:
	3539	+ if ke - kb < 0.000001 or tlb > kb or tle <= kb:
3019	3540	continue
3020	3541	data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
3021	3542	ke, e['cdata'], e['rdata'])
3022	3543	if sysvals.usecallgraph:
3023	3544	# add the callgraph data to the device hierarchy
3024	3545	sortlist = dict()
3025		- for key in test.ftemp:
	3546	+ for key in sorted(test.ftemp):
3026	3547	proc, pid = key
3027	3548	for cg in test.ftemp[key]:
3028	3549	if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
..	..	@@ -3039,9 +3560,9 @@
3039	3560	if not devname:
3040	3561	sortkey = '%f%f%d' % (cg.start, cg.end, pid)
3041	3562	sortlist[sortkey] = cg
3042		- elif len(cg.list) > 1000000:
3043		- print 'WARNING: the callgraph for %s is massive (%d lines)' %\
3044		- (devname, len(cg.list))
	3563	+ elif len(cg.list) > 1000000 and cg.name != sysvals.ftopfunc:
	3564	+ sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\
	3565	+ (devname, len(cg.list)))
3045	3566	# create blocks for orphan cg data
3046	3567	for sortkey in sorted(sortlist):
3047	3568	cg = sortlist[sortkey]
..	..	@@ -3057,25 +3578,34 @@
3057	3578	for data in testdata:
3058	3579	tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))
3059	3580	terr = ''
3060		- lp = data.phases[0]
3061		- for p in data.phases:
3062		- if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
	3581	+ phasedef = data.phasedef
	3582	+ lp = 'suspend_prepare'
	3583	+ for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
	3584	+ if p not in data.dmesg:
3063	3585	if not terr:
3064		- print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)
3065		- terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp)
	3586	+ ph = p if 'machine' in p else lp
	3587	+ terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph)
	3588	+ pprint('TEST%s FAILED: %s' % (tn, terr))
3066	3589	error.append(terr)
	3590	+ if data.tSuspended == 0:
	3591	+ data.tSuspended = data.dmesg[lp]['end']
	3592	+ if data.tResumed == 0:
	3593	+ data.tResumed = data.dmesg[lp]['end']
	3594	+ data.fwValid = False
3067	3595	sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3068		- if(data.dmesg[p]['start'] < 0):
3069		- data.dmesg[p]['start'] = data.dmesg[lp]['end']
3070		- if(p == 'resume_machine'):
3071		- data.tSuspended = data.dmesg[lp]['end']
3072		- data.tResumed = data.dmesg[lp]['end']
3073		- data.tLow = 0
3074		- if(data.dmesg[p]['end'] < 0):
3075		- data.dmesg[p]['end'] = data.dmesg[p]['start']
3076		- if(p != lp and not ('machine' in p and 'machine' in lp)):
3077		- data.dmesg[lp]['end'] = data.dmesg[p]['start']
3078	3596	lp = p
	3597	+ if not terr and 'dev' in data.wifi and data.wifi['stat'] == 'timeout':
	3598	+ terr = '%s%s failed in wifi_resume <i>(%s %.0fs timeout)</i>' % \
	3599	+ (sysvals.suspendmode, tn, data.wifi['dev'], data.wifi['time'])
	3600	+ error.append(terr)
	3601	+ if not terr and data.enterfail:
	3602	+ pprint('test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail))
	3603	+ terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode)
	3604	+ error.append(terr)
	3605	+ if data.tSuspended == 0:
	3606	+ data.tSuspended = data.tKernRes
	3607	+ if data.tResumed == 0:
	3608	+ data.tResumed = data.tSuspended
3079	3609
3080	3610	if(len(sysvals.devicefilter) > 0):
3081	3611	data.deviceFilter(sysvals.devicefilter)
..	..	@@ -3117,19 +3647,7 @@
3117	3647	idx = line.find('[')
3118	3648	if idx > 1:
3119	3649	line = line[idx:]
3120		- # grab the stamp and sysinfo
3121		- if re.match(tp.stampfmt, line):
3122		- tp.stamp = line
3123		- continue
3124		- elif re.match(tp.sysinfofmt, line):
3125		- tp.sysinfo = line
3126		- continue
3127		- elif re.match(tp.cmdlinefmt, line):
3128		- tp.cmdline = line
3129		- continue
3130		- m = re.match(sysvals.firmwarefmt, line)
3131		- if(m):
3132		- tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
	3650	+ if tp.stampInfo(line, sysvals):
3133	3651	continue
3134	3652	m = re.match('[ \t](\[ )(?P<ktime>[0-9\.])(\]) (?P<msg>.)', line)
3135	3653	if(not m):
..	..	@@ -3140,10 +3658,6 @@
3140	3658	testruns.append(data)
3141	3659	data = Data(len(testruns))
3142	3660	tp.parseStamp(data, sysvals)
3143		- if len(tp.fwdata) > data.testnumber:
3144		- data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
3145		- if(data.fwSuspend > 0 or data.fwResume > 0):
3146		- data.fwValid = True
3147	3661	if(not data):
3148	3662	continue
3149	3663	m = re.match('.* (?P<k>[0-9]\.[0-9]{2}\.[0-9]-.) .*', msg)
..	..	@@ -3158,7 +3672,7 @@
3158	3672	if data:
3159	3673	testruns.append(data)
3160	3674	if len(testruns) < 1:
3161		- print('ERROR: dmesg log has no suspend/resume data: %s' \
	3675	+ doError('dmesg log has no suspend/resume data: %s' \
3162	3676	% sysvals.dmesgfile)
3163	3677
3164	3678	# fix lines with same timestamp/function with the call and return swapped
..	..	@@ -3199,30 +3713,30 @@
3199	3713
3200	3714	# dmesg phase match table
3201	3715	dm = {
3202		- 'suspend_prepare': 'PM: Syncing filesystems.*',
3203		- 'suspend': 'PM: Entering [a-z]* sleep.*',
3204		- 'suspend_late': 'PM: suspend of devices complete after.*',
3205		- 'suspend_noirq': 'PM: late suspend of devices complete after.*',
3206		- 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
3207		- 'resume_machine': 'ACPI: Low-level resume complete.*',
3208		- 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
3209		- 'resume_early': 'PM: noirq resume of devices complete after.*',
3210		- 'resume': 'PM: early resume of devices complete after.*',
3211		- 'resume_complete': 'PM: resume of devices complete after.*',
3212		- 'post_resume': '.Restarting tasks \.\.\..',
	3716	+ 'suspend_prepare': ['PM: Syncing filesystems.*'],
	3717	+ 'suspend': ['PM: Entering [a-z]* sleep.', 'Suspending console.'],
	3718	+ 'suspend_late': ['PM: suspend of devices complete after.*'],
	3719	+ 'suspend_noirq': ['PM: late suspend of devices complete after.*'],
	3720	+ 'suspend_machine': ['PM: noirq suspend of devices complete after.*'],
	3721	+ 'resume_machine': ['ACPI: Low-level resume complete.*'],
	3722	+ 'resume_noirq': ['ACPI: Waking up from system sleep state.*'],
	3723	+ 'resume_early': ['PM: noirq resume of devices complete after.*'],
	3724	+ 'resume': ['PM: early resume of devices complete after.*'],
	3725	+ 'resume_complete': ['PM: resume of devices complete after.*'],
	3726	+ 'post_resume': ['.Restarting tasks \.\.\..'],
3213	3727	}
3214	3728	if(sysvals.suspendmode == 'standby'):
3215		- dm['resume_machine'] = 'PM: Restoring platform NVS memory'
	3729	+ dm['resume_machine'] = ['PM: Restoring platform NVS memory']
3216	3730	elif(sysvals.suspendmode == 'disk'):
3217		- dm['suspend_late'] = 'PM: freeze of devices complete after.*'
3218		- dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
3219		- dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
3220		- dm['resume_machine'] = 'PM: Restoring platform NVS memory'
3221		- dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
3222		- dm['resume'] = 'PM: early restore of devices complete after.*'
3223		- dm['resume_complete'] = 'PM: restore of devices complete after.*'
	3731	+ dm['suspend_late'] = ['PM: freeze of devices complete after.*']
	3732	+ dm['suspend_noirq'] = ['PM: late freeze of devices complete after.*']
	3733	+ dm['suspend_machine'] = ['PM: noirq freeze of devices complete after.*']
	3734	+ dm['resume_machine'] = ['PM: Restoring platform NVS memory']
	3735	+ dm['resume_early'] = ['PM: noirq restore of devices complete after.*']
	3736	+ dm['resume'] = ['PM: early restore of devices complete after.*']
	3737	+ dm['resume_complete'] = ['PM: restore of devices complete after.*']
3224	3738	elif(sysvals.suspendmode == 'freeze'):
3225		- dm['resume_machine'] = 'ACPI: resume from mwait'
	3739	+ dm['resume_machine'] = ['ACPI: resume from mwait']
3226	3740
3227	3741	# action table (expected events that occur and show up in dmesg)
3228	3742	at = {
..	..	@@ -3264,81 +3778,89 @@
3264	3778	else:
3265	3779	continue
3266	3780
	3781	+ # check for a phase change line
	3782	+ phasechange = False
	3783	+ for p in dm:
	3784	+ for s in dm[p]:
	3785	+ if(re.match(s, msg)):
	3786	+ phasechange, phase = True, p
	3787	+ break
	3788	+
3267	3789	# hack for determining resume_machine end for freeze
3268	3790	if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
3269	3791	and phase == 'resume_machine' and \
3270	3792	re.match('calling (?P<f>.)\+ @ ., parent: .*', msg)):
3271		- data.dmesg['resume_machine']['end'] = ktime
	3793	+ data.setPhase(phase, ktime, False)
3272	3794	phase = 'resume_noirq'
3273		- data.dmesg[phase]['start'] = ktime
	3795	+ data.setPhase(phase, ktime, True)
3274	3796
3275		- # suspend start
3276		- if(re.match(dm['suspend_prepare'], msg)):
3277		- phase = 'suspend_prepare'
3278		- data.dmesg[phase]['start'] = ktime
3279		- data.setStart(ktime)
3280		- data.tKernSus = ktime
3281		- # suspend start
3282		- elif(re.match(dm['suspend'], msg)):
3283		- data.dmesg['suspend_prepare']['end'] = ktime
3284		- phase = 'suspend'
3285		- data.dmesg[phase]['start'] = ktime
3286		- # suspend_late start
3287		- elif(re.match(dm['suspend_late'], msg)):
3288		- data.dmesg['suspend']['end'] = ktime
3289		- phase = 'suspend_late'
3290		- data.dmesg[phase]['start'] = ktime
3291		- # suspend_noirq start
3292		- elif(re.match(dm['suspend_noirq'], msg)):
3293		- data.dmesg['suspend_late']['end'] = ktime
3294		- phase = 'suspend_noirq'
3295		- data.dmesg[phase]['start'] = ktime
3296		- # suspend_machine start
3297		- elif(re.match(dm['suspend_machine'], msg)):
3298		- data.dmesg['suspend_noirq']['end'] = ktime
3299		- phase = 'suspend_machine'
3300		- data.dmesg[phase]['start'] = ktime
3301		- # resume_machine start
3302		- elif(re.match(dm['resume_machine'], msg)):
3303		- if(sysvals.suspendmode in ['freeze', 'standby']):
3304		- data.tSuspended = prevktime
3305		- data.dmesg['suspend_machine']['end'] = prevktime
3306		- else:
3307		- data.tSuspended = ktime
3308		- data.dmesg['suspend_machine']['end'] = ktime
3309		- phase = 'resume_machine'
3310		- data.tResumed = ktime
3311		- data.tLow = data.tResumed - data.tSuspended
3312		- data.dmesg[phase]['start'] = ktime
3313		- # resume_noirq start
3314		- elif(re.match(dm['resume_noirq'], msg)):
3315		- data.dmesg['resume_machine']['end'] = ktime
3316		- phase = 'resume_noirq'
3317		- data.dmesg[phase]['start'] = ktime
3318		- # resume_early start
3319		- elif(re.match(dm['resume_early'], msg)):
3320		- data.dmesg['resume_noirq']['end'] = ktime
3321		- phase = 'resume_early'
3322		- data.dmesg[phase]['start'] = ktime
3323		- # resume start
3324		- elif(re.match(dm['resume'], msg)):
3325		- data.dmesg['resume_early']['end'] = ktime
3326		- phase = 'resume'
3327		- data.dmesg[phase]['start'] = ktime
3328		- # resume complete start
3329		- elif(re.match(dm['resume_complete'], msg)):
3330		- data.dmesg['resume']['end'] = ktime
3331		- phase = 'resume_complete'
3332		- data.dmesg[phase]['start'] = ktime
3333		- # post resume start
3334		- elif(re.match(dm['post_resume'], msg)):
3335		- data.dmesg['resume_complete']['end'] = ktime
3336		- data.setEnd(ktime)
3337		- data.tKernRes = ktime
3338		- break
	3797	+ if phasechange:
	3798	+ if phase == 'suspend_prepare':
	3799	+ data.setPhase(phase, ktime, True)
	3800	+ data.setStart(ktime)
	3801	+ data.tKernSus = ktime
	3802	+ elif phase == 'suspend':
	3803	+ lp = data.lastPhase()
	3804	+ if lp:
	3805	+ data.setPhase(lp, ktime, False)
	3806	+ data.setPhase(phase, ktime, True)
	3807	+ elif phase == 'suspend_late':
	3808	+ lp = data.lastPhase()
	3809	+ if lp:
	3810	+ data.setPhase(lp, ktime, False)
	3811	+ data.setPhase(phase, ktime, True)
	3812	+ elif phase == 'suspend_noirq':
	3813	+ lp = data.lastPhase()
	3814	+ if lp:
	3815	+ data.setPhase(lp, ktime, False)
	3816	+ data.setPhase(phase, ktime, True)
	3817	+ elif phase == 'suspend_machine':
	3818	+ lp = data.lastPhase()
	3819	+ if lp:
	3820	+ data.setPhase(lp, ktime, False)
	3821	+ data.setPhase(phase, ktime, True)
	3822	+ elif phase == 'resume_machine':
	3823	+ lp = data.lastPhase()
	3824	+ if(sysvals.suspendmode in ['freeze', 'standby']):
	3825	+ data.tSuspended = prevktime
	3826	+ if lp:
	3827	+ data.setPhase(lp, prevktime, False)
	3828	+ else:
	3829	+ data.tSuspended = ktime
	3830	+ if lp:
	3831	+ data.setPhase(lp, prevktime, False)
	3832	+ data.tResumed = ktime
	3833	+ data.setPhase(phase, ktime, True)
	3834	+ elif phase == 'resume_noirq':
	3835	+ lp = data.lastPhase()
	3836	+ if lp:
	3837	+ data.setPhase(lp, ktime, False)
	3838	+ data.setPhase(phase, ktime, True)
	3839	+ elif phase == 'resume_early':
	3840	+ lp = data.lastPhase()
	3841	+ if lp:
	3842	+ data.setPhase(lp, ktime, False)
	3843	+ data.setPhase(phase, ktime, True)
	3844	+ elif phase == 'resume':
	3845	+ lp = data.lastPhase()
	3846	+ if lp:
	3847	+ data.setPhase(lp, ktime, False)
	3848	+ data.setPhase(phase, ktime, True)
	3849	+ elif phase == 'resume_complete':
	3850	+ lp = data.lastPhase()
	3851	+ if lp:
	3852	+ data.setPhase(lp, ktime, False)
	3853	+ data.setPhase(phase, ktime, True)
	3854	+ elif phase == 'post_resume':
	3855	+ lp = data.lastPhase()
	3856	+ if lp:
	3857	+ data.setPhase(lp, ktime, False)
	3858	+ data.setEnd(ktime)
	3859	+ data.tKernRes = ktime
	3860	+ break
3339	3861
3340	3862	# -- device callbacks --
3341		- if(phase in data.phases):
	3863	+ if(phase in data.sortedPhases()):
3342	3864	# device init call
3343	3865	if(re.match('calling (?P<f>.)\+ @ ., parent: .*', msg)):
3344	3866	sm = re.match('calling (?P<f>.*)\+ @ '+\
..	..	@@ -3364,7 +3886,7 @@
3364	3886	# if trace events are not available, these are better than nothing
3365	3887	if(not sysvals.usetraceevents):
3366	3888	# look for known actions
3367		- for a in at:
	3889	+ for a in sorted(at):
3368	3890	if(re.match(at[a]['smsg'], msg)):
3369	3891	if(a not in actions):
3370	3892	actions[a] = []
..	..	@@ -3396,27 +3918,34 @@
3396	3918	actions[cpu].append({'begin': cpu_start, 'end': ktime})
3397	3919	cpu_start = ktime
3398	3920	prevktime = ktime
	3921	+ data.initDevicegroups()
3399	3922
3400	3923	# fill in any missing phases
3401		- lp = data.phases[0]
3402		- for p in data.phases:
3403		- if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
3404		- print('WARNING: phase "%s" is missing, something went wrong!' % p)
3405		- print(' In %s, this dmesg line denotes the start of %s:' % \
3406		- (sysvals.suspendmode, p))
3407		- print(' "%s"' % dm[p])
3408		- if(data.dmesg[p]['start'] < 0):
3409		- data.dmesg[p]['start'] = data.dmesg[lp]['end']
3410		- if(p == 'resume_machine'):
3411		- data.tSuspended = data.dmesg[lp]['end']
3412		- data.tResumed = data.dmesg[lp]['end']
3413		- data.tLow = 0
3414		- if(data.dmesg[p]['end'] < 0):
3415		- data.dmesg[p]['end'] = data.dmesg[p]['start']
	3924	+ phasedef = data.phasedef
	3925	+ terr, lp = '', 'suspend_prepare'
	3926	+ for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
	3927	+ if p not in data.dmesg:
	3928	+ if not terr:
	3929	+ pprint('TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp))
	3930	+ terr = '%s failed in %s phase' % (sysvals.suspendmode, lp)
	3931	+ if data.tSuspended == 0:
	3932	+ data.tSuspended = data.dmesg[lp]['end']
	3933	+ if data.tResumed == 0:
	3934	+ data.tResumed = data.dmesg[lp]['end']
	3935	+ sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3416	3936	lp = p
	3937	+ lp = data.sortedPhases()[0]
	3938	+ for p in data.sortedPhases():
	3939	+ if(p != lp and not ('machine' in p and 'machine' in lp)):
	3940	+ data.dmesg[lp]['end'] = data.dmesg[p]['start']
	3941	+ lp = p
	3942	+ if data.tSuspended == 0:
	3943	+ data.tSuspended = data.tKernRes
	3944	+ if data.tResumed == 0:
	3945	+ data.tResumed = data.tSuspended
3417	3946
3418	3947	# fill in any actions we've found
3419		- for name in actions:
	3948	+ for name in sorted(actions):
3420	3949	for event in actions[name]:
3421	3950	data.newActionGlobal(name, event['begin'], event['end'])
3422	3951
..	..	@@ -3462,26 +3991,30 @@
3462	3991	hf.write('<section id="callgraphs" class="callgraph">\n')
3463	3992	# write out the ftrace data converted to html
3464	3993	num = 0
3465		- for p in data.phases:
	3994	+ for p in data.sortedPhases():
3466	3995	if sv.cgphase and p != sv.cgphase:
3467	3996	continue
3468	3997	list = data.dmesg[p]['list']
3469		- for devname in data.sortedDevices(p):
3470		- if len(sv.cgfilter) > 0 and devname not in sv.cgfilter:
	3998	+ for d in data.sortedDevices(p):
	3999	+ if len(sv.cgfilter) > 0 and d not in sv.cgfilter:
3471	4000	continue
3472		- dev = list[devname]
	4001	+ dev = list[d]
3473	4002	color = 'white'
3474	4003	if 'color' in data.dmesg[p]:
3475	4004	color = data.dmesg[p]['color']
3476	4005	if 'color' in dev:
3477	4006	color = dev['color']
3478		- name = devname
3479		- if(devname in sv.devprops):
3480		- name = sv.devprops[devname].altName(devname)
	4007	+ name = d if '[' not in d else d.split('[')[0]
	4008	+ if(d in sv.devprops):
	4009	+ name = sv.devprops[d].altName(d)
	4010	+ if 'drv' in dev and dev['drv']:
	4011	+ name += ' {%s}' % dev['drv']
3481	4012	if sv.suspendmode in suspendmodename:
3482	4013	name += ' '+p
3483	4014	if('ftrace' in dev):
3484	4015	cg = dev['ftrace']
	4016	+ if cg.name == sv.ftopfunc:
	4017	+ name = 'top level suspend/resume call'
3485	4018	num = callgraphHTML(sv, hf, num, cg,
3486	4019	name, color, dev['id'])
3487	4020	if('ftraces' in dev):
..	..	@@ -3490,22 +4023,16 @@
3490	4023	name+' → '+cg.name, color, dev['id'])
3491	4024	hf.write('\n\n </section>\n')
3492	4025
3493		-# Function: createHTMLSummarySimple
3494		-# Description:
3495		-# Create summary html file for a series of tests
3496		-# Arguments:
3497		-# testruns: array of Data objects from parseTraceLog
3498		-def createHTMLSummarySimple(testruns, htmlfile, folder):
3499		- # write the html header first (html head, css code, up to body start)
3500		- html = '<!DOCTYPE html>\n<html>\n<head>\n\
	4026	+def summaryCSS(title, center=True):
	4027	+ tdcenter = 'text-align:center;' if center else ''
	4028	+ out = '<!DOCTYPE html>\n<html>\n<head>\n\
3501	4029	<meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3502		- <title>SleepGraph Summary</title>\n\
	4030	+ <title>'+title+'</title>\n\
3503	4031	<style type=\'text/css\'>\n\
3504	4032	.stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\
3505		- table {width:100%;border-collapse: collapse;}\n\
3506		- .summary {border:1px solid;}\n\
	4033	+ table {width:100%;border-collapse: collapse;border:1px solid;}\n\
3507	4034	th {border: 1px solid black;background:#222;color:white;}\n\
3508		- td {font: 16px "Times New Roman";text-align: center;}\n\
	4035	+ td {font: 14px "Times New Roman";'+tdcenter+'}\n\
3509	4036	tr.head td {border: 1px solid black;background:#aaa;}\n\
3510	4037	tr.alt {background-color:#ddd;}\n\
3511	4038	tr.notice {color:red;}\n\
..	..	@@ -3514,14 +4041,25 @@
3514	4041	.maxval {background-color:#FFBBBB;}\n\
3515	4042	.head a {color:#000;text-decoration: none;}\n\
3516	4043	</style>\n</head>\n<body>\n'
	4044	+ return out
	4045	+
	4046	+# Function: createHTMLSummarySimple
	4047	+# Description:
	4048	+# Create summary html file for a series of tests
	4049	+# Arguments:
	4050	+# testruns: array of Data objects from parseTraceLog
	4051	+def createHTMLSummarySimple(testruns, htmlfile, title):
	4052	+ # write the html header first (html head, css code, up to body start)
	4053	+ html = summaryCSS('Summary - SleepGraph')
3517	4054
3518	4055	# extract the test data into list
3519	4056	list = dict()
3520		- tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
	4057	+ tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()]
3521	4058	iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3522	4059	num = 0
	4060	+ useturbo = usewifi = False
3523	4061	lastmode = ''
3524		- cnt = {'pass':0, 'fail':0, 'hang':0}
	4062	+ cnt = dict()
3525	4063	for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
3526	4064	mode = data['mode']
3527	4065	if mode not in list:
..	..	@@ -3529,24 +4067,36 @@
3529	4067	if lastmode and lastmode != mode and num > 0:
3530	4068	for i in range(2):
3531	4069	s = sorted(tMed[i])
3532		- list[lastmode]['med'][i] = s[int(len(s)/2)]
3533		- iMed[i] = tMed[i].index(list[lastmode]['med'][i])
	4070	+ list[lastmode]['med'][i] = s[int(len(s)//2)]
	4071	+ iMed[i] = tMed[i][list[lastmode]['med'][i]]
3534	4072	list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
3535	4073	list[lastmode]['min'] = tMin
3536	4074	list[lastmode]['max'] = tMax
3537	4075	list[lastmode]['idx'] = (iMin, iMed, iMax)
3538		- tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
	4076	+ tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()]
3539	4077	iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3540	4078	num = 0
	4079	+ pkgpc10 = syslpi = wifi = ''
	4080	+ if 'pkgpc10' in data and 'syslpi' in data:
	4081	+ pkgpc10, syslpi, useturbo = data['pkgpc10'], data['syslpi'], True
	4082	+ if 'wifi' in data:
	4083	+ wifi, usewifi = data['wifi'], True
	4084	+ res = data['result']
3541	4085	tVal = [float(data['suspend']), float(data['resume'])]
3542	4086	list[mode]['data'].append([data['host'], data['kernel'],
3543		- data['time'], tVal[0], tVal[1], data['url'], data['result'],
3544		- data['issues']])
	4087	+ data['time'], tVal[0], tVal[1], data['url'], res,
	4088	+ data['issues'], data['sus_worst'], data['sus_worsttime'],
	4089	+ data['res_worst'], data['res_worsttime'], pkgpc10, syslpi, wifi])
3545	4090	idx = len(list[mode]['data']) - 1
3546		- if data['result'] == 'pass':
3547		- cnt['pass'] += 1
	4091	+ if res.startswith('fail in'):
	4092	+ res = 'fail'
	4093	+ if res not in cnt:
	4094	+ cnt[res] = 1
	4095	+ else:
	4096	+ cnt[res] += 1
	4097	+ if res == 'pass':
3548	4098	for i in range(2):
3549		- tMed[i].append(tVal[i])
	4099	+ tMed[i][tVal[i]] = idx
3550	4100	tAvg[i] += tVal[i]
3551	4101	if tMin[i] == 0 or tVal[i] < tMin[i]:
3552	4102	iMin[i] = idx
..	..	@@ -3555,16 +4105,12 @@
3555	4105	iMax[i] = idx
3556	4106	tMax[i] = tVal[i]
3557	4107	num += 1
3558		- elif data['result'] == 'hang':
3559		- cnt['hang'] += 1
3560		- elif data['result'] == 'fail':
3561		- cnt['fail'] += 1
3562	4108	lastmode = mode
3563	4109	if lastmode and num > 0:
3564	4110	for i in range(2):
3565	4111	s = sorted(tMed[i])
3566		- list[lastmode]['med'][i] = s[int(len(s)/2)]
3567		- iMed[i] = tMed[i].index(list[lastmode]['med'][i])
	4112	+ list[lastmode]['med'][i] = s[int(len(s)//2)]
	4113	+ iMed[i] = tMed[i][list[lastmode]['med'][i]]
3568	4114	list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
3569	4115	list[lastmode]['min'] = tMin
3570	4116	list[lastmode]['max'] = tMax
..	..	@@ -3575,21 +4121,33 @@
3575	4121	for ilk in sorted(cnt, reverse=True):
3576	4122	if cnt[ilk] > 0:
3577	4123	desc.append('%d %s' % (cnt[ilk], ilk))
3578		- html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (folder, len(testruns), ', '.join(desc))
	4124	+ html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (title, len(testruns), ', '.join(desc))
3579	4125	th = '\t<th>{0}</th>\n'
3580	4126	td = '\t<td>{0}</td>\n'
3581	4127	tdh = '\t<td{1}>{0}</td>\n'
3582	4128	tdlink = '\t<td><a href="{0}">html</a></td>\n'
	4129	+ cols = 12
	4130	+ if useturbo:
	4131	+ cols += 2
	4132	+ if usewifi:
	4133	+ cols += 1
	4134	+ colspan = '%d' % cols
3583	4135
3584	4136	# table header
3585		- html += '<table class="summary">\n<tr>\n' + th.format('#') +\
	4137	+ html += '<table>\n<tr>\n' + th.format('#') +\
3586	4138	th.format('Mode') + th.format('Host') + th.format('Kernel') +\
3587	4139	th.format('Test Time') + th.format('Result') + th.format('Issues') +\
3588		- th.format('Suspend') + th.format('Resume') + th.format('Detail') + '</tr>\n'
3589		-
	4140	+ th.format('Suspend') + th.format('Resume') +\
	4141	+ th.format('Worst Suspend Device') + th.format('SD Time') +\
	4142	+ th.format('Worst Resume Device') + th.format('RD Time')
	4143	+ if useturbo:
	4144	+ html += th.format('PkgPC10') + th.format('SysLPI')
	4145	+ if usewifi:
	4146	+ html += th.format('Wifi')
	4147	+ html += th.format('Detail')+'</tr>\n'
3590	4148	# export list into html
3591	4149	head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\
3592		- '<td colspan=8 class="sus">Suspend Avg={2} '+\
	4150	+ '<td colspan='+colspan+' class="sus">Suspend Avg={2} '+\
3593	4151	'<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\
3594	4152	'<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\
3595	4153	'<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\
..	..	@@ -3598,8 +4156,9 @@
3598	4156	'<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\
3599	4157	'<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\
3600	4158	'</tr>\n'
3601		- headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=8></td></tr>\n'
3602		- for mode in list:
	4159	+ headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan='+\
	4160	+ colspan+'></td></tr>\n'
	4161	+ for mode in sorted(list):
3603	4162	# header line for each suspend mode
3604	4163	num = 0
3605	4164	tAvg, tMin, tMax, tMed = list[mode]['avg'], list[mode]['min'],\
..	..	@@ -3641,6 +4200,15 @@
3641	4200	html += td.format(d[7]) # issues
3642	4201	html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend
3643	4202	html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume
	4203	+ html += td.format(d[8]) # sus_worst
	4204	+ html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time
	4205	+ html += td.format(d[10]) # res_worst
	4206	+ html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time
	4207	+ if useturbo:
	4208	+ html += td.format(d[12]) # pkg_pc10
	4209	+ html += td.format(d[13]) # syslpi
	4210	+ if usewifi:
	4211	+ html += td.format(d[14]) # wifi
3644	4212	html += tdlink.format(d[5]) if d[5] else td.format('') # url
3645	4213	html += '</tr>\n'
3646	4214	num += 1
..	..	@@ -3649,6 +4217,116 @@
3649	4217	hf = open(htmlfile, 'w')
3650	4218	hf.write(html+'</table>\n</body>\n</html>\n')
3651	4219	hf.close()
	4220	+
	4221	+def createHTMLDeviceSummary(testruns, htmlfile, title):
	4222	+ html = summaryCSS('Device Summary - SleepGraph', False)
	4223	+
	4224	+ # create global device list from all tests
	4225	+ devall = dict()
	4226	+ for data in testruns:
	4227	+ host, url, devlist = data['host'], data['url'], data['devlist']
	4228	+ for type in devlist:
	4229	+ if type not in devall:
	4230	+ devall[type] = dict()
	4231	+ mdevlist, devlist = devall[type], data['devlist'][type]
	4232	+ for name in devlist:
	4233	+ length = devlist[name]
	4234	+ if name not in mdevlist:
	4235	+ mdevlist[name] = {'name': name, 'host': host,
	4236	+ 'worst': length, 'total': length, 'count': 1,
	4237	+ 'url': url}
	4238	+ else:
	4239	+ if length > mdevlist[name]['worst']:
	4240	+ mdevlist[name]['worst'] = length
	4241	+ mdevlist[name]['url'] = url
	4242	+ mdevlist[name]['host'] = host
	4243	+ mdevlist[name]['total'] += length
	4244	+ mdevlist[name]['count'] += 1
	4245	+
	4246	+ # generate the html
	4247	+ th = '\t<th>{0}</th>\n'
	4248	+ td = '\t<td align=center>{0}</td>\n'
	4249	+ tdr = '\t<td align=right>{0}</td>\n'
	4250	+ tdlink = '\t<td align=center><a href="{0}">html</a></td>\n'
	4251	+ limit = 1
	4252	+ for type in sorted(devall, reverse=True):
	4253	+ num = 0
	4254	+ devlist = devall[type]
	4255	+ # table header
	4256	+ html += '<div class="stamp">%s (%s devices > %d ms)</div><table>\n' % \
	4257	+ (title, type.upper(), limit)
	4258	+ html += '<tr>\n' + '<th align=right>Device Name</th>' +\
	4259	+ th.format('Average Time') + th.format('Count') +\
	4260	+ th.format('Worst Time') + th.format('Host (worst time)') +\
	4261	+ th.format('Link (worst time)') + '</tr>\n'
	4262	+ for name in sorted(devlist, key=lambda k:(devlist[k]['worst'], \
	4263	+ devlist[k]['total'], devlist[k]['name']), reverse=True):
	4264	+ data = devall[type][name]
	4265	+ data['average'] = data['total'] / data['count']
	4266	+ if data['average'] < limit:
	4267	+ continue
	4268	+ # row classes - alternate row color
	4269	+ rcls = ['alt'] if num % 2 == 1 else []
	4270	+ html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
	4271	+ html += tdr.format(data['name']) # name
	4272	+ html += td.format('%.3f ms' % data['average']) # average
	4273	+ html += td.format(data['count']) # count
	4274	+ html += td.format('%.3f ms' % data['worst']) # worst
	4275	+ html += td.format(data['host']) # host
	4276	+ html += tdlink.format(data['url']) # url
	4277	+ html += '</tr>\n'
	4278	+ num += 1
	4279	+ html += '</table>\n'
	4280	+
	4281	+ # flush the data to file
	4282	+ hf = open(htmlfile, 'w')
	4283	+ hf.write(html+'</body>\n</html>\n')
	4284	+ hf.close()
	4285	+ return devall
	4286	+
	4287	+def createHTMLIssuesSummary(testruns, issues, htmlfile, title, extra=''):
	4288	+ multihost = len([e for e in issues if len(e['urls']) > 1]) > 0
	4289	+ html = summaryCSS('Issues Summary - SleepGraph', False)
	4290	+ total = len(testruns)
	4291	+
	4292	+ # generate the html
	4293	+ th = '\t<th>{0}</th>\n'
	4294	+ td = '\t<td align={0}>{1}</td>\n'
	4295	+ tdlink = '<a href="{1}">{0}</a>'
	4296	+ subtitle = '%d issues' % len(issues) if len(issues) > 0 else 'no issues'
	4297	+ html += '<div class="stamp">%s (%s)</div><table>\n' % (title, subtitle)
	4298	+ html += '<tr>\n' + th.format('Issue') + th.format('Count')
	4299	+ if multihost:
	4300	+ html += th.format('Hosts')
	4301	+ html += th.format('Tests') + th.format('Fail Rate') +\
	4302	+ th.format('First Instance') + '</tr>\n'
	4303	+
	4304	+ num = 0
	4305	+ for e in sorted(issues, key=lambda v:v['count'], reverse=True):
	4306	+ testtotal = 0
	4307	+ links = []
	4308	+ for host in sorted(e['urls']):
	4309	+ links.append(tdlink.format(host, e['urls'][host][0]))
	4310	+ testtotal += len(e['urls'][host])
	4311	+ rate = '%d/%d (%.2f%%)' % (testtotal, total, 100*float(testtotal)/float(total))
	4312	+ # row classes - alternate row color
	4313	+ rcls = ['alt'] if num % 2 == 1 else []
	4314	+ html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
	4315	+ html += td.format('left', e['line']) # issue
	4316	+ html += td.format('center', e['count']) # count
	4317	+ if multihost:
	4318	+ html += td.format('center', len(e['urls'])) # hosts
	4319	+ html += td.format('center', testtotal) # test count
	4320	+ html += td.format('center', rate) # test rate
	4321	+ html += td.format('center nowrap', '<br>'.join(links)) # links
	4322	+ html += '</tr>\n'
	4323	+ num += 1
	4324	+
	4325	+ # flush the data to file
	4326	+ hf = open(htmlfile, 'w')
	4327	+ hf.write(html+'</table>\n'+extra+'</body>\n</html>\n')
	4328	+ hf.close()
	4329	+ return issues
3652	4330
3653	4331	def ordinal(value):
3654	4332	suffix = 'th'
..	..	@@ -3670,14 +4348,17 @@
3670	4348	# True if the html file was created, false if it failed
3671	4349	def createHTML(testruns, testfail):
3672	4350	if len(testruns) < 1:
3673		- print('ERROR: Not enough test data to build a timeline')
	4351	+ pprint('ERROR: Not enough test data to build a timeline')
3674	4352	return
3675	4353
3676	4354	kerror = False
3677	4355	for data in testruns:
3678	4356	if data.kerror:
3679	4357	kerror = True
3680		- data.normalizeTime(testruns[-1].tSuspended)
	4358	+ if(sysvals.suspendmode in ['freeze', 'standby']):
	4359	+ data.trimFreezeTime(testruns[-1].tSuspended)
	4360	+ else:
	4361	+ data.getMemTime()
3681	4362
3682	4363	# html function templates
3683	4364	html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</div>\n'
..	..	@@ -3696,13 +4377,10 @@
3696	4377	'<td class="green">Execution Time: <b>{0} ms</b></td>'\
3697	4378	'<td class="yellow">Command: <b>{1}</b></td>'\
3698	4379	'</tr>\n</table>\n'
3699		- html_timegroups = '<table class="time2">\n<tr>'\
3700		- '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\
3701		- '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3702		- '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
3703		- '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\
3704		- '</tr>\n</table>\n'
3705	4380	html_fail = '<table class="testfail"><tr><td>{0}</td></tr></table>\n'
	4381	+ html_kdesc = '<td class="{3}" title="time spent in kernel execution">{0}Kernel {2}: {1} ms</td>'
	4382	+ html_fwdesc = '<td class="{3}" title="time spent in firmware">{0}Firmware {2}: {1} ms</td>'
	4383	+ html_wifdesc = '<td class="yellow" title="time for wifi to reconnect after resume complete ({2})">{0}Wifi Resume: {1}</td>'
3706	4384
3707	4385	# html format variables
3708	4386	scaleH = 20
..	..	@@ -3718,13 +4396,10 @@
3718	4396	# Generate the header for this timeline
3719	4397	for data in testruns:
3720	4398	tTotal = data.end - data.start
3721		- sktime, rktime = data.getTimeValues()
3722	4399	if(tTotal == 0):
3723	4400	doError('No timeline data')
3724		- if(data.tLow > 0):
3725		- low_time = '%.0f'%(data.tLow*1000)
3726	4401	if sysvals.suspendmode == 'command':
3727		- run_time = '%.0f'%((data.end-data.start)*1000)
	4402	+ run_time = '%.0f' % (tTotal * 1000)
3728	4403	if sysvals.testcommand:
3729	4404	testdesc = sysvals.testcommand
3730	4405	else:
..	..	@@ -3733,43 +4408,55 @@
3733	4408	testdesc = ordinal(data.testnumber+1)+' '+testdesc
3734	4409	thtml = html_timetotal3.format(run_time, testdesc)
3735	4410	devtl.html += thtml
3736		- elif data.fwValid:
3737		- suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3738		- resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
3739		- testdesc1 = 'Total'
3740		- testdesc2 = ''
3741		- stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode
3742		- rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode
3743		- if(len(testruns) > 1):
3744		- testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3745		- testdesc2 += ' '
3746		- if(data.tLow == 0):
3747		- thtml = html_timetotal.format(suspend_time, \
3748		- resume_time, testdesc1, stitle, rtitle)
3749		- else:
3750		- thtml = html_timetotal2.format(suspend_time, low_time, \
3751		- resume_time, testdesc1, stitle, rtitle)
3752		- devtl.html += thtml
	4411	+ continue
	4412	+ # typical full suspend/resume header
	4413	+ stot, rtot = sktime, rktime = data.getTimeValues()
	4414	+ ssrc, rsrc, testdesc, testdesc2 = ['kernel'], ['kernel'], 'Kernel', ''
	4415	+ if data.fwValid:
	4416	+ stot += (data.fwSuspend/1000000.0)
	4417	+ rtot += (data.fwResume/1000000.0)
	4418	+ ssrc.append('firmware')
	4419	+ rsrc.append('firmware')
	4420	+ testdesc = 'Total'
	4421	+ if 'time' in data.wifi and data.wifi['stat'] != 'timeout':
	4422	+ rtot += data.end - data.tKernRes + (data.wifi['time'] * 1000.0)
	4423	+ rsrc.append('wifi')
	4424	+ testdesc = 'Total'
	4425	+ suspend_time, resume_time = '%.3f' % stot, '%.3f' % rtot
	4426	+ stitle = 'time from kernel suspend start to %s mode [%s time]' % \
	4427	+ (sysvals.suspendmode, ' & '.join(ssrc))
	4428	+ rtitle = 'time from %s mode to kernel resume complete [%s time]' % \
	4429	+ (sysvals.suspendmode, ' & '.join(rsrc))
	4430	+ if(len(testruns) > 1):
	4431	+ testdesc = testdesc2 = ordinal(data.testnumber+1)
	4432	+ testdesc2 += ' '
	4433	+ if(len(data.tLow) == 0):
	4434	+ thtml = html_timetotal.format(suspend_time, \
	4435	+ resume_time, testdesc, stitle, rtitle)
	4436	+ else:
	4437	+ low_time = '+'.join(data.tLow)
	4438	+ thtml = html_timetotal2.format(suspend_time, low_time, \
	4439	+ resume_time, testdesc, stitle, rtitle)
	4440	+ devtl.html += thtml
	4441	+ if not data.fwValid and 'dev' not in data.wifi:
	4442	+ continue
	4443	+ # extra detail when the times come from multiple sources
	4444	+ thtml = '<table class="time2">\n<tr>'
	4445	+ thtml += html_kdesc.format(testdesc2, '%.3f'%sktime, 'Suspend', 'green')
	4446	+ if data.fwValid:
3753	4447	sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3754	4448	rftime = '%.3f'%(data.fwResume / 1000000.0)
3755		- devtl.html += html_timegroups.format('%.3f'%sktime, \
3756		- sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode)
3757		- else:
3758		- suspend_time = '%.3f' % sktime
3759		- resume_time = '%.3f' % rktime
3760		- testdesc = 'Kernel'
3761		- stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode
3762		- rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode
3763		- if(len(testruns) > 1):
3764		- testdesc = ordinal(data.testnumber+1)+' '+testdesc
3765		- if(data.tLow == 0):
3766		- thtml = html_timetotal.format(suspend_time, \
3767		- resume_time, testdesc, stitle, rtitle)
	4449	+ thtml += html_fwdesc.format(testdesc2, sftime, 'Suspend', 'green')
	4450	+ thtml += html_fwdesc.format(testdesc2, rftime, 'Resume', 'yellow')
	4451	+ thtml += html_kdesc.format(testdesc2, '%.3f'%rktime, 'Resume', 'yellow')
	4452	+ if 'time' in data.wifi:
	4453	+ if data.wifi['stat'] != 'timeout':
	4454	+ wtime = '%.0f ms'%(data.end - data.tKernRes + (data.wifi['time'] * 1000.0))
3768	4455	else:
3769		- thtml = html_timetotal2.format(suspend_time, low_time, \
3770		- resume_time, testdesc, stitle, rtitle)
3771		- devtl.html += thtml
3772		-
	4456	+ wtime = 'TIMEOUT'
	4457	+ thtml += html_wifdesc.format(testdesc2, wtime, data.wifi['dev'])
	4458	+ thtml += '</tr>\n</table>\n'
	4459	+ devtl.html += thtml
3773	4460	if testfail:
3774	4461	devtl.html += html_fail.format(testfail)
3775	4462
..	..	@@ -3788,7 +4475,7 @@
3788	4475	for group in data.devicegroups:
3789	4476	devlist = []
3790	4477	for phase in group:
3791		- for devname in data.tdevlist[phase]:
	4478	+ for devname in sorted(data.tdevlist[phase]):
3792	4479	d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3793	4480	devlist.append(d)
3794	4481	if d.isa('kth'):
..	..	@@ -3820,15 +4507,14 @@
3820	4507
3821	4508	# draw the full timeline
3822	4509	devtl.createZoomBox(sysvals.suspendmode, len(testruns))
3823		- phases = {'suspend':[],'resume':[]}
3824		- for phase in data.dmesg:
3825		- if 'resume' in phase:
3826		- phases['resume'].append(phase)
3827		- else:
3828		- phases['suspend'].append(phase)
3829		-
3830		- # draw each test run chronologically
3831	4510	for data in testruns:
	4511	+ # draw each test run and block chronologically
	4512	+ phases = {'suspend':[],'resume':[]}
	4513	+ for phase in data.sortedPhases():
	4514	+ if data.dmesg[phase]['start'] >= data.tSuspended:
	4515	+ phases['resume'].append(phase)
	4516	+ else:
	4517	+ phases['suspend'].append(phase)
3832	4518	# now draw the actual timeline blocks
3833	4519	for dir in phases:
3834	4520	# draw suspend and resume blocks separately
..	..	@@ -3850,7 +4536,7 @@
3850	4536	continue
3851	4537	width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3852	4538	devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)
3853		- for b in sorted(phases[dir]):
	4539	+ for b in phases[dir]:
3854	4540	# draw the phase color background
3855	4541	phase = data.dmesg[b]
3856	4542	length = phase['end']-phase['start']
..	..	@@ -3865,16 +4551,13 @@
3865	4551	id = '%d_%d' % (idx1, idx2)
3866	4552	right = '%f' % (((mMax-t)*100.0)/mTotal)
3867	4553	devtl.html += html_error.format(right, id, type)
3868		- for b in sorted(phases[dir]):
	4554	+ for b in phases[dir]:
3869	4555	# draw the devices for this phase
3870	4556	phaselist = data.dmesg[b]['list']
3871		- for d in data.tdevlist[b]:
3872		- name = d
3873		- drv = ''
3874		- dev = phaselist[d]
3875		- xtraclass = ''
3876		- xtrainfo = ''
3877		- xtrastyle = ''
	4557	+ for d in sorted(data.tdevlist[b]):
	4558	+ dname = d if '[' not in d else d.split('[')[0]
	4559	+ name, dev = dname, phaselist[d]
	4560	+ drv = xtraclass = xtrainfo = xtrastyle = ''
3878	4561	if 'htmlclass' in dev:
3879	4562	xtraclass = dev['htmlclass']
3880	4563	if 'color' in dev:
..	..	@@ -3905,7 +4588,7 @@
3905	4588	title += b
3906	4589	devtl.html += devtl.html_device.format(dev['id'], \
3907	4590	title, left, top, '%.3f'%rowheight, width, \
3908		- d+drv, xtraclass, xtrastyle)
	4591	+ dname+drv, xtraclass, xtrastyle)
3909	4592	if('cpuexec' in dev):
3910	4593	for t in sorted(dev['cpuexec']):
3911	4594	start, end = t
..	..	@@ -3923,6 +4606,8 @@
3923	4606	continue
3924	4607	# draw any trace events for this device
3925	4608	for e in dev['src']:
	4609	+ if e.length == 0:
	4610	+ continue
3926	4611	height = '%.3f' % devtl.rowH
3927	4612	top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
3928	4613	left = '%f' % (((e.time-m0)*100)/mTotal)
..	..	@@ -3942,19 +4627,17 @@
3942	4627
3943	4628	# draw a legend which describes the phases by color
3944	4629	if sysvals.suspendmode != 'command':
3945		- data = testruns[-1]
	4630	+ phasedef = testruns[-1].phasedef
3946	4631	devtl.html += '<div class="legend">\n'
3947		- pdelta = 100.0/len(data.phases)
	4632	+ pdelta = 100.0/len(phasedef.keys())
3948	4633	pmargin = pdelta / 4.0
3949		- for phase in data.phases:
3950		- tmp = phase.split('_')
3951		- id = tmp[0][0]
3952		- if(len(tmp) > 1):
3953		- id += tmp[1][0]
3954		- order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3955		- name = string.replace(phase, '_', '  ')
3956		- devtl.html += devtl.html_legend.format(order, \
3957		- data.dmesg[phase]['color'], name, id)
	4634	+ for phase in sorted(phasedef, key=lambda k:phasedef[k]['order']):
	4635	+ id, p = '', phasedef[phase]
	4636	+ for word in phase.split('_'):
	4637	+ id += word[0]
	4638	+ order = '%.2f' % ((p['order'] * pdelta) + pmargin)
	4639	+ name = phase.replace('_', '  ')
	4640	+ devtl.html += devtl.html_legend.format(order, p['color'], name, id)
3958	4641	devtl.html += '</div>\n'
3959	4642
3960	4643	hf = open(sysvals.htmlfile, 'w')
..	..	@@ -3970,7 +4653,7 @@
3970	4653	pscolor = 'linear-gradient(to top left, #ccc, #eee)'
3971	4654	hf.write(devtl.html_phaselet.format('pre_suspend_process', \
3972	4655	'0', '0', pscolor))
3973		- for b in data.phases:
	4656	+ for b in data.sortedPhases():
3974	4657	phase = data.dmesg[b]
3975	4658	length = phase['end']-phase['start']
3976	4659	left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
..	..	@@ -4522,48 +5205,49 @@
4522	5205	sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled'
4523	5206	else:
4524	5207	sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled'
4525		- print('CONFIGURING RUNTIME SUSPEND...')
	5208	+ pprint('CONFIGURING RUNTIME SUSPEND...')
4526	5209	sv.rslist = deviceInfo(sv.rstgt)
4527	5210	for i in sv.rslist:
4528	5211	sv.setVal(sv.rsval, i)
4529		- print('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist)))
4530		- print('waiting 5 seconds...')
	5212	+ pprint('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist)))
	5213	+ pprint('waiting 5 seconds...')
4531	5214	time.sleep(5)
4532	5215	else:
4533	5216	# runtime suspend re-enable or re-disable
4534	5217	for i in sv.rslist:
4535	5218	sv.setVal(sv.rstgt, i)
4536		- print('runtime suspend settings restored on %d devices' % len(sv.rslist))
	5219	+ pprint('runtime suspend settings restored on %d devices' % len(sv.rslist))
4537	5220
4538	5221	# Function: executeSuspend
4539	5222	# Description:
4540	5223	# Execute system suspend through the sysfs interface, then copy the output
4541	5224	# dmesg and ftrace files to the test output directory.
4542		-def executeSuspend():
	5225	+def executeSuspend(quiet=False):
4543	5226	pm = ProcessMonitor()
4544	5227	tp = sysvals.tpath
4545		- fwdata = []
	5228	+ if sysvals.wifi:
	5229	+ wifi = sysvals.checkWifi()
	5230	+ testdata = []
4546	5231	# run these commands to prepare the system for suspend
4547	5232	if sysvals.display:
4548		- if sysvals.display > 0:
4549		- print('TURN DISPLAY ON')
4550		- call('xset -d :0.0 dpms force suspend', shell=True)
4551		- call('xset -d :0.0 dpms force on', shell=True)
4552		- else:
4553		- print('TURN DISPLAY OFF')
4554		- call('xset -d :0.0 dpms force suspend', shell=True)
	5233	+ if not quiet:
	5234	+ pprint('SET DISPLAY TO %s' % sysvals.display.upper())
	5235	+ displayControl(sysvals.display)
4555	5236	time.sleep(1)
4556	5237	if sysvals.sync:
4557		- print('SYNCING FILESYSTEMS')
	5238	+ if not quiet:
	5239	+ pprint('SYNCING FILESYSTEMS')
4558	5240	call('sync', shell=True)
4559	5241	# mark the start point in the kernel ring buffer just as we start
4560	5242	sysvals.initdmesg()
4561	5243	# start ftrace
4562	5244	if(sysvals.usecallgraph or sysvals.usetraceevents):
4563		- print('START TRACING')
	5245	+ if not quiet:
	5246	+ pprint('START TRACING')
4564	5247	sysvals.fsetVal('1', 'tracing_on')
4565	5248	if sysvals.useprocmon:
4566	5249	pm.start()
	5250	+ sysvals.cmdinfo(True)
4567	5251	# execute however many s/r runs requested
4568	5252	for count in range(1,sysvals.execcount+1):
4569	5253	# x2delay in between test runs
..	..	@@ -4573,27 +5257,31 @@
4573	5257	sysvals.fsetVal('WAIT END', 'trace_marker')
4574	5258	# start message
4575	5259	if sysvals.testcommand != '':
4576		- print('COMMAND START')
	5260	+ pprint('COMMAND START')
4577	5261	else:
4578	5262	if(sysvals.rtcwake):
4579		- print('SUSPEND START')
	5263	+ pprint('SUSPEND START')
4580	5264	else:
4581		- print('SUSPEND START (press a key to resume)')
	5265	+ pprint('SUSPEND START (press a key to resume)')
4582	5266	# set rtcwake
4583	5267	if(sysvals.rtcwake):
4584		- print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
	5268	+ if not quiet:
	5269	+ pprint('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
4585	5270	sysvals.rtcWakeAlarmOn()
4586	5271	# start of suspend trace marker
4587	5272	if(sysvals.usecallgraph or sysvals.usetraceevents):
4588		- sysvals.fsetVal('SUSPEND START', 'trace_marker')
	5273	+ sysvals.fsetVal(datetime.now().strftime(sysvals.tmstart), 'trace_marker')
4589	5274	# predelay delay
4590	5275	if(count == 1 and sysvals.predelay > 0):
4591	5276	sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
4592	5277	time.sleep(sysvals.predelay/1000.0)
4593	5278	sysvals.fsetVal('WAIT END', 'trace_marker')
4594	5279	# initiate suspend or command
	5280	+ tdata = {'error': ''}
4595	5281	if sysvals.testcommand != '':
4596		- call(sysvals.testcommand+' 2>&1', shell=True);
	5282	+ res = call(sysvals.testcommand+' 2>&1', shell=True);
	5283	+ if res != 0:
	5284	+ tdata['error'] = 'cmd returned %d' % res
4597	5285	else:
4598	5286	mode = sysvals.suspendmode
4599	5287	if sysvals.memmode and os.path.exists(sysvals.mempowerfile):
..	..	@@ -4601,13 +5289,24 @@
4601	5289	pf = open(sysvals.mempowerfile, 'w')
4602	5290	pf.write(sysvals.memmode)
4603	5291	pf.close()
4604		- pf = open(sysvals.powerfile, 'w')
4605		- pf.write(mode)
4606		- # execution will pause here
4607		- try:
	5292	+ if sysvals.diskmode and os.path.exists(sysvals.diskpowerfile):
	5293	+ mode = 'disk'
	5294	+ pf = open(sysvals.diskpowerfile, 'w')
	5295	+ pf.write(sysvals.diskmode)
4608	5296	pf.close()
4609		- except:
4610		- pass
	5297	+ if mode == 'freeze' and sysvals.haveTurbostat():
	5298	+ # execution will pause here
	5299	+ turbo = sysvals.turbostat()
	5300	+ if turbo:
	5301	+ tdata['turbo'] = turbo
	5302	+ else:
	5303	+ pf = open(sysvals.powerfile, 'w')
	5304	+ pf.write(mode)
	5305	+ # execution will pause here
	5306	+ try:
	5307	+ pf.close()
	5308	+ except Exception as e:
	5309	+ tdata['error'] = str(e)
4611	5310	if(sysvals.rtcwake):
4612	5311	sysvals.rtcWakeAlarmOff()
4613	5312	# postdelay delay
..	..	@@ -4616,27 +5315,35 @@
4616	5315	time.sleep(sysvals.postdelay/1000.0)
4617	5316	sysvals.fsetVal('WAIT END', 'trace_marker')
4618	5317	# return from suspend
4619		- print('RESUME COMPLETE')
	5318	+ pprint('RESUME COMPLETE')
4620	5319	if(sysvals.usecallgraph or sysvals.usetraceevents):
4621		- sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
	5320	+ sysvals.fsetVal(datetime.now().strftime(sysvals.tmend), 'trace_marker')
	5321	+ if sysvals.wifi and wifi:
	5322	+ tdata['wifi'] = sysvals.pollWifi(wifi)
4622	5323	if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4623		- fwdata.append(getFPDT(False))
	5324	+ tdata['fw'] = getFPDT(False)
	5325	+ testdata.append(tdata)
	5326	+ cmdafter = sysvals.cmdinfo(False)
4624	5327	# stop ftrace
4625	5328	if(sysvals.usecallgraph or sysvals.usetraceevents):
4626	5329	if sysvals.useprocmon:
4627	5330	pm.stop()
4628	5331	sysvals.fsetVal('0', 'tracing_on')
4629		- print('CAPTURING TRACE')
4630		- op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata)
	5332	+ # grab a copy of the dmesg output
	5333	+ if not quiet:
	5334	+ pprint('CAPTURING DMESG')
	5335	+ sysvals.getdmesg(testdata)
	5336	+ # grab a copy of the ftrace output
	5337	+ if(sysvals.usecallgraph or sysvals.usetraceevents):
	5338	+ if not quiet:
	5339	+ pprint('CAPTURING TRACE')
	5340	+ op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata)
4631	5341	fp = open(tp+'trace', 'r')
4632	5342	for line in fp:
4633	5343	op.write(line)
4634	5344	op.close()
4635	5345	sysvals.fsetVal('', 'trace')
4636		- devProps()
4637		- # grab a copy of the dmesg output
4638		- print('CAPTURING DMESG')
4639		- sysvals.getdmesg(fwdata)
	5346	+ sysvals.platforminfo(cmdafter)
4640	5347
4641	5348	def readFile(file):
4642	5349	if os.path.islink(file):
..	..	@@ -4651,9 +5358,9 @@
4651	5358	# The time string, e.g. "1901m16s"
4652	5359	def ms2nice(val):
4653	5360	val = int(val)
4654		- h = val / 3600000
4655		- m = (val / 60000) % 60
4656		- s = (val / 1000) % 60
	5361	+ h = val // 3600000
	5362	+ m = (val // 60000) % 60
	5363	+ s = (val // 1000) % 60
4657	5364	if h > 0:
4658	5365	return '%d:%02d:%02d' % (h, m, s)
4659	5366	if m > 0:
..	..	@@ -4673,15 +5380,15 @@
4673	5380	# a list of USB device names to sysvals for better timeline readability
4674	5381	def deviceInfo(output=''):
4675	5382	if not output:
4676		- print('LEGEND')
4677		- print('---------------------------------------------------------------------------------------------')
4678		- print(' A = async/sync PM queue (A/S) C = runtime active children')
4679		- print(' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)')
4680		- print(' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)')
4681		- print(' U = runtime usage count')
4682		- print('---------------------------------------------------------------------------------------------')
4683		- print('DEVICE NAME A R S U C rACTIVE rSUSPEND')
4684		- print('---------------------------------------------------------------------------------------------')
	5383	+ pprint('LEGEND\n'\
	5384	+ '---------------------------------------------------------------------------------------------\n'\
	5385	+ ' A = async/sync PM queue (A/S) C = runtime active children\n'\
	5386	+ ' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)\n'\
	5387	+ ' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)\n'\
	5388	+ ' U = runtime usage count\n'\
	5389	+ '---------------------------------------------------------------------------------------------\n'\
	5390	+ 'DEVICE NAME A R S U C rACTIVE rSUSPEND\n'\
	5391	+ '---------------------------------------------------------------------------------------------')
4685	5392
4686	5393	res = []
4687	5394	tgtval = 'runtime_status'
..	..	@@ -4723,129 +5430,8 @@
4723	5430	ms2nice(power['runtime_active_time']), \
4724	5431	ms2nice(power['runtime_suspended_time']))
4725	5432	for i in sorted(lines):
4726		- print lines[i]
	5433	+ print(lines[i])
4727	5434	return res
4728		-
4729		-# Function: devProps
4730		-# Description:
4731		-# Retrieve a list of properties for all devices in the trace log
4732		-def devProps(data=0):
4733		- props = dict()
4734		-
4735		- if data:
4736		- idx = data.index(': ') + 2
4737		- if idx >= len(data):
4738		- return
4739		- devlist = data[idx:].split(';')
4740		- for dev in devlist:
4741		- f = dev.split(',')
4742		- if len(f) < 3:
4743		- continue
4744		- dev = f[0]
4745		- props[dev] = DevProps()
4746		- props[dev].altname = f[1]
4747		- if int(f[2]):
4748		- props[dev].async = True
4749		- else:
4750		- props[dev].async = False
4751		- sysvals.devprops = props
4752		- if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4753		- sysvals.testcommand = props['testcommandstring'].altname
4754		- return
4755		-
4756		- if(os.path.exists(sysvals.ftracefile) == False):
4757		- doError('%s does not exist' % sysvals.ftracefile)
4758		-
4759		- # first get the list of devices we need properties for
4760		- msghead = 'Additional data added by AnalyzeSuspend'
4761		- alreadystamped = False
4762		- tp = TestProps()
4763		- tf = sysvals.openlog(sysvals.ftracefile, 'r')
4764		- for line in tf:
4765		- if msghead in line:
4766		- alreadystamped = True
4767		- continue
4768		- # determine the trace data type (required for further parsing)
4769		- m = re.match(sysvals.tracertypefmt, line)
4770		- if(m):
4771		- tp.setTracerType(m.group('t'))
4772		- continue
4773		- # parse only valid lines, if this is not one move on
4774		- m = re.match(tp.ftrace_line_fmt, line)
4775		- if(not m or 'device_pm_callback_start' not in line):
4776		- continue
4777		- m = re.match('.: (?P<drv>.) (?P<d>.), parent: (?P<p>.), .', m.group('msg'));
4778		- if(not m):
4779		- continue
4780		- dev = m.group('d')
4781		- if dev not in props:
4782		- props[dev] = DevProps()
4783		- tf.close()
4784		-
4785		- if not alreadystamped and sysvals.suspendmode == 'command':
4786		- out = '#\n# '+msghead+'\n# Device Properties: '
4787		- out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
4788		- with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
4789		- fp.write(out+'\n')
4790		- sysvals.devprops = props
4791		- return
4792		-
4793		- # now get the syspath for each of our target devices
4794		- for dirname, dirnames, filenames in os.walk('/sys/devices'):
4795		- if(re.match('.*/power', dirname) and 'async' in filenames):
4796		- dev = dirname.split('/')[-2]
4797		- if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
4798		- props[dev].syspath = dirname[:-6]
4799		-
4800		- # now fill in the properties for our target devices
4801		- for dev in props:
4802		- dirname = props[dev].syspath
4803		- if not dirname or not os.path.exists(dirname):
4804		- continue
4805		- with open(dirname+'/power/async') as fp:
4806		- text = fp.read()
4807		- props[dev].async = False
4808		- if 'enabled' in text:
4809		- props[dev].async = True
4810		- fields = os.listdir(dirname)
4811		- if 'product' in fields:
4812		- with open(dirname+'/product') as fp:
4813		- props[dev].altname = fp.read()
4814		- elif 'name' in fields:
4815		- with open(dirname+'/name') as fp:
4816		- props[dev].altname = fp.read()
4817		- elif 'model' in fields:
4818		- with open(dirname+'/model') as fp:
4819		- props[dev].altname = fp.read()
4820		- elif 'description' in fields:
4821		- with open(dirname+'/description') as fp:
4822		- props[dev].altname = fp.read()
4823		- elif 'id' in fields:
4824		- with open(dirname+'/id') as fp:
4825		- props[dev].altname = fp.read()
4826		- elif 'idVendor' in fields and 'idProduct' in fields:
4827		- idv, idp = '', ''
4828		- with open(dirname+'/idVendor') as fp:
4829		- idv = fp.read().strip()
4830		- with open(dirname+'/idProduct') as fp:
4831		- idp = fp.read().strip()
4832		- props[dev].altname = '%s:%s' % (idv, idp)
4833		-
4834		- if props[dev].altname:
4835		- out = props[dev].altname.strip().replace('\n', ' ')
4836		- out = out.replace(',', ' ')
4837		- out = out.replace(';', ' ')
4838		- props[dev].altname = out
4839		-
4840		- # and now write the data to the ftrace file
4841		- if not alreadystamped:
4842		- out = '#\n# '+msghead+'\n# Device Properties: '
4843		- for dev in sorted(props):
4844		- out += props[dev].out(dev)
4845		- with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
4846		- fp.write(out+'\n')
4847		-
4848		- sysvals.devprops = props
4849	5435
4850	5436	# Function: getModes
4851	5437	# Description:
..	..	@@ -4856,12 +5442,12 @@
4856	5442	modes = []
4857	5443	if(os.path.exists(sysvals.powerfile)):
4858	5444	fp = open(sysvals.powerfile, 'r')
4859		- modes = string.split(fp.read())
	5445	+ modes = fp.read().split()
4860	5446	fp.close()
4861	5447	if(os.path.exists(sysvals.mempowerfile)):
4862	5448	deep = False
4863	5449	fp = open(sysvals.mempowerfile, 'r')
4864		- for m in string.split(fp.read()):
	5450	+ for m in fp.read().split():
4865	5451	memmode = m.strip('[]')
4866	5452	if memmode == 'deep':
4867	5453	deep = True
..	..	@@ -4870,6 +5456,11 @@
4870	5456	fp.close()
4871	5457	if 'mem' in modes and not deep:
4872	5458	modes.remove('mem')
	5459	+ if('disk' in modes and os.path.exists(sysvals.diskpowerfile)):
	5460	+ fp = open(sysvals.diskpowerfile, 'r')
	5461	+ for m in fp.read().split():
	5462	+ modes.append('disk-%s' % m.strip('[]'))
	5463	+ fp.close()
4873	5464	return modes
4874	5465
4875	5466	# Function: dmidecode
..	..	@@ -4930,25 +5521,26 @@
4930	5521	continue
4931	5522
4932	5523	# read in the memory for scanning
4933		- fp = open(mempath, 'rb')
4934	5524	try:
	5525	+ fp = open(mempath, 'rb')
4935	5526	fp.seek(memaddr)
4936	5527	buf = fp.read(memsize)
4937	5528	except:
4938	5529	if(fatal):
4939	5530	doError('DMI table is unreachable, sorry')
4940	5531	else:
	5532	+ pprint('WARNING: /dev/mem is not readable, ignoring DMI data')
4941	5533	return out
4942	5534	fp.close()
4943	5535
4944	5536	# search for either an SM table or DMI table
4945	5537	i = base = length = num = 0
4946	5538	while(i < memsize):
4947		- if buf[i:i+4] == '_SM_' and i < memsize - 16:
	5539	+ if buf[i:i+4] == b'_SM_' and i < memsize - 16:
4948	5540	length = struct.unpack('H', buf[i+22:i+24])[0]
4949	5541	base, num = struct.unpack('IH', buf[i+24:i+30])
4950	5542	break
4951		- elif buf[i:i+5] == '_DMI_':
	5543	+ elif buf[i:i+5] == b'_DMI_':
4952	5544	length = struct.unpack('H', buf[i+6:i+8])[0]
4953	5545	base, num = struct.unpack('IH', buf[i+8:i+14])
4954	5546	break
..	..	@@ -4960,14 +5552,15 @@
4960	5552	return out
4961	5553
4962	5554	# read in the SM or DMI table
4963		- fp = open(mempath, 'rb')
4964	5555	try:
	5556	+ fp = open(mempath, 'rb')
4965	5557	fp.seek(base)
4966	5558	buf = fp.read(length)
4967	5559	except:
4968	5560	if(fatal):
4969	5561	doError('DMI table is unreachable, sorry')
4970	5562	else:
	5563	+ pprint('WARNING: /dev/mem is not readable, ignoring DMI data')
4971	5564	return out
4972	5565	fp.close()
4973	5566
..	..	@@ -4980,37 +5573,51 @@
4980	5573	if 0 == struct.unpack('H', buf[n:n+2])[0]:
4981	5574	break
4982	5575	n += 1
4983		- data = buf[i+size:n+2].split('\0')
	5576	+ data = buf[i+size:n+2].split(b'\0')
4984	5577	for name in info:
4985	5578	itype, idxadr = info[name]
4986	5579	if itype == type:
4987		- idx = struct.unpack('B', buf[i+idxadr])[0]
	5580	+ idx = struct.unpack('B', buf[i+idxadr:i+idxadr+1])[0]
4988	5581	if idx > 0 and idx < len(data) - 1:
4989		- s = data[idx-1].strip()
4990		- if s and s.lower() != 'to be filled by o.e.m.':
4991		- out[name] = data[idx-1]
	5582	+ s = data[idx-1].decode('utf-8')
	5583	+ if s.strip() and s.strip().lower() != 'to be filled by o.e.m.':
	5584	+ out[name] = s
4992	5585	i = n + 2
4993	5586	count += 1
4994	5587	return out
4995	5588
4996		-def getBattery():
4997		- p = '/sys/class/power_supply'
4998		- bat = dict()
4999		- for d in os.listdir(p):
5000		- type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower()
5001		- if type != 'battery':
5002		- continue
5003		- for v in ['status', 'energy_now', 'capacity_now']:
5004		- bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower()
5005		- break
5006		- ac = True
5007		- if 'status' in bat and 'discharging' in bat['status']:
5008		- ac = False
5009		- charge = 0
5010		- for v in ['energy_now', 'capacity_now']:
5011		- if v in bat and bat[v]:
5012		- charge = int(bat[v])
5013		- return (ac, charge)
	5589	+def displayControl(cmd):
	5590	+ xset, ret = 'timeout 10 xset -d :0.0 {0}', 0
	5591	+ if sysvals.sudouser:
	5592	+ xset = 'sudo -u %s %s' % (sysvals.sudouser, xset)
	5593	+ if cmd == 'init':
	5594	+ ret = call(xset.format('dpms 0 0 0'), shell=True)
	5595	+ if not ret:
	5596	+ ret = call(xset.format('s off'), shell=True)
	5597	+ elif cmd == 'reset':
	5598	+ ret = call(xset.format('s reset'), shell=True)
	5599	+ elif cmd in ['on', 'off', 'standby', 'suspend']:
	5600	+ b4 = displayControl('stat')
	5601	+ ret = call(xset.format('dpms force %s' % cmd), shell=True)
	5602	+ if not ret:
	5603	+ curr = displayControl('stat')
	5604	+ sysvals.vprint('Display Switched: %s -> %s' % (b4, curr))
	5605	+ if curr != cmd:
	5606	+ sysvals.vprint('WARNING: Display failed to change to %s' % cmd)
	5607	+ if ret:
	5608	+ sysvals.vprint('WARNING: Display failed to change to %s with xset' % cmd)
	5609	+ return ret
	5610	+ elif cmd == 'stat':
	5611	+ fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout
	5612	+ ret = 'unknown'
	5613	+ for line in fp:
	5614	+ m = re.match('[\s]Monitor is (?P<m>.)', ascii(line))
	5615	+ if(m and len(m.group('m')) >= 2):
	5616	+ out = m.group('m').lower()
	5617	+ ret = out[3:] if out[0:2] == 'in' else out
	5618	+ break
	5619	+ fp.close()
	5620	+ return ret
5014	5621
5015	5622	# Function: getFPDT
5016	5623	# Description:
..	..	@@ -5055,20 +5662,22 @@
5055	5662
5056	5663	table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
5057	5664	if(output):
5058		- print('')
5059		- print('Firmware Performance Data Table (%s)' % table[0])
5060		- print(' Signature : %s' % table[0])
5061		- print(' Table Length : %u' % table[1])
5062		- print(' Revision : %u' % table[2])
5063		- print(' Checksum : 0x%x' % table[3])
5064		- print(' OEM ID : %s' % table[4])
5065		- print(' OEM Table ID : %s' % table[5])
5066		- print(' OEM Revision : %u' % table[6])
5067		- print(' Creator ID : %s' % table[7])
5068		- print(' Creator Revision : 0x%x' % table[8])
5069		- print('')
	5665	+ pprint('\n'\
	5666	+ 'Firmware Performance Data Table (%s)\n'\
	5667	+ ' Signature : %s\n'\
	5668	+ ' Table Length : %u\n'\
	5669	+ ' Revision : %u\n'\
	5670	+ ' Checksum : 0x%x\n'\
	5671	+ ' OEM ID : %s\n'\
	5672	+ ' OEM Table ID : %s\n'\
	5673	+ ' OEM Revision : %u\n'\
	5674	+ ' Creator ID : %s\n'\
	5675	+ ' Creator Revision : 0x%x\n'\
	5676	+ '' % (ascii(table[0]), ascii(table[0]), table[1], table[2],
	5677	+ table[3], ascii(table[4]), ascii(table[5]), table[6],
	5678	+ ascii(table[7]), table[8]))
5070	5679
5071		- if(table[0] != 'FPDT'):
	5680	+ if(table[0] != b'FPDT'):
5072	5681	if(output):
5073	5682	doError('Invalid FPDT table')
5074	5683	return False
..	..	@@ -5077,7 +5686,11 @@
5077	5686	i = 0
5078	5687	fwData = [0, 0]
5079	5688	records = buf[36:]
5080		- fp = open(sysvals.mempath, 'rb')
	5689	+ try:
	5690	+ fp = open(sysvals.mempath, 'rb')
	5691	+ except:
	5692	+ pprint('WARNING: /dev/mem is not readable, ignoring the FPDT data')
	5693	+ return False
5081	5694	while(i < len(records)):
5082	5695	header = struct.unpack('HBB', records[i:i+4])
5083	5696	if(header[0] not in rectype):
..	..	@@ -5092,22 +5705,24 @@
5092	5705	first = fp.read(8)
5093	5706	except:
5094	5707	if(output):
5095		- print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
	5708	+ pprint('Bad address 0x%x in %s' % (addr, sysvals.mempath))
5096	5709	return [0, 0]
5097	5710	rechead = struct.unpack('4sI', first)
5098	5711	recdata = fp.read(rechead[1]-8)
5099		- if(rechead[0] == 'FBPT'):
5100		- record = struct.unpack('HBBIQQQQQ', recdata)
	5712	+ if(rechead[0] == b'FBPT'):
	5713	+ record = struct.unpack('HBBIQQQQQ', recdata[:48])
5101	5714	if(output):
5102		- print('%s (%s)' % (rectype[header[0]], rechead[0]))
5103		- print(' Reset END : %u ns' % record[4])
5104		- print(' OS Loader LoadImage Start : %u ns' % record[5])
5105		- print(' OS Loader StartImage Start : %u ns' % record[6])
5106		- print(' ExitBootServices Entry : %u ns' % record[7])
5107		- print(' ExitBootServices Exit : %u ns' % record[8])
5108		- elif(rechead[0] == 'S3PT'):
	5715	+ pprint('%s (%s)\n'\
	5716	+ ' Reset END : %u ns\n'\
	5717	+ ' OS Loader LoadImage Start : %u ns\n'\
	5718	+ ' OS Loader StartImage Start : %u ns\n'\
	5719	+ ' ExitBootServices Entry : %u ns\n'\
	5720	+ ' ExitBootServices Exit : %u ns'\
	5721	+ '' % (rectype[header[0]], ascii(rechead[0]), record[4], record[5],
	5722	+ record[6], record[7], record[8]))
	5723	+ elif(rechead[0] == b'S3PT'):
5109	5724	if(output):
5110		- print('%s (%s)' % (rectype[header[0]], rechead[0]))
	5725	+ pprint('%s (%s)' % (rectype[header[0]], ascii(rechead[0])))
5111	5726	j = 0
5112	5727	while(j < len(recdata)):
5113	5728	prechead = struct.unpack('HBB', recdata[j:j+4])
..	..	@@ -5117,27 +5732,26 @@
5117	5732	record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
5118	5733	fwData[1] = record[2]
5119	5734	if(output):
5120		- print(' %s' % prectype[prechead[0]])
5121		- print(' Resume Count : %u' % \
5122		- record[1])
5123		- print(' FullResume : %u ns' % \
5124		- record[2])
5125		- print(' AverageResume : %u ns' % \
5126		- record[3])
	5735	+ pprint(' %s\n'\
	5736	+ ' Resume Count : %u\n'\
	5737	+ ' FullResume : %u ns\n'\
	5738	+ ' AverageResume : %u ns'\
	5739	+ '' % (prectype[prechead[0]], record[1],
	5740	+ record[2], record[3]))
5127	5741	elif(prechead[0] == 1):
5128	5742	record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
5129	5743	fwData[0] = record[1] - record[0]
5130	5744	if(output):
5131		- print(' %s' % prectype[prechead[0]])
5132		- print(' SuspendStart : %u ns' % \
5133		- record[0])
5134		- print(' SuspendEnd : %u ns' % \
5135		- record[1])
5136		- print(' SuspendTime : %u ns' % \
5137		- fwData[0])
	5745	+ pprint(' %s\n'\
	5746	+ ' SuspendStart : %u ns\n'\
	5747	+ ' SuspendEnd : %u ns\n'\
	5748	+ ' SuspendTime : %u ns'\
	5749	+ '' % (prectype[prechead[0]], record[0],
	5750	+ record[1], fwData[0]))
	5751	+
5138	5752	j += prechead[1]
5139	5753	if(output):
5140		- print('')
	5754	+ pprint('')
5141	5755	i += header[1]
5142	5756	fp.close()
5143	5757	return fwData
..	..	@@ -5149,26 +5763,26 @@
5149	5763	# Output:
5150	5764	# True if the test will work, False if not
5151	5765	def statusCheck(probecheck=False):
5152		- status = True
	5766	+ status = ''
5153	5767
5154		- print('Checking this system (%s)...' % platform.node())
	5768	+ pprint('Checking this system (%s)...' % platform.node())
5155	5769
5156	5770	# check we have root access
5157	5771	res = sysvals.colorText('NO (No features of this tool will work!)')
5158	5772	if(sysvals.rootCheck(False)):
5159	5773	res = 'YES'
5160		- print(' have root access: %s' % res)
	5774	+ pprint(' have root access: %s' % res)
5161	5775	if(res != 'YES'):
5162		- print(' Try running this script with sudo')
5163		- return False
	5776	+ pprint(' Try running this script with sudo')
	5777	+ return 'missing root access'
5164	5778
5165	5779	# check sysfs is mounted
5166	5780	res = sysvals.colorText('NO (No features of this tool will work!)')
5167	5781	if(os.path.exists(sysvals.powerfile)):
5168	5782	res = 'YES'
5169		- print(' is sysfs mounted: %s' % res)
	5783	+ pprint(' is sysfs mounted: %s' % res)
5170	5784	if(res != 'YES'):
5171		- return False
	5785	+ return 'sysfs is missing'
5172	5786
5173	5787	# check target mode is a valid mode
5174	5788	if sysvals.suspendmode != 'command':
..	..	@@ -5177,11 +5791,11 @@
5177	5791	if(sysvals.suspendmode in modes):
5178	5792	res = 'YES'
5179	5793	else:
5180		- status = False
5181		- print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
	5794	+ status = '%s mode is not supported' % sysvals.suspendmode
	5795	+ pprint(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
5182	5796	if(res == 'NO'):
5183		- print(' valid power modes are: %s' % modes)
5184		- print(' please choose one with -m')
	5797	+ pprint(' valid power modes are: %s' % modes)
	5798	+ pprint(' please choose one with -m')
5185	5799
5186	5800	# check if ftrace is available
5187	5801	res = sysvals.colorText('NO')
..	..	@@ -5189,17 +5803,18 @@
5189	5803	if(ftgood):
5190	5804	res = 'YES'
5191	5805	elif(sysvals.usecallgraph):
5192		- status = False
5193		- print(' is ftrace supported: %s' % res)
	5806	+ status = 'ftrace is not properly supported'
	5807	+ pprint(' is ftrace supported: %s' % res)
5194	5808
5195	5809	# check if kprobes are available
5196		- res = sysvals.colorText('NO')
5197		- sysvals.usekprobes = sysvals.verifyKprobes()
5198		- if(sysvals.usekprobes):
5199		- res = 'YES'
5200		- else:
5201		- sysvals.usedevsrc = False
5202		- print(' are kprobes supported: %s' % res)
	5810	+ if sysvals.usekprobes:
	5811	+ res = sysvals.colorText('NO')
	5812	+ sysvals.usekprobes = sysvals.verifyKprobes()
	5813	+ if(sysvals.usekprobes):
	5814	+ res = 'YES'
	5815	+ else:
	5816	+ sysvals.usedevsrc = False
	5817	+ pprint(' are kprobes supported: %s' % res)
5203	5818
5204	5819	# what data source are we using
5205	5820	res = 'DMESG'
..	..	@@ -5210,15 +5825,26 @@
5210	5825	sysvals.usetraceevents = False
5211	5826	if(sysvals.usetraceevents):
5212	5827	res = 'FTRACE (all trace events found)'
5213		- print(' timeline data source: %s' % res)
	5828	+ pprint(' timeline data source: %s' % res)
5214	5829
5215	5830	# check if rtcwake
5216	5831	res = sysvals.colorText('NO')
5217	5832	if(sysvals.rtcpath != ''):
5218	5833	res = 'YES'
5219	5834	elif(sysvals.rtcwake):
5220		- status = False
5221		- print(' is rtcwake supported: %s' % res)
	5835	+ status = 'rtcwake is not properly supported'
	5836	+ pprint(' is rtcwake supported: %s' % res)
	5837	+
	5838	+ # check info commands
	5839	+ pprint(' optional commands this tool may use for info:')
	5840	+ no = sysvals.colorText('MISSING')
	5841	+ yes = sysvals.colorText('FOUND', 32)
	5842	+ for c in ['turbostat', 'mcelog', 'lspci', 'lsusb']:
	5843	+ if c == 'turbostat':
	5844	+ res = yes if sysvals.haveTurbostat() else no
	5845	+ else:
	5846	+ res = yes if sysvals.getExec(c) else no
	5847	+ pprint(' %s: %s' % (c, res))
5222	5848
5223	5849	if not probecheck:
5224	5850	return status
..	..	@@ -5243,9 +5869,9 @@
5243	5869	def doError(msg, help=False):
5244	5870	if(help == True):
5245	5871	printHelp()
5246		- print('ERROR: %s\n') % msg
	5872	+ pprint('ERROR: %s\n' % msg)
5247	5873	sysvals.outputResult({'error':msg})
5248		- sys.exit()
	5874	+ sys.exit(1)
5249	5875
5250	5876	# Function: getArgInt
5251	5877	# Description:
..	..	@@ -5253,7 +5879,7 @@
5253	5879	def getArgInt(name, args, min, max, main=True):
5254	5880	if main:
5255	5881	try:
5256		- arg = args.next()
	5882	+ arg = next(args)
5257	5883	except:
5258	5884	doError(name+': no argument supplied', True)
5259	5885	else:
..	..	@@ -5272,7 +5898,7 @@
5272	5898	def getArgFloat(name, args, min, max, main=True):
5273	5899	if main:
5274	5900	try:
5275		- arg = args.next()
	5901	+ arg = next(args)
5276	5902	except:
5277	5903	doError(name+': no argument supplied', True)
5278	5904	else:
..	..	@@ -5285,8 +5911,11 @@
5285	5911	doError(name+': value should be between %f and %f' % (min, max), True)
5286	5912	return val
5287	5913
5288		-def processData(live=False):
5289		- print('PROCESSING DATA')
	5914	+def processData(live=False, quiet=False):
	5915	+ if not quiet:
	5916	+ pprint('PROCESSING: %s' % sysvals.htmlfile)
	5917	+ sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \
	5918	+ (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes))
5290	5919	error = ''
5291	5920	if(sysvals.usetraceevents):
5292	5921	testruns, error = parseTraceLog(live)
..	..	@@ -5299,18 +5928,44 @@
5299	5928	parseKernelLog(data)
5300	5929	if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
5301	5930	appendIncompleteTraceLog(testruns)
	5931	+ if not sysvals.stamp:
	5932	+ pprint('ERROR: data does not include the expected stamp')
	5933	+ return (testruns, {'error': 'timeline generation failed'})
	5934	+ shown = ['bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr',
	5935	+ 'memsz', 'mode', 'numcpu', 'plat', 'time', 'wifi']
	5936	+ sysvals.vprint('System Info:')
	5937	+ for key in sorted(sysvals.stamp):
	5938	+ if key in shown:
	5939	+ sysvals.vprint(' %-8s : %s' % (key.upper(), sysvals.stamp[key]))
5302	5940	sysvals.vprint('Command:\n %s' % sysvals.cmdline)
5303	5941	for data in testruns:
	5942	+ if data.turbostat:
	5943	+ idx, s = 0, 'Turbostat:\n '
	5944	+ for val in data.turbostat.split('\|'):
	5945	+ idx += len(val) + 1
	5946	+ if idx >= 80:
	5947	+ idx = 0
	5948	+ s += '\n '
	5949	+ s += val + ' '
	5950	+ sysvals.vprint(s)
5304	5951	data.printDetails()
	5952	+ if len(sysvals.platinfo) > 0:
	5953	+ sysvals.vprint('\nPlatform Info:')
	5954	+ for info in sysvals.platinfo:
	5955	+ sysvals.vprint('[%s - %s]' % (info[0], info[1]))
	5956	+ sysvals.vprint(info[2])
	5957	+ sysvals.vprint('')
5305	5958	if sysvals.cgdump:
5306	5959	for data in testruns:
5307	5960	data.debugPrint()
5308		- sys.exit()
	5961	+ sys.exit(0)
5309	5962	if len(testruns) < 1:
	5963	+ pprint('ERROR: Not enough test data to build a timeline')
5310	5964	return (testruns, {'error': 'timeline generation failed'})
5311	5965	sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
5312	5966	createHTML(testruns, error)
5313		- print('DONE')
	5967	+ if not quiet:
	5968	+ pprint('DONE: %s' % sysvals.htmlfile)
5314	5969	data = testruns[0]
5315	5970	stamp = data.stamp
5316	5971	stamp['suspend'], stamp['resume'] = data.getTimeValues()
..	..	@@ -5323,126 +5978,255 @@
5323	5978	# Function: rerunTest
5324	5979	# Description:
5325	5980	# generate an output from an existing set of ftrace/dmesg logs
5326		-def rerunTest():
	5981	+def rerunTest(htmlfile=''):
5327	5982	if sysvals.ftracefile:
5328	5983	doesTraceLogHaveTraceEvents()
5329	5984	if not sysvals.dmesgfile and not sysvals.usetraceevents:
5330	5985	doError('recreating this html output requires a dmesg file')
5331		- sysvals.setOutputFile()
	5986	+ if htmlfile:
	5987	+ sysvals.htmlfile = htmlfile
	5988	+ else:
	5989	+ sysvals.setOutputFile()
5332	5990	if os.path.exists(sysvals.htmlfile):
5333	5991	if not os.path.isfile(sysvals.htmlfile):
5334	5992	doError('a directory already exists with this name: %s' % sysvals.htmlfile)
5335	5993	elif not os.access(sysvals.htmlfile, os.W_OK):
5336	5994	doError('missing permission to write to %s' % sysvals.htmlfile)
5337		- testruns, stamp = processData(False)
	5995	+ testruns, stamp = processData()
	5996	+ sysvals.resetlog()
5338	5997	return stamp
5339	5998
5340	5999	# Function: runTest
5341	6000	# Description:
5342	6001	# execute a suspend/resume, gather the logs, and generate the output
5343		-def runTest(n=0):
	6002	+def runTest(n=0, quiet=False):
5344	6003	# prepare for the test
5345		- sysvals.initFtrace()
	6004	+ sysvals.initFtrace(quiet)
5346	6005	sysvals.initTestOutput('suspend')
5347	6006
5348	6007	# execute the test
5349		- executeSuspend()
	6008	+ executeSuspend(quiet)
5350	6009	sysvals.cleanupFtrace()
5351	6010	if sysvals.skiphtml:
5352		- sysvals.sudouser(sysvals.testdir)
	6011	+ sysvals.outputResult({}, n)
	6012	+ sysvals.sudoUserchown(sysvals.testdir)
5353	6013	return
5354		- testruns, stamp = processData(True)
	6014	+ testruns, stamp = processData(True, quiet)
5355	6015	for data in testruns:
5356	6016	del data
5357		- sysvals.sudouser(sysvals.testdir)
	6017	+ sysvals.sudoUserchown(sysvals.testdir)
5358	6018	sysvals.outputResult(stamp, n)
	6019	+ if 'error' in stamp:
	6020	+ return 2
	6021	+ return 0
5359	6022
5360	6023	def find_in_html(html, start, end, firstonly=True):
5361		- n, out = 0, []
5362		- while n < len(html):
5363		- m = re.search(start, html[n:])
	6024	+ cnt, out, list = len(html), [], []
	6025	+ if firstonly:
	6026	+ m = re.search(start, html)
	6027	+ if m:
	6028	+ list.append(m)
	6029	+ else:
	6030	+ list = re.finditer(start, html)
	6031	+ for match in list:
	6032	+ s = match.end()
	6033	+ e = cnt if (len(out) < 1 or s + 10000 > cnt) else s + 10000
	6034	+ m = re.search(end, html[s:e])
5364	6035	if not m:
5365	6036	break
5366		- i = m.end()
5367		- m = re.search(end, html[n+i:])
5368		- if not m:
5369		- break
5370		- j = m.start()
5371		- str = html[n+i:n+i+j]
	6037	+ e = s + m.start()
	6038	+ str = html[s:e]
5372	6039	if end == 'ms':
5373	6040	num = re.search(r'[-+]?\d*\.\d+\|\d+', str)
5374	6041	str = num.group() if num else 'NaN'
5375	6042	if firstonly:
5376	6043	return str
5377	6044	out.append(str)
5378		- n += i+j
5379	6045	if firstonly:
5380	6046	return ''
5381	6047	return out
	6048	+
	6049	+def data_from_html(file, outpath, issues, fulldetail=False):
	6050	+ html = open(file, 'r').read()
	6051	+ sysvals.htmlfile = os.path.relpath(file, outpath)
	6052	+ # extract general info
	6053	+ suspend = find_in_html(html, 'Kernel Suspend', 'ms')
	6054	+ resume = find_in_html(html, 'Kernel Resume', 'ms')
	6055	+ sysinfo = find_in_html(html, '<div class="stamp sysinfo">', '</div>')
	6056	+ line = find_in_html(html, '<div class="stamp">', '</div>')
	6057	+ stmp = line.split()
	6058	+ if not suspend or not resume or len(stmp) != 8:
	6059	+ return False
	6060	+ try:
	6061	+ dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
	6062	+ except:
	6063	+ return False
	6064	+ sysvals.hostname = stmp[0]
	6065	+ tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
	6066	+ error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
	6067	+ if error:
	6068	+ m = re.match('[a-z0-9]* failed in (?P<p>\S).', error)
	6069	+ if m:
	6070	+ result = 'fail in %s' % m.group('p')
	6071	+ else:
	6072	+ result = 'fail'
	6073	+ else:
	6074	+ result = 'pass'
	6075	+ # extract error info
	6076	+ tp, ilist = False, []
	6077	+ extra = dict()
	6078	+ log = find_in_html(html, '<div id="dmesglog" style="display:none;">',
	6079	+ '</div>').strip()
	6080	+ if log:
	6081	+ d = Data(0)
	6082	+ d.end = 999999999
	6083	+ d.dmesgtext = log.split('\n')
	6084	+ tp = d.extractErrorInfo()
	6085	+ for msg in tp.msglist:
	6086	+ sysvals.errorSummary(issues, msg)
	6087	+ if stmp[2] == 'freeze':
	6088	+ extra = d.turbostatInfo()
	6089	+ elist = dict()
	6090	+ for dir in d.errorinfo:
	6091	+ for err in d.errorinfo[dir]:
	6092	+ if err[0] not in elist:
	6093	+ elist[err[0]] = 0
	6094	+ elist[err[0]] += 1
	6095	+ for i in elist:
	6096	+ ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i)
	6097	+ wifi = find_in_html(html, 'Wifi Resume: ', '</td>')
	6098	+ if wifi:
	6099	+ extra['wifi'] = wifi
	6100	+ low = find_in_html(html, 'freeze time: <b>', ' ms</b>')
	6101	+ if low and 'waking' in low:
	6102	+ issue = 'FREEZEWAKE'
	6103	+ match = [i for i in issues if i['match'] == issue]
	6104	+ if len(match) > 0:
	6105	+ match[0]['count'] += 1
	6106	+ if sysvals.hostname not in match[0]['urls']:
	6107	+ match[0]['urls'][sysvals.hostname] = [sysvals.htmlfile]
	6108	+ elif sysvals.htmlfile not in match[0]['urls'][sysvals.hostname]:
	6109	+ match[0]['urls'][sysvals.hostname].append(sysvals.htmlfile)
	6110	+ else:
	6111	+ issues.append({
	6112	+ 'match': issue, 'count': 1, 'line': issue,
	6113	+ 'urls': {sysvals.hostname: [sysvals.htmlfile]},
	6114	+ })
	6115	+ ilist.append(issue)
	6116	+ # extract device info
	6117	+ devices = dict()
	6118	+ for line in html.split('\n'):
	6119	+ m = re.match(' <div id=\"[a,0-9]\" title=\"(?P<title>.)\" class=\"thread.*', line)
	6120	+ if not m or 'thread kth' in line or 'thread sec' in line:
	6121	+ continue
	6122	+ m = re.match('(?P<n>.) $(?P<t>[0-9,\.]) ms$ (?P<p>.*)', m.group('title'))
	6123	+ if not m:
	6124	+ continue
	6125	+ name, time, phase = m.group('n'), m.group('t'), m.group('p')
	6126	+ if ' async' in name or ' sync' in name:
	6127	+ name = ' '.join(name.split(' ')[:-1])
	6128	+ if phase.startswith('suspend'):
	6129	+ d = 'suspend'
	6130	+ elif phase.startswith('resume'):
	6131	+ d = 'resume'
	6132	+ else:
	6133	+ continue
	6134	+ if d not in devices:
	6135	+ devices[d] = dict()
	6136	+ if name not in devices[d]:
	6137	+ devices[d][name] = 0.0
	6138	+ devices[d][name] += float(time)
	6139	+ # create worst device info
	6140	+ worst = dict()
	6141	+ for d in ['suspend', 'resume']:
	6142	+ worst[d] = {'name':'', 'time': 0.0}
	6143	+ dev = devices[d] if d in devices else 0
	6144	+ if dev and len(dev.keys()) > 0:
	6145	+ n = sorted(dev, key=lambda k:(dev[k], k), reverse=True)[0]
	6146	+ worst[d]['name'], worst[d]['time'] = n, dev[n]
	6147	+ data = {
	6148	+ 'mode': stmp[2],
	6149	+ 'host': stmp[0],
	6150	+ 'kernel': stmp[1],
	6151	+ 'sysinfo': sysinfo,
	6152	+ 'time': tstr,
	6153	+ 'result': result,
	6154	+ 'issues': ' '.join(ilist),
	6155	+ 'suspend': suspend,
	6156	+ 'resume': resume,
	6157	+ 'devlist': devices,
	6158	+ 'sus_worst': worst['suspend']['name'],
	6159	+ 'sus_worsttime': worst['suspend']['time'],
	6160	+ 'res_worst': worst['resume']['name'],
	6161	+ 'res_worsttime': worst['resume']['time'],
	6162	+ 'url': sysvals.htmlfile,
	6163	+ }
	6164	+ for key in extra:
	6165	+ data[key] = extra[key]
	6166	+ if fulldetail:
	6167	+ data['funclist'] = find_in_html(html, '<div title="', '" class="traceevent"', False)
	6168	+ if tp:
	6169	+ for arg in ['-multi ', '-info ']:
	6170	+ if arg in tp.cmdline:
	6171	+ data['target'] = tp.cmdline[tp.cmdline.find(arg):].split()[1]
	6172	+ break
	6173	+ return data
	6174	+
	6175	+def genHtml(subdir, force=False):
	6176	+ for dirname, dirnames, filenames in os.walk(subdir):
	6177	+ sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
	6178	+ for filename in filenames:
	6179	+ file = os.path.join(dirname, filename)
	6180	+ if sysvals.usable(file):
	6181	+ if(re.match('.*_dmesg.txt', filename)):
	6182	+ sysvals.dmesgfile = file
	6183	+ elif(re.match('.*_ftrace.txt', filename)):
	6184	+ sysvals.ftracefile = file
	6185	+ sysvals.setOutputFile()
	6186	+ if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \
	6187	+ (force or not sysvals.usable(sysvals.htmlfile)):
	6188	+ pprint('FTRACE: %s' % sysvals.ftracefile)
	6189	+ if sysvals.dmesgfile:
	6190	+ pprint('DMESG : %s' % sysvals.dmesgfile)
	6191	+ rerunTest()
5382	6192
5383	6193	# Function: runSummary
5384	6194	# Description:
5385	6195	# create a summary of tests in a sub-directory
5386	6196	def runSummary(subdir, local=True, genhtml=False):
5387	6197	inpath = os.path.abspath(subdir)
5388		- outpath = inpath
5389		- if local:
5390		- outpath = os.path.abspath('.')
5391		- print('Generating a summary of folder "%s"' % inpath)
	6198	+ outpath = os.path.abspath('.') if local else inpath
	6199	+ pprint('Generating a summary of folder:\n %s' % inpath)
5392	6200	if genhtml:
5393		- for dirname, dirnames, filenames in os.walk(subdir):
5394		- sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
5395		- for filename in filenames:
5396		- if(re.match('.*_dmesg.txt', filename)):
5397		- sysvals.dmesgfile = os.path.join(dirname, filename)
5398		- elif(re.match('.*_ftrace.txt', filename)):
5399		- sysvals.ftracefile = os.path.join(dirname, filename)
5400		- sysvals.setOutputFile()
5401		- if sysvals.ftracefile and sysvals.htmlfile and \
5402		- not os.path.exists(sysvals.htmlfile):
5403		- print('FTRACE: %s' % sysvals.ftracefile)
5404		- if sysvals.dmesgfile:
5405		- print('DMESG : %s' % sysvals.dmesgfile)
5406		- rerunTest()
5407		- testruns = []
	6201	+ genHtml(subdir)
	6202	+ target, issues, testruns = '', [], []
	6203	+ desc = {'host':[],'mode':[],'kernel':[]}
5408	6204	for dirname, dirnames, filenames in os.walk(subdir):
5409	6205	for filename in filenames:
5410	6206	if(not re.match('.*.html', filename)):
5411	6207	continue
5412		- file = os.path.join(dirname, filename)
5413		- html = open(file, 'r').read()
5414		- suspend = find_in_html(html, 'Kernel Suspend', 'ms')
5415		- resume = find_in_html(html, 'Kernel Resume', 'ms')
5416		- line = find_in_html(html, '<div class="stamp">', '</div>')
5417		- stmp = line.split()
5418		- if not suspend or not resume or len(stmp) != 8:
	6208	+ data = data_from_html(os.path.join(dirname, filename), outpath, issues)
	6209	+ if(not data):
5419	6210	continue
5420		- try:
5421		- dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
5422		- except:
5423		- continue
5424		- tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
5425		- error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
5426		- result = 'fail' if error else 'pass'
5427		- ilist = []
5428		- e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '→</div>', False)
5429		- for i in list(set(e)):
5430		- ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
5431		- data = {
5432		- 'mode': stmp[2],
5433		- 'host': stmp[0],
5434		- 'kernel': stmp[1],
5435		- 'time': tstr,
5436		- 'result': result,
5437		- 'issues': ','.join(ilist),
5438		- 'suspend': suspend,
5439		- 'resume': resume,
5440		- 'url': os.path.relpath(file, outpath),
5441		- }
	6211	+ if 'target' in data:
	6212	+ target = data['target']
5442	6213	testruns.append(data)
5443		- outfile = os.path.join(outpath, 'summary.html')
5444		- print('Summary file: %s' % outfile)
5445		- createHTMLSummarySimple(testruns, outfile, inpath)
	6214	+ for key in desc:
	6215	+ if data[key] not in desc[key]:
	6216	+ desc[key].append(data[key])
	6217	+ pprint('Summary files:')
	6218	+ if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1:
	6219	+ title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0])
	6220	+ if target:
	6221	+ title += ' %s' % target
	6222	+ else:
	6223	+ title = inpath
	6224	+ createHTMLSummarySimple(testruns, os.path.join(outpath, 'summary.html'), title)
	6225	+ pprint(' summary.html - tabular list of test data found')
	6226	+ createHTMLDeviceSummary(testruns, os.path.join(outpath, 'summary-devices.html'), title)
	6227	+ pprint(' summary-devices.html - kernel device list sorted by total execution time')
	6228	+ createHTMLIssuesSummary(testruns, issues, os.path.join(outpath, 'summary-issues.html'), title)
	6229	+ pprint(' summary-issues.html - kernel issues found sorted by frequency')
5446	6230
5447	6231	# Function: checkArgBool
5448	6232	# Description:
..	..	@@ -5459,7 +6243,7 @@
5459	6243	# Description:
5460	6244	# Configure the script via the info in a config file
5461	6245	def configFromFile(file):
5462		- Config = ConfigParser.ConfigParser()
	6246	+ Config = configparser.ConfigParser()
5463	6247
5464	6248	Config.read(file)
5465	6249	sections = Config.sections()
..	..	@@ -5499,13 +6283,10 @@
5499	6283	else:
5500	6284	doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)
5501	6285	elif(option == 'display'):
5502		- if value in switchvalues:
5503		- if value in switchoff:
5504		- sysvals.display = -1
5505		- else:
5506		- sysvals.display = 1
5507		- else:
5508		- doError('invalid value --> (%s: %s), use "on/off"' % (option, value), True)
	6286	+ disopt = ['on', 'off', 'standby', 'suspend']
	6287	+ if value not in disopt:
	6288	+ doError('invalid value --> (%s: %s), use %s' % (option, value, disopt), True)
	6289	+ sysvals.display = value
5509	6290	elif(option == 'gzip'):
5510	6291	sysvals.gzip = checkArgBool(option, value)
5511	6292	elif(option == 'cgfilter'):
..	..	@@ -5521,9 +6302,9 @@
5521	6302	sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)
5522	6303	elif(option == 'cgphase'):
5523	6304	d = Data(0)
5524		- if value not in d.phases:
	6305	+ if value not in d.phasedef:
5525	6306	doError('invalid phase --> (%s: %s), valid phases are %s'\
5526		- % (option, value, d.phases), True)
	6307	+ % (option, value, d.phasedef.keys()), True)
5527	6308	sysvals.cgphase = value
5528	6309	elif(option == 'fadd'):
5529	6310	file = sysvals.configFile(value)
..	..	@@ -5536,9 +6317,7 @@
5536	6317	nums = value.split()
5537	6318	if len(nums) != 2:
5538	6319	doError('multi requires 2 integers (exec_count and delay)', True)
5539		- sysvals.multitest['run'] = True
5540		- sysvals.multitest['count'] = getArgInt('multi: n d (exec count)', nums[0], 2, 1000000, False)
5541		- sysvals.multitest['delay'] = getArgInt('multi: n d (delay between tests)', nums[1], 0, 3600, False)
	6320	+ sysvals.multiinit(nums[0], nums[1])
5542	6321	elif(option == 'devicefilter'):
5543	6322	sysvals.setDeviceFilter(value)
5544	6323	elif(option == 'expandcg'):
..	..	@@ -5660,84 +6439,92 @@
5660	6439	# Description:
5661	6440	# print out the help text
5662	6441	def printHelp():
5663		- print('')
5664		- print('%s v%s' % (sysvals.title, sysvals.version))
5665		- print('Usage: sudo sleepgraph <options> <commands>')
5666		- print('')
5667		- print('Description:')
5668		- print(' This tool is designed to assist kernel and OS developers in optimizing')
5669		- print(' their linux stack\'s suspend/resume time. Using a kernel image built')
5670		- print(' with a few extra options enabled, the tool will execute a suspend and')
5671		- print(' capture dmesg and ftrace data until resume is complete. This data is')
5672		- print(' transformed into a device timeline and an optional callgraph to give')
5673		- print(' a detailed view of which devices/subsystems are taking the most')
5674		- print(' time in suspend/resume.')
5675		- print('')
5676		- print(' If no specific command is given, the default behavior is to initiate')
5677		- print(' a suspend/resume and capture the dmesg/ftrace output as an html timeline.')
5678		- print('')
5679		- print(' Generates output files in subdirectory: suspend-yymmdd-HHMMSS')
5680		- print(' HTML output: <hostname>_<mode>.html')
5681		- print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
5682		- print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
5683		- print('')
5684		- print('Options:')
5685		- print(' -h Print this help text')
5686		- print(' -v Print the current tool version')
5687		- print(' -config fn Pull arguments and config options from file fn')
5688		- print(' -verbose Print extra information during execution and analysis')
5689		- print(' -m mode Mode to initiate for suspend (default: %s)') % (sysvals.suspendmode)
5690		- print(' -o name Overrides the output subdirectory name when running a new test')
5691		- print(' default: suspend-{date}-{time}')
5692		- print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)')
5693		- print(' -addlogs Add the dmesg and ftrace logs to the html output')
5694		- print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
5695		- print(' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)')
5696		- print(' -result fn Export a results table to a text file for parsing.')
5697		- print(' [testprep]')
5698		- print(' -sync Sync the filesystems before starting the test')
5699		- print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test')
5700		- print(' -display on/off Turn the display on or off for the test')
5701		- print(' [advanced]')
5702		- print(' -gzip Gzip the trace and dmesg logs to save space')
5703		- print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"')
5704		- print(' -proc Add usermode process info into the timeline (default: disabled)')
5705		- print(' -dev Add kernel function calls and threads to the timeline (default: disabled)')
5706		- print(' -x2 Run two suspend/resumes back to back (default: disabled)')
5707		- print(' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)')
5708		- print(' -predelay t Include t ms delay before 1st suspend (default: 0 ms)')
5709		- print(' -postdelay t Include t ms delay after last resume (default: 0 ms)')
5710		- print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
5711		- print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
5712		- print(' be created in a new subdirectory with a summary page.')
5713		- print(' [debug]')
5714		- print(' -f Use ftrace to create device callgraphs (default: disabled)')
5715		- print(' -maxdepth N limit the callgraph data to N call levels (default: 0=all)')
5716		- print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
5717		- print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
5718		- print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names')
5719		- print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
5720		- print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)')
5721		- print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
5722		- print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
5723		- print(' -cgfilter S Filter the callgraph output in the timeline')
5724		- print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)')
5725		- print(' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)')
5726		- print('')
5727		- print('Other commands:')
5728		- print(' -modes List available suspend modes')
5729		- print(' -status Test to see if the system is enabled to run this tool')
5730		- print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
5731		- print(' -battery Print out battery info (if available)')
5732		- print(' -sysinfo Print out system info extracted from BIOS')
5733		- print(' -devinfo Print out the pm settings of all devices which support runtime suspend')
5734		- print(' -flist Print the list of functions currently being captured in ftrace')
5735		- print(' -flistall Print all functions capable of being captured in ftrace')
5736		- print(' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]')
5737		- print(' [redo]')
5738		- print(' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)')
5739		- print(' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)')
5740		- print('')
	6442	+ pprint('\n%s v%s\n'\
	6443	+ 'Usage: sudo sleepgraph <options> <commands>\n'\
	6444	+ '\n'\
	6445	+ 'Description:\n'\
	6446	+ ' This tool is designed to assist kernel and OS developers in optimizing\n'\
	6447	+ ' their linux stack\'s suspend/resume time. Using a kernel image built\n'\
	6448	+ ' with a few extra options enabled, the tool will execute a suspend and\n'\
	6449	+ ' capture dmesg and ftrace data until resume is complete. This data is\n'\
	6450	+ ' transformed into a device timeline and an optional callgraph to give\n'\
	6451	+ ' a detailed view of which devices/subsystems are taking the most\n'\
	6452	+ ' time in suspend/resume.\n'\
	6453	+ '\n'\
	6454	+ ' If no specific command is given, the default behavior is to initiate\n'\
	6455	+ ' a suspend/resume and capture the dmesg/ftrace output as an html timeline.\n'\
	6456	+ '\n'\
	6457	+ ' Generates output files in subdirectory: suspend-yymmdd-HHMMSS\n'\
	6458	+ ' HTML output: <hostname>_<mode>.html\n'\
	6459	+ ' raw dmesg output: <hostname>_<mode>_dmesg.txt\n'\
	6460	+ ' raw ftrace output: <hostname>_<mode>_ftrace.txt\n'\
	6461	+ '\n'\
	6462	+ 'Options:\n'\
	6463	+ ' -h Print this help text\n'\
	6464	+ ' -v Print the current tool version\n'\
	6465	+ ' -config fn Pull arguments and config options from file fn\n'\
	6466	+ ' -verbose Print extra information during execution and analysis\n'\
	6467	+ ' -m mode Mode to initiate for suspend (default: %s)\n'\
	6468	+ ' -o name Overrides the output subdirectory name when running a new test\n'\
	6469	+ ' default: suspend-{date}-{time}\n'\
	6470	+ ' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)\n'\
	6471	+ ' -addlogs Add the dmesg and ftrace logs to the html output\n'\
	6472	+ ' -noturbostat Dont use turbostat in freeze mode (default: disabled)\n'\
	6473	+ ' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\
	6474	+ ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\
	6475	+ ' -result fn Export a results table to a text file for parsing.\n'\
	6476	+ ' -wifi If a wifi connection is available, check that it reconnects after resume.\n'\
	6477	+ ' [testprep]\n'\
	6478	+ ' -sync Sync the filesystems before starting the test\n'\
	6479	+ ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\
	6480	+ ' -display m Change the display mode to m for the test (on/off/standby/suspend)\n'\
	6481	+ ' [advanced]\n'\
	6482	+ ' -gzip Gzip the trace and dmesg logs to save space\n'\
	6483	+ ' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"\n'\
	6484	+ ' -proc Add usermode process info into the timeline (default: disabled)\n'\
	6485	+ ' -dev Add kernel function calls and threads to the timeline (default: disabled)\n'\
	6486	+ ' -x2 Run two suspend/resumes back to back (default: disabled)\n'\
	6487	+ ' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)\n'\
	6488	+ ' -predelay t Include t ms delay before 1st suspend (default: 0 ms)\n'\
	6489	+ ' -postdelay t Include t ms delay after last resume (default: 0 ms)\n'\
	6490	+ ' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)\n'\
	6491	+ ' -multi n d Execute <n> consecutive tests at <d> seconds intervals. If <n> is followed\n'\
	6492	+ ' by a "d", "h", or "m" execute for <n> days, hours, or mins instead.\n'\
	6493	+ ' The outputs will be created in a new subdirectory with a summary page.\n'\
	6494	+ ' -maxfail n Abort a -multi run after n consecutive fails (default is 0 = never abort)\n'\
	6495	+ ' [debug]\n'\
	6496	+ ' -f Use ftrace to create device callgraphs (default: disabled)\n'\
	6497	+ ' -ftop Use ftrace on the top level call: "%s" (default: disabled)\n'\
	6498	+ ' -maxdepth N limit the callgraph data to N call levels (default: 0=all)\n'\
	6499	+ ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\
	6500	+ ' -fadd file Add functions to be graphed in the timeline from a list in a text file\n'\
	6501	+ ' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names\n'\
	6502	+ ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\
	6503	+ ' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)\n'\
	6504	+ ' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)\n'\
	6505	+ ' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)\n'\
	6506	+ ' -cgfilter S Filter the callgraph output in the timeline\n'\
	6507	+ ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\
	6508	+ ' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)\n'\
	6509	+ ' -devdump Print out all the raw device data for each phase\n'\
	6510	+ ' -cgdump Print out all the raw callgraph data\n'\
	6511	+ '\n'\
	6512	+ 'Other commands:\n'\
	6513	+ ' -modes List available suspend modes\n'\
	6514	+ ' -status Test to see if the system is enabled to run this tool\n'\
	6515	+ ' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\
	6516	+ ' -wificheck Print out wifi connection info\n'\
	6517	+ ' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\
	6518	+ ' -sysinfo Print out system info extracted from BIOS\n'\
	6519	+ ' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\
	6520	+ ' -cmdinfo Print out all the platform info collected before and after suspend/resume\n'\
	6521	+ ' -flist Print the list of functions currently being captured in ftrace\n'\
	6522	+ ' -flistall Print all functions capable of being captured in ftrace\n'\
	6523	+ ' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]\n'\
	6524	+ ' [redo]\n'\
	6525	+ ' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)\n'\
	6526	+ ' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)\n'\
	6527	+ '' % (sysvals.title, sysvals.version, sysvals.suspendmode, sysvals.ftopfunc))
5741	6528	return True
5742	6529
5743	6530	# ----------------- MAIN --------------------
..	..	@@ -5745,7 +6532,9 @@
5745	6532	if __name__ == '__main__':
5746	6533	genhtml = False
5747	6534	cmd = ''
5748		- simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status', '-battery']
	6535	+ simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall',
	6536	+ '-devinfo', '-status', '-xon', '-xoff', '-xstandby', '-xsuspend',
	6537	+ '-xinit', '-xreset', '-xstat', '-wificheck', '-cmdinfo']
5749	6538	if '-f' in sys.argv:
5750	6539	sysvals.cgskip = sysvals.configFile('cgskip.txt')
5751	6540	# loop through the command line arguments
..	..	@@ -5753,7 +6542,7 @@
5753	6542	for arg in args:
5754	6543	if(arg == '-m'):
5755	6544	try:
5756		- val = args.next()
	6545	+ val = next(args)
5757	6546	except:
5758	6547	doError('No mode supplied', True)
5759	6548	if val == 'command' and not sysvals.testcommand:
..	..	@@ -5763,10 +6552,10 @@
5763	6552	cmd = arg[1:]
5764	6553	elif(arg == '-h'):
5765	6554	printHelp()
5766		- sys.exit()
	6555	+ sys.exit(0)
5767	6556	elif(arg == '-v'):
5768		- print("Version %s" % sysvals.version)
5769		- sys.exit()
	6557	+ pprint("Version %s" % sysvals.version)
	6558	+ sys.exit(0)
5770	6559	elif(arg == '-x2'):
5771	6560	sysvals.execcount = 2
5772	6561	elif(arg == '-x2delay'):
..	..	@@ -5777,14 +6566,28 @@
5777	6566	sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
5778	6567	elif(arg == '-f'):
5779	6568	sysvals.usecallgraph = True
	6569	+ elif(arg == '-ftop'):
	6570	+ sysvals.usecallgraph = True
	6571	+ sysvals.ftop = True
	6572	+ sysvals.usekprobes = False
5780	6573	elif(arg == '-skiphtml'):
5781	6574	sysvals.skiphtml = True
5782	6575	elif(arg == '-cgdump'):
5783	6576	sysvals.cgdump = True
	6577	+ elif(arg == '-devdump'):
	6578	+ sysvals.devdump = True
5784	6579	elif(arg == '-genhtml'):
5785	6580	genhtml = True
5786	6581	elif(arg == '-addlogs'):
5787	6582	sysvals.dmesglog = sysvals.ftracelog = True
	6583	+ elif(arg == '-nologs'):
	6584	+ sysvals.dmesglog = sysvals.ftracelog = False
	6585	+ elif(arg == '-addlogdmesg'):
	6586	+ sysvals.dmesglog = True
	6587	+ elif(arg == '-addlogftrace'):
	6588	+ sysvals.ftracelog = True
	6589	+ elif(arg == '-noturbostat'):
	6590	+ sysvals.tstat = False
5788	6591	elif(arg == '-verbose'):
5789	6592	sysvals.verbose = True
5790	6593	elif(arg == '-proc'):
..	..	@@ -5793,11 +6596,18 @@
5793	6596	sysvals.usedevsrc = True
5794	6597	elif(arg == '-sync'):
5795	6598	sysvals.sync = True
	6599	+ elif(arg == '-wifi'):
	6600	+ sysvals.wifi = True
5796	6601	elif(arg == '-gzip'):
5797	6602	sysvals.gzip = True
	6603	+ elif(arg == '-info'):
	6604	+ try:
	6605	+ val = next(args)
	6606	+ except:
	6607	+ doError('-info requires one string argument', True)
5798	6608	elif(arg == '-rs'):
5799	6609	try:
5800		- val = args.next()
	6610	+ val = next(args)
5801	6611	except:
5802	6612	doError('-rs requires "enable" or "disable"', True)
5803	6613	if val.lower() in switchvalues:
..	..	@@ -5809,21 +6619,18 @@
5809	6619	doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True)
5810	6620	elif(arg == '-display'):
5811	6621	try:
5812		- val = args.next()
	6622	+ val = next(args)
5813	6623	except:
5814		- doError('-display requires "on" or "off"', True)
5815		- if val.lower() in switchvalues:
5816		- if val.lower() in switchoff:
5817		- sysvals.display = -1
5818		- else:
5819		- sysvals.display = 1
5820		- else:
5821		- doError('invalid option: %s, use "on/off"' % val, True)
	6624	+ doError('-display requires an mode value', True)
	6625	+ disopt = ['on', 'off', 'standby', 'suspend']
	6626	+ if val.lower() not in disopt:
	6627	+ doError('valid display mode values are %s' % disopt, True)
	6628	+ sysvals.display = val.lower()
5822	6629	elif(arg == '-maxdepth'):
5823	6630	sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
5824	6631	elif(arg == '-rtcwake'):
5825	6632	try:
5826		- val = args.next()
	6633	+ val = next(args)
5827	6634	except:
5828	6635	doError('No rtcwake time supplied', True)
5829	6636	if val.lower() in switchoff:
..	..	@@ -5843,23 +6650,29 @@
5843	6650	sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
5844	6651	elif(arg == '-cgphase'):
5845	6652	try:
5846		- val = args.next()
	6653	+ val = next(args)
5847	6654	except:
5848	6655	doError('No phase name supplied', True)
5849	6656	d = Data(0)
5850		- if val not in d.phases:
	6657	+ if val not in d.phasedef:
5851	6658	doError('invalid phase --> (%s: %s), valid phases are %s'\
5852		- % (arg, val, d.phases), True)
	6659	+ % (arg, val, d.phasedef.keys()), True)
5853	6660	sysvals.cgphase = val
5854	6661	elif(arg == '-cgfilter'):
5855	6662	try:
5856		- val = args.next()
	6663	+ val = next(args)
5857	6664	except:
5858	6665	doError('No callgraph functions supplied', True)
5859	6666	sysvals.setCallgraphFilter(val)
	6667	+ elif(arg == '-skipkprobe'):
	6668	+ try:
	6669	+ val = next(args)
	6670	+ except:
	6671	+ doError('No kprobe functions supplied', True)
	6672	+ sysvals.skipKprobes(val)
5860	6673	elif(arg == '-cgskip'):
5861	6674	try:
5862		- val = args.next()
	6675	+ val = next(args)
5863	6676	except:
5864	6677	doError('No file supplied', True)
5865	6678	if val.lower() in switchoff:
..	..	@@ -5874,7 +6687,7 @@
5874	6687	sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)
5875	6688	elif(arg == '-cmd'):
5876	6689	try:
5877		- val = args.next()
	6690	+ val = next(args)
5878	6691	except:
5879	6692	doError('No command string supplied', True)
5880	6693	sysvals.testcommand = val
..	..	@@ -5883,19 +6696,23 @@
5883	6696	sysvals.cgexp = True
5884	6697	elif(arg == '-srgap'):
5885	6698	sysvals.srgap = 5
	6699	+ elif(arg == '-maxfail'):
	6700	+ sysvals.maxfail = getArgInt('-maxfail', args, 0, 1000000)
5886	6701	elif(arg == '-multi'):
5887		- sysvals.multitest['run'] = True
5888		- sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000)
5889		- sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600)
	6702	+ try:
	6703	+ c, d = next(args), next(args)
	6704	+ except:
	6705	+ doError('-multi requires two values', True)
	6706	+ sysvals.multiinit(c, d)
5890	6707	elif(arg == '-o'):
5891	6708	try:
5892		- val = args.next()
	6709	+ val = next(args)
5893	6710	except:
5894	6711	doError('No subdirectory name supplied', True)
5895	6712	sysvals.outdir = sysvals.setOutputFolder(val)
5896	6713	elif(arg == '-config'):
5897	6714	try:
5898		- val = args.next()
	6715	+ val = next(args)
5899	6716	except:
5900	6717	doError('No text file supplied', True)
5901	6718	file = sysvals.configFile(val)
..	..	@@ -5904,7 +6721,7 @@
5904	6721	configFromFile(file)
5905	6722	elif(arg == '-fadd'):
5906	6723	try:
5907		- val = args.next()
	6724	+ val = next(args)
5908	6725	except:
5909	6726	doError('No text file supplied', True)
5910	6727	file = sysvals.configFile(val)
..	..	@@ -5913,7 +6730,7 @@
5913	6730	sysvals.addFtraceFilterFunctions(file)
5914	6731	elif(arg == '-dmesg'):
5915	6732	try:
5916		- val = args.next()
	6733	+ val = next(args)
5917	6734	except:
5918	6735	doError('No dmesg file supplied', True)
5919	6736	sysvals.notestrun = True
..	..	@@ -5922,7 +6739,7 @@
5922	6739	doError('%s does not exist' % sysvals.dmesgfile)
5923	6740	elif(arg == '-ftrace'):
5924	6741	try:
5925		- val = args.next()
	6742	+ val = next(args)
5926	6743	except:
5927	6744	doError('No ftrace file supplied', True)
5928	6745	sysvals.notestrun = True
..	..	@@ -5931,7 +6748,7 @@
5931	6748	doError('%s does not exist' % sysvals.ftracefile)
5932	6749	elif(arg == '-summary'):
5933	6750	try:
5934		- val = args.next()
	6751	+ val = next(args)
5935	6752	except:
5936	6753	doError('No directory supplied', True)
5937	6754	cmd = 'summary'
..	..	@@ -5941,16 +6758,17 @@
5941	6758	doError('%s is not accesible' % val)
5942	6759	elif(arg == '-filter'):
5943	6760	try:
5944		- val = args.next()
	6761	+ val = next(args)
5945	6762	except:
5946	6763	doError('No devnames supplied', True)
5947	6764	sysvals.setDeviceFilter(val)
5948	6765	elif(arg == '-result'):
5949	6766	try:
5950		- val = args.next()
	6767	+ val = next(args)
5951	6768	except:
5952	6769	doError('No result file supplied', True)
5953	6770	sysvals.result = val
	6771	+ sysvals.signalHandlerInit()
5954	6772	else:
5955	6773	doError('Invalid argument: '+arg, True)
5956	6774
..	..	@@ -5975,43 +6793,56 @@
5975	6793
5976	6794	# just run a utility command and exit
5977	6795	if(cmd != ''):
	6796	+ ret = 0
5978	6797	if(cmd == 'status'):
5979		- statusCheck(True)
	6798	+ if not statusCheck(True):
	6799	+ ret = 1
5980	6800	elif(cmd == 'fpdt'):
5981		- getFPDT(True)
5982		- elif(cmd == 'battery'):
5983		- print 'AC Connect: %s\nCharge: %d' % getBattery()
	6801	+ if not getFPDT(True):
	6802	+ ret = 1
5984	6803	elif(cmd == 'sysinfo'):
5985	6804	sysvals.printSystemInfo(True)
5986	6805	elif(cmd == 'devinfo'):
5987	6806	deviceInfo()
5988	6807	elif(cmd == 'modes'):
5989		- print getModes()
	6808	+ pprint(getModes())
5990	6809	elif(cmd == 'flist'):
5991	6810	sysvals.getFtraceFilterFunctions(True)
5992	6811	elif(cmd == 'flistall'):
5993	6812	sysvals.getFtraceFilterFunctions(False)
5994	6813	elif(cmd == 'summary'):
5995	6814	runSummary(sysvals.outdir, True, genhtml)
5996		- sys.exit()
	6815	+ elif(cmd in ['xon', 'xoff', 'xstandby', 'xsuspend', 'xinit', 'xreset']):
	6816	+ sysvals.verbose = True
	6817	+ ret = displayControl(cmd[1:])
	6818	+ elif(cmd == 'xstat'):
	6819	+ pprint('Display Status: %s' % displayControl('stat').upper())
	6820	+ elif(cmd == 'wificheck'):
	6821	+ dev = sysvals.checkWifi()
	6822	+ if dev:
	6823	+ print('%s is connected' % sysvals.wifiDetails(dev))
	6824	+ else:
	6825	+ print('No wifi connection found')
	6826	+ elif(cmd == 'cmdinfo'):
	6827	+ for out in sysvals.cmdinfo(False, True):
	6828	+ print('[%s - %s]\n%s\n' % out)
	6829	+ sys.exit(ret)
5997	6830
5998	6831	# if instructed, re-analyze existing data files
5999	6832	if(sysvals.notestrun):
6000		- stamp = rerunTest()
	6833	+ stamp = rerunTest(sysvals.outdir)
6001	6834	sysvals.outputResult(stamp)
6002		- sys.exit()
	6835	+ sys.exit(0)
6003	6836
6004	6837	# verify that we can run a test
6005		- if(not statusCheck()):
6006		- doError('Check FAILED, aborting the test run!')
	6838	+ error = statusCheck()
	6839	+ if(error):
	6840	+ doError(error)
6007	6841
6008		- # extract mem modes and convert
	6842	+ # extract mem/disk extra modes and convert
6009	6843	mode = sysvals.suspendmode
6010		- if 'mem' == mode[:3]:
6011		- if '-' in mode:
6012		- memmode = mode.split('-')[-1]
6013		- else:
6014		- memmode = 'deep'
	6844	+ if mode.startswith('mem'):
	6845	+ memmode = mode.split('-', 1)[-1] if '-' in mode else 'deep'
6015	6846	if memmode == 'shallow':
6016	6847	mode = 'standby'
6017	6848	elif memmode == 's2idle':
..	..	@@ -6020,38 +6851,56 @@
6020	6851	mode = 'mem'
6021	6852	sysvals.memmode = memmode
6022	6853	sysvals.suspendmode = mode
	6854	+ if mode.startswith('disk-'):
	6855	+ sysvals.diskmode = mode.split('-', 1)[-1]
	6856	+ sysvals.suspendmode = 'disk'
6023	6857
6024	6858	sysvals.systemInfo(dmidecode(sysvals.mempath))
6025	6859
6026	6860	setRuntimeSuspend(True)
6027	6861	if sysvals.display:
6028		- call('xset -d :0.0 dpms 0 0 0', shell=True)
6029		- call('xset -d :0.0 s off', shell=True)
	6862	+ displayControl('init')
	6863	+ failcnt, ret = 0, 0
6030	6864	if sysvals.multitest['run']:
6031	6865	# run multiple tests in a separate subdirectory
6032	6866	if not sysvals.outdir:
6033		- s = 'suspend-x%d' % sysvals.multitest['count']
6034		- sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
	6867	+ if 'time' in sysvals.multitest:
	6868	+ s = '-%dm' % sysvals.multitest['time']
	6869	+ else:
	6870	+ s = '-x%d' % sysvals.multitest['count']
	6871	+ sysvals.outdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S'+s)
6035	6872	if not os.path.isdir(sysvals.outdir):
6036		- os.mkdir(sysvals.outdir)
	6873	+ os.makedirs(sysvals.outdir)
	6874	+ sysvals.sudoUserchown(sysvals.outdir)
	6875	+ finish = datetime.now()
	6876	+ if 'time' in sysvals.multitest:
	6877	+ finish += timedelta(minutes=sysvals.multitest['time'])
6037	6878	for i in range(sysvals.multitest['count']):
6038		- if(i != 0):
6039		- print('Waiting %d seconds...' % (sysvals.multitest['delay']))
	6879	+ sysvals.multistat(True, i, finish)
	6880	+ if i != 0 and sysvals.multitest['delay'] > 0:
	6881	+ pprint('Waiting %d seconds...' % (sysvals.multitest['delay']))
6040	6882	time.sleep(sysvals.multitest['delay'])
6041		- print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count']))
6042	6883	fmt = 'suspend-%y%m%d-%H%M%S'
6043	6884	sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
6044		- runTest(i+1)
6045		- print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
6046		- sysvals.logmsg = ''
	6885	+ ret = runTest(i+1, True)
	6886	+ failcnt = 0 if not ret else failcnt + 1
	6887	+ if sysvals.maxfail > 0 and failcnt >= sysvals.maxfail:
	6888	+ pprint('Maximum fail count of %d reached, aborting multitest' % (sysvals.maxfail))
	6889	+ break
	6890	+ time.sleep(5)
	6891	+ sysvals.resetlog()
	6892	+ sysvals.multistat(False, i, finish)
	6893	+ if 'time' in sysvals.multitest and datetime.now() >= finish:
	6894	+ break
6047	6895	if not sysvals.skiphtml:
6048	6896	runSummary(sysvals.outdir, False, False)
6049		- sysvals.sudouser(sysvals.outdir)
	6897	+ sysvals.sudoUserchown(sysvals.outdir)
6050	6898	else:
6051	6899	if sysvals.outdir:
6052	6900	sysvals.testdir = sysvals.outdir
6053	6901	# run the test in the current directory
6054		- runTest()
	6902	+ ret = runTest()
6055	6903	if sysvals.display:
6056		- call('xset -d :0.0 s reset', shell=True)
	6904	+ displayControl('reset')
6057	6905	setRuntimeSuspend(False)
	6906	+ sys.exit(ret)