aboutsummaryrefslogtreecommitdiffstats
path: root/scripts
diff options
context:
space:
mode:
authorLinus Torvalds <torvalds@linux-foundation.org>2016-07-26 20:29:07 -0400
committerLinus Torvalds <torvalds@linux-foundation.org>2016-07-26 20:29:07 -0400
commit6453dbdda30428a3c56568c96fe70ea3612f07e2 (patch)
tree9a3c6087a2832c36e8c49296fb05f95b877e0111 /scripts
parent27b79027bc112a63ad4004eb83c6acacae08a0de (diff)
parentbc841e260c95608921809a2c7481cf6f03bec21a (diff)
Merge tag 'pm-4.8-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
Pull power management updates from Rafael Wysocki: "Again, the majority of changes go into the cpufreq subsystem, but there are no big features this time. The cpufreq changes that stand out somewhat are the governor interface rework and improvements related to the handling of frequency tables. Apart from those, there are fixes and new device/CPU IDs in drivers, cleanups and an improvement of the new schedutil governor. Next, there are some changes in the hibernation core, including a fix for a nasty problem related to the MONITOR/MWAIT usage by CPU offline during resume from hibernation, a few core improvements related to memory management during resume, a couple of additional debug features and cleanups. Finally, we have some fixes and cleanups in the devfreq subsystem, generic power domains framework improvements related to system suspend/resume, support for some new chips in intel_idle and in the power capping RAPL driver, a new version of the AnalyzeSuspend utility and some assorted fixes and cleanups. Specifics: - Rework the cpufreq governor interface to make it more straightforward and modify the conservative governor to avoid using transition notifications (Rafael Wysocki). - Rework the handling of frequency tables by the cpufreq core to make it more efficient (Viresh Kumar). - Modify the schedutil governor to reduce the number of wakeups it causes to occur in cases when the CPU frequency doesn't need to be changed (Steve Muckle, Viresh Kumar). - Fix some minor issues and clean up code in the cpufreq core and governors (Rafael Wysocki, Viresh Kumar). - Add Intel Broxton support to the intel_pstate driver (Srinivas Pandruvada). - Fix problems related to the config TDP feature and to the validity of the MSR_HWP_INTERRUPT register in intel_pstate (Jan Kiszka, Srinivas Pandruvada). - Make intel_pstate update the cpu_frequency tracepoint even if the frequency doesn't change to avoid confusing powertop (Rafael Wysocki). - Clean up the usage of __init/__initdata in intel_pstate, mark some of its internal variables as __read_mostly and drop an unused structure element from it (Jisheng Zhang, Carsten Emde). - Clean up the usage of some duplicate MSR symbols in intel_pstate and turbostat (Srinivas Pandruvada). - Update/fix the powernv, s3c24xx and mvebu cpufreq drivers (Akshay Adiga, Viresh Kumar, Ben Dooks). - Fix a regression (introduced during the 4.5 cycle) in the pcc-cpufreq driver by reverting the problematic commit (Andreas Herrmann). - Add support for Intel Denverton to intel_idle, clean up Broxton support in it and make it explicitly non-modular (Jacob Pan, Jan Beulich, Paul Gortmaker). - Add support for Denverton and Ivy Bridge server to the Intel RAPL power capping driver and make it more careful about the handing of MSRs that may not be present (Jacob Pan, Xiaolong Wang). - Fix resume from hibernation on x86-64 by making the CPU offline during resume avoid using MONITOR/MWAIT in the "play dead" loop which may lead to an inadvertent "revival" of a "dead" CPU and a page fault leading to a kernel crash from it (Rafael Wysocki). - Make memory management during resume from hibernation more straightforward (Rafael Wysocki). - Add debug features that should help to detect problems related to hibernation and resume from it (Rafael Wysocki, Chen Yu). - Clean up hibernation core somewhat (Rafael Wysocki). - Prevent KASAN from instrumenting the hibernation core which leads to large numbers of false-positives from it (James Morse). - Prevent PM (hibernate and suspend) notifiers from being called during the cleanup phase if they have not been called during the corresponding preparation phase which is possible if one of the other notifiers returns an error at that time (Lianwei Wang). - Improve suspend-related debug printout in the tasks freezer and clean up suspend-related console handling (Roger Lu, Borislav Petkov). - Update the AnalyzeSuspend script in the kernel sources to version 4.2 (Todd Brandt). - Modify the generic power domains framework to make it handle system suspend/resume better (Ulf Hansson). - Make the runtime PM framework avoid resuming devices synchronously when user space changes the runtime PM settings for them and improve its error reporting (Rafael Wysocki, Linus Walleij). - Fix error paths in devfreq drivers (exynos, exynos-ppmu, exynos-bus) and in the core, make some devfreq code explicitly non-modular and change some of it into tristate (Bartlomiej Zolnierkiewicz, Peter Chen, Paul Gortmaker). - Add DT support to the generic PM clocks management code and make it export some more symbols (Jon Hunter, Paul Gortmaker). - Make the PCI PM core code slightly more robust against possible driver errors (Andy Shevchenko). - Make it possible to change DESTDIR and PREFIX in turbostat (Andy Shevchenko)" * tag 'pm-4.8-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm: (89 commits) Revert "cpufreq: pcc-cpufreq: update default value of cpuinfo_transition_latency" PM / hibernate: Introduce test_resume mode for hibernation cpufreq: export cpufreq_driver_resolve_freq() cpufreq: Disallow ->resolve_freq() for drivers providing ->target_index() PCI / PM: check all fields in pci_set_platform_pm() cpufreq: acpi-cpufreq: use cached frequency mapping when possible cpufreq: schedutil: map raw required frequency to driver frequency cpufreq: add cpufreq_driver_resolve_freq() cpufreq: intel_pstate: Check cpuid for MSR_HWP_INTERRUPT intel_pstate: Update cpu_frequency tracepoint every time cpufreq: intel_pstate: clean remnant struct element PM / tools: scripts: AnalyzeSuspend v4.2 x86 / hibernate: Use hlt_play_dead() when resuming from hibernation cpufreq: powernv: Replacing pstate_id with frequency table index intel_pstate: Fix MSR_CONFIG_TDP_x addressing in core_get_max_pstate() PM / hibernate: Image data protection during restoration PM / hibernate: Add missing braces in __register_nosave_region() PM / hibernate: Clean up comments in snapshot.c PM / hibernate: Clean up function headers in snapshot.c PM / hibernate: Add missing braces in hibernate_setup() ...
Diffstat (limited to 'scripts')
-rwxr-xr-xscripts/analyze_suspend.py3641
1 files changed, 2474 insertions, 1167 deletions
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index 93e1fd40f430..a0ba48fa2c5e 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -19,6 +19,17 @@
19# Authors: 19# Authors:
20# Todd Brandt <todd.e.brandt@linux.intel.com> 20# Todd Brandt <todd.e.brandt@linux.intel.com>
21# 21#
22# Links:
23# Home Page
24# https://01.org/suspendresume
25# Source repo
26# https://github.com/01org/suspendresume
27# Documentation
28# Getting Started
29# https://01.org/suspendresume/documentation/getting-started
30# Command List:
31# https://01.org/suspendresume/documentation/command-list
32#
22# Description: 33# Description:
23# This tool is designed to assist kernel and OS developers in optimizing 34# This tool is designed to assist kernel and OS developers in optimizing
24# their linux stack's suspend/resume time. Using a kernel image built 35# their linux stack's suspend/resume time. Using a kernel image built
@@ -35,6 +46,8 @@
35# CONFIG_FTRACE=y 46# CONFIG_FTRACE=y
36# CONFIG_FUNCTION_TRACER=y 47# CONFIG_FUNCTION_TRACER=y
37# CONFIG_FUNCTION_GRAPH_TRACER=y 48# CONFIG_FUNCTION_GRAPH_TRACER=y
49# CONFIG_KPROBES=y
50# CONFIG_KPROBES_ON_FTRACE=y
38# 51#
39# For kernel versions older than 3.15: 52# For kernel versions older than 3.15:
40# The following additional kernel parameters are required: 53# The following additional kernel parameters are required:
@@ -52,6 +65,7 @@ import re
52import platform 65import platform
53from datetime import datetime 66from datetime import datetime
54import struct 67import struct
68import ConfigParser
55 69
56# ----------------- CLASSES -------------------- 70# ----------------- CLASSES --------------------
57 71
@@ -60,8 +74,15 @@ import struct
60# A global, single-instance container used to 74# A global, single-instance container used to
61# store system values and test parameters 75# store system values and test parameters
62class SystemValues: 76class SystemValues:
63 version = 3.0 77 ansi = False
78 version = '4.2'
64 verbose = False 79 verbose = False
80 addlogs = False
81 mindevlen = 0.001
82 mincglen = 1.0
83 srgap = 0
84 cgexp = False
85 outdir = ''
65 testdir = '.' 86 testdir = '.'
66 tpath = '/sys/kernel/debug/tracing/' 87 tpath = '/sys/kernel/debug/tracing/'
67 fpdtpath = '/sys/firmware/acpi/tables/FPDT' 88 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
@@ -71,26 +92,21 @@ class SystemValues:
71 'device_pm_callback_end', 92 'device_pm_callback_end',
72 'device_pm_callback_start' 93 'device_pm_callback_start'
73 ] 94 ]
74 modename = { 95 testcommand = ''
75 'freeze': 'Suspend-To-Idle (S0)',
76 'standby': 'Power-On Suspend (S1)',
77 'mem': 'Suspend-to-RAM (S3)',
78 'disk': 'Suspend-to-disk (S4)'
79 }
80 mempath = '/dev/mem' 96 mempath = '/dev/mem'
81 powerfile = '/sys/power/state' 97 powerfile = '/sys/power/state'
82 suspendmode = 'mem' 98 suspendmode = 'mem'
83 hostname = 'localhost' 99 hostname = 'localhost'
84 prefix = 'test' 100 prefix = 'test'
85 teststamp = '' 101 teststamp = ''
102 dmesgstart = 0.0
86 dmesgfile = '' 103 dmesgfile = ''
87 ftracefile = '' 104 ftracefile = ''
88 htmlfile = '' 105 htmlfile = ''
106 embedded = False
89 rtcwake = False 107 rtcwake = False
90 rtcwaketime = 10 108 rtcwaketime = 10
91 rtcpath = '' 109 rtcpath = ''
92 android = False
93 adb = 'adb'
94 devicefilter = [] 110 devicefilter = []
95 stamp = 0 111 stamp = 0
96 execcount = 1 112 execcount = 1
@@ -98,16 +114,90 @@ class SystemValues:
98 usecallgraph = False 114 usecallgraph = False
99 usetraceevents = False 115 usetraceevents = False
100 usetraceeventsonly = False 116 usetraceeventsonly = False
117 usetracemarkers = True
118 usekprobes = True
119 usedevsrc = False
101 notestrun = False 120 notestrun = False
102 altdevname = dict() 121 devprops = dict()
103 postresumetime = 0 122 postresumetime = 0
123 devpropfmt = '# Device Properties: .*'
104 tracertypefmt = '# tracer: (?P<t>.*)' 124 tracertypefmt = '# tracer: (?P<t>.*)'
105 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' 125 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
106 postresumefmt = '# post resume time (?P<t>[0-9]*)$' 126 postresumefmt = '# post resume time (?P<t>[0-9]*)$'
107 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ 127 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
108 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ 128 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
109 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' 129 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
130 kprobecolor = 'rgba(204,204,204,0.5)'
131 synccolor = 'rgba(204,204,204,0.5)'
132 debugfuncs = []
133 tracefuncs = {
134 'sys_sync': dict(),
135 'pm_prepare_console': dict(),
136 'pm_notifier_call_chain': dict(),
137 'freeze_processes': dict(),
138 'freeze_kernel_threads': dict(),
139 'pm_restrict_gfp_mask': dict(),
140 'acpi_suspend_begin': dict(),
141 'suspend_console': dict(),
142 'acpi_pm_prepare': dict(),
143 'syscore_suspend': dict(),
144 'arch_enable_nonboot_cpus_end': dict(),
145 'syscore_resume': dict(),
146 'acpi_pm_finish': dict(),
147 'resume_console': dict(),
148 'acpi_pm_end': dict(),
149 'pm_restore_gfp_mask': dict(),
150 'thaw_processes': dict(),
151 'pm_restore_console': dict(),
152 'CPU_OFF': {
153 'func':'_cpu_down',
154 'args_x86_64': {'cpu':'%di:s32'},
155 'format': 'CPU_OFF[{cpu}]',
156 'mask': 'CPU_.*_DOWN'
157 },
158 'CPU_ON': {
159 'func':'_cpu_up',
160 'args_x86_64': {'cpu':'%di:s32'},
161 'format': 'CPU_ON[{cpu}]',
162 'mask': 'CPU_.*_UP'
163 },
164 }
165 dev_tracefuncs = {
166 # general wait/delay/sleep
167 'msleep': { 'args_x86_64': {'time':'%di:s32'} },
168 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} },
169 'acpi_os_stall': dict(),
170 # ACPI
171 'acpi_resume_power_resources': dict(),
172 'acpi_ps_parse_aml': dict(),
173 # filesystem
174 'ext4_sync_fs': dict(),
175 # ATA
176 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
177 # i915
178 'i915_gem_restore_gtt_mappings': dict(),
179 'intel_opregion_setup': dict(),
180 'intel_dp_detect': dict(),
181 'intel_hdmi_detect': dict(),
182 'intel_opregion_init': dict(),
183 }
184 kprobes_postresume = [
185 {
186 'name': 'ataportrst',
187 'func': 'ata_eh_recover',
188 'args': {'port':'+36(%di):s32'},
189 'format': 'ata{port}_port_reset',
190 'mask': 'ata.*_port_reset'
191 }
192 ]
193 kprobes = dict()
194 timeformat = '%.3f'
110 def __init__(self): 195 def __init__(self):
196 # if this is a phoronix test run, set some default options
197 if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
198 self.embedded = True
199 self.addlogs = True
200 self.htmlfile = os.environ['LOG_FILE']
111 self.hostname = platform.node() 201 self.hostname = platform.node()
112 if(self.hostname == ''): 202 if(self.hostname == ''):
113 self.hostname = 'localhost' 203 self.hostname = 'localhost'
@@ -118,6 +208,12 @@ class SystemValues:
118 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \ 208 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
119 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'): 209 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
120 self.rtcpath = rtc 210 self.rtcpath = rtc
211 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
212 self.ansi = True
213 def setPrecision(self, num):
214 if num < 0 or num > 6:
215 return
216 self.timeformat = '%.{0}f'.format(num)
121 def setOutputFile(self): 217 def setOutputFile(self):
122 if((self.htmlfile == '') and (self.dmesgfile != '')): 218 if((self.htmlfile == '') and (self.dmesgfile != '')):
123 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) 219 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
@@ -129,32 +225,37 @@ class SystemValues:
129 self.htmlfile = m.group('name')+'.html' 225 self.htmlfile = m.group('name')+'.html'
130 if(self.htmlfile == ''): 226 if(self.htmlfile == ''):
131 self.htmlfile = 'output.html' 227 self.htmlfile = 'output.html'
132 def initTestOutput(self, subdir): 228 def initTestOutput(self, subdir, testpath=''):
133 if(not self.android): 229 self.prefix = self.hostname
134 self.prefix = self.hostname 230 v = open('/proc/version', 'r').read().strip()
135 v = open('/proc/version', 'r').read().strip() 231 kver = string.split(v)[2]
136 kver = string.split(v)[2] 232 n = datetime.now()
137 else: 233 testtime = n.strftime('suspend-%m%d%y-%H%M%S')
138 self.prefix = 'android' 234 if not testpath:
139 v = os.popen(self.adb+' shell cat /proc/version').read().strip() 235 testpath = n.strftime('suspend-%y%m%d-%H%M%S')
140 kver = string.split(v)[2]
141 testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S')
142 if(subdir != "."): 236 if(subdir != "."):
143 self.testdir = subdir+"/"+testtime 237 self.testdir = subdir+"/"+testpath
144 else: 238 else:
145 self.testdir = testtime 239 self.testdir = testpath
146 self.teststamp = \ 240 self.teststamp = \
147 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver 241 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
242 if(self.embedded):
243 self.dmesgfile = \
244 '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'
245 self.ftracefile = \
246 '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
247 return
148 self.dmesgfile = \ 248 self.dmesgfile = \
149 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' 249 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
150 self.ftracefile = \ 250 self.ftracefile = \
151 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' 251 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
152 self.htmlfile = \ 252 self.htmlfile = \
153 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' 253 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
154 os.mkdir(self.testdir) 254 if not os.path.isdir(self.testdir):
255 os.mkdir(self.testdir)
155 def setDeviceFilter(self, devnames): 256 def setDeviceFilter(self, devnames):
156 self.devicefilter = string.split(devnames) 257 self.devicefilter = string.split(devnames)
157 def rtcWakeAlarm(self): 258 def rtcWakeAlarmOn(self):
158 os.system('echo 0 > '+self.rtcpath+'/wakealarm') 259 os.system('echo 0 > '+self.rtcpath+'/wakealarm')
159 outD = open(self.rtcpath+'/date', 'r').read().strip() 260 outD = open(self.rtcpath+'/date', 'r').read().strip()
160 outT = open(self.rtcpath+'/time', 'r').read().strip() 261 outT = open(self.rtcpath+'/time', 'r').read().strip()
@@ -172,9 +273,361 @@ class SystemValues:
172 nowtime = int(datetime.now().strftime('%s')) 273 nowtime = int(datetime.now().strftime('%s'))
173 alarm = nowtime + self.rtcwaketime 274 alarm = nowtime + self.rtcwaketime
174 os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath)) 275 os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
276 def rtcWakeAlarmOff(self):
277 os.system('echo 0 > %s/wakealarm' % self.rtcpath)
278 def initdmesg(self):
279 # get the latest time stamp from the dmesg log
280 fp = os.popen('dmesg')
281 ktime = '0'
282 for line in fp:
283 line = line.replace('\r\n', '')
284 idx = line.find('[')
285 if idx > 1:
286 line = line[idx:]
287 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
288 if(m):
289 ktime = m.group('ktime')
290 fp.close()
291 self.dmesgstart = float(ktime)
292 def getdmesg(self):
293 # store all new dmesg lines since initdmesg was called
294 fp = os.popen('dmesg')
295 op = open(self.dmesgfile, 'a')
296 for line in fp:
297 line = line.replace('\r\n', '')
298 idx = line.find('[')
299 if idx > 1:
300 line = line[idx:]
301 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
302 if(not m):
303 continue
304 ktime = float(m.group('ktime'))
305 if ktime > self.dmesgstart:
306 op.write(line)
307 fp.close()
308 op.close()
309 def addFtraceFilterFunctions(self, file):
310 fp = open(file)
311 list = fp.read().split('\n')
312 fp.close()
313 for i in list:
314 if len(i) < 2:
315 continue
316 self.tracefuncs[i] = dict()
317 def getFtraceFilterFunctions(self, current):
318 rootCheck(True)
319 if not current:
320 os.system('cat '+self.tpath+'available_filter_functions')
321 return
322 fp = open(self.tpath+'available_filter_functions')
323 master = fp.read().split('\n')
324 fp.close()
325 if len(self.debugfuncs) > 0:
326 for i in self.debugfuncs:
327 if i in master:
328 print i
329 else:
330 print self.colorText(i)
331 else:
332 for i in self.tracefuncs:
333 if 'func' in self.tracefuncs[i]:
334 i = self.tracefuncs[i]['func']
335 if i in master:
336 print i
337 else:
338 print self.colorText(i)
339 def setFtraceFilterFunctions(self, list):
340 fp = open(self.tpath+'available_filter_functions')
341 master = fp.read().split('\n')
342 fp.close()
343 flist = ''
344 for i in list:
345 if i not in master:
346 continue
347 if ' [' in i:
348 flist += i.split(' ')[0]+'\n'
349 else:
350 flist += i+'\n'
351 fp = open(self.tpath+'set_graph_function', 'w')
352 fp.write(flist)
353 fp.close()
354 def kprobeMatch(self, name, target):
355 if name not in self.kprobes:
356 return False
357 if re.match(self.kprobes[name]['mask'], target):
358 return True
359 return False
360 def basicKprobe(self, name):
361 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name,'mask': name}
362 def defaultKprobe(self, name, kdata):
363 k = kdata
364 for field in ['name', 'format', 'mask', 'func']:
365 if field not in k:
366 k[field] = name
367 archargs = 'args_'+platform.machine()
368 if archargs in k:
369 k['args'] = k[archargs]
370 else:
371 k['args'] = dict()
372 k['format'] = name
373 self.kprobes[name] = k
374 def kprobeColor(self, name):
375 if name not in self.kprobes or 'color' not in self.kprobes[name]:
376 return ''
377 return self.kprobes[name]['color']
378 def kprobeDisplayName(self, name, dataraw):
379 if name not in self.kprobes:
380 self.basicKprobe(name)
381 data = ''
382 quote=0
383 # first remvoe any spaces inside quotes, and the quotes
384 for c in dataraw:
385 if c == '"':
386 quote = (quote + 1) % 2
387 if quote and c == ' ':
388 data += '_'
389 elif c != '"':
390 data += c
391 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
392 arglist = dict()
393 # now process the args
394 for arg in sorted(args):
395 arglist[arg] = ''
396 m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
397 if m:
398 arglist[arg] = m.group('arg')
399 else:
400 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
401 if m:
402 arglist[arg] = m.group('arg')
403 out = fmt.format(**arglist)
404 out = out.replace(' ', '_').replace('"', '')
405 return out
406 def kprobeText(self, kprobe):
407 name, fmt, func, args = kprobe['name'], kprobe['format'], kprobe['func'], kprobe['args']
408 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
409 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func), False)
410 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
411 if arg not in args:
412 doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
413 val = 'p:%s_cal %s' % (name, func)
414 for i in sorted(args):
415 val += ' %s=%s' % (i, args[i])
416 val += '\nr:%s_ret %s $retval\n' % (name, func)
417 return val
418 def addKprobes(self):
419 # first test each kprobe
420 print('INITIALIZING KPROBES...')
421 rejects = []
422 for name in sorted(self.kprobes):
423 if not self.testKprobe(self.kprobes[name]):
424 rejects.append(name)
425 # remove all failed ones from the list
426 for name in rejects:
427 vprint('Skipping KPROBE: %s' % name)
428 self.kprobes.pop(name)
429 self.fsetVal('', 'kprobe_events')
430 kprobeevents = ''
431 # set the kprobes all at once
432 for kp in self.kprobes:
433 val = self.kprobeText(self.kprobes[kp])
434 vprint('Adding KPROBE: %s\n%s' % (kp, val.strip()))
435 kprobeevents += self.kprobeText(self.kprobes[kp])
436 self.fsetVal(kprobeevents, 'kprobe_events')
437 # verify that the kprobes were set as ordered
438 check = self.fgetVal('kprobe_events')
439 linesout = len(kprobeevents.split('\n'))
440 linesack = len(check.split('\n'))
441 if linesack < linesout:
442 # if not, try appending the kprobes 1 by 1
443 for kp in self.kprobes:
444 kprobeevents = self.kprobeText(self.kprobes[kp])
445 self.fsetVal(kprobeevents, 'kprobe_events', 'a')
446 self.fsetVal('1', 'events/kprobes/enable')
447 def testKprobe(self, kprobe):
448 kprobeevents = self.kprobeText(kprobe)
449 if not kprobeevents:
450 return False
451 try:
452 self.fsetVal(kprobeevents, 'kprobe_events')
453 check = self.fgetVal('kprobe_events')
454 except:
455 return False
456 linesout = len(kprobeevents.split('\n'))
457 linesack = len(check.split('\n'))
458 if linesack < linesout:
459 return False
460 return True
461 def fsetVal(self, val, path, mode='w'):
462 file = self.tpath+path
463 if not os.path.exists(file):
464 return False
465 try:
466 fp = open(file, mode)
467 fp.write(val)
468 fp.close()
469 except:
470 pass
471 return True
472 def fgetVal(self, path):
473 file = self.tpath+path
474 res = ''
475 if not os.path.exists(file):
476 return res
477 try:
478 fp = open(file, 'r')
479 res = fp.read()
480 fp.close()
481 except:
482 pass
483 return res
484 def cleanupFtrace(self):
485 if(self.usecallgraph or self.usetraceevents):
486 self.fsetVal('0', 'events/kprobes/enable')
487 self.fsetVal('', 'kprobe_events')
488 def setupAllKprobes(self):
489 for name in self.tracefuncs:
490 self.defaultKprobe(name, self.tracefuncs[name])
491 for name in self.dev_tracefuncs:
492 self.defaultKprobe(name, self.dev_tracefuncs[name])
493 def isCallgraphFunc(self, name):
494 if len(self.debugfuncs) < 1 and self.suspendmode == 'command':
495 return True
496 if name in self.debugfuncs:
497 return True
498 funclist = []
499 for i in self.tracefuncs:
500 if 'func' in self.tracefuncs[i]:
501 funclist.append(self.tracefuncs[i]['func'])
502 else:
503 funclist.append(i)
504 if name in funclist:
505 return True
506 return False
507 def initFtrace(self, testing=False):
508 tp = self.tpath
509 print('INITIALIZING FTRACE...')
510 # turn trace off
511 self.fsetVal('0', 'tracing_on')
512 self.cleanupFtrace()
513 # set the trace clock to global
514 self.fsetVal('global', 'trace_clock')
515 # set trace buffer to a huge value
516 self.fsetVal('nop', 'current_tracer')
517 self.fsetVal('100000', 'buffer_size_kb')
518 # go no further if this is just a status check
519 if testing:
520 return
521 if self.usekprobes:
522 # add tracefunc kprobes so long as were not using full callgraph
523 if(not self.usecallgraph or len(self.debugfuncs) > 0):
524 for name in self.tracefuncs:
525 self.defaultKprobe(name, self.tracefuncs[name])
526 if self.usedevsrc:
527 for name in self.dev_tracefuncs:
528 self.defaultKprobe(name, self.dev_tracefuncs[name])
529 else:
530 self.usedevsrc = False
531 self.addKprobes()
532 # initialize the callgraph trace, unless this is an x2 run
533 if(self.usecallgraph):
534 # set trace type
535 self.fsetVal('function_graph', 'current_tracer')
536 self.fsetVal('', 'set_ftrace_filter')
537 # set trace format options
538 self.fsetVal('print-parent', 'trace_options')
539 self.fsetVal('funcgraph-abstime', 'trace_options')
540 self.fsetVal('funcgraph-cpu', 'trace_options')
541 self.fsetVal('funcgraph-duration', 'trace_options')
542 self.fsetVal('funcgraph-proc', 'trace_options')
543 self.fsetVal('funcgraph-tail', 'trace_options')
544 self.fsetVal('nofuncgraph-overhead', 'trace_options')
545 self.fsetVal('context-info', 'trace_options')
546 self.fsetVal('graph-time', 'trace_options')
547 self.fsetVal('0', 'max_graph_depth')
548 if len(self.debugfuncs) > 0:
549 self.setFtraceFilterFunctions(self.debugfuncs)
550 elif self.suspendmode == 'command':
551 self.fsetVal('', 'set_graph_function')
552 else:
553 cf = ['dpm_run_callback']
554 if(self.usetraceeventsonly):
555 cf += ['dpm_prepare', 'dpm_complete']
556 for fn in self.tracefuncs:
557 if 'func' in self.tracefuncs[fn]:
558 cf.append(self.tracefuncs[fn]['func'])
559 else:
560 cf.append(fn)
561 self.setFtraceFilterFunctions(cf)
562 if(self.usetraceevents):
563 # turn trace events on
564 events = iter(self.traceevents)
565 for e in events:
566 self.fsetVal('1', 'events/power/'+e+'/enable')
567 # clear the trace buffer
568 self.fsetVal('', 'trace')
569 def verifyFtrace(self):
570 # files needed for any trace data
571 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
572 'trace_marker', 'trace_options', 'tracing_on']
573 # files needed for callgraph trace data
574 tp = self.tpath
575 if(self.usecallgraph):
576 files += [
577 'available_filter_functions',
578 'set_ftrace_filter',
579 'set_graph_function'
580 ]
581 for f in files:
582 if(os.path.exists(tp+f) == False):
583 return False
584 return True
585 def verifyKprobes(self):
586 # files needed for kprobes to work
587 files = ['kprobe_events', 'events']
588 tp = self.tpath
589 for f in files:
590 if(os.path.exists(tp+f) == False):
591 return False
592 return True
593 def colorText(self, str):
594 if not self.ansi:
595 return str
596 return '\x1B[31;40m'+str+'\x1B[m'
175 597
176sysvals = SystemValues() 598sysvals = SystemValues()
177 599
600# Class: DevProps
601# Description:
602# Simple class which holds property values collected
603# for all the devices used in the timeline.
604class DevProps:
605 syspath = ''
606 altname = ''
607 async = True
608 xtraclass = ''
609 xtrainfo = ''
610 def out(self, dev):
611 return '%s,%s,%d;' % (dev, self.altname, self.async)
612 def debug(self, dev):
613 print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)
614 def altName(self, dev):
615 if not self.altname or self.altname == dev:
616 return dev
617 return '%s [%s]' % (self.altname, dev)
618 def xtraClass(self):
619 if self.xtraclass:
620 return ' '+self.xtraclass
621 if not self.async:
622 return ' sync'
623 return ''
624 def xtraInfo(self):
625 if self.xtraclass:
626 return ' '+self.xtraclass
627 if self.async:
628 return ' async'
629 return ' sync'
630
178# Class: DeviceNode 631# Class: DeviceNode
179# Description: 632# Description:
180# A container used to create a device hierachy, with a single root node 633# A container used to create a device hierachy, with a single root node
@@ -228,6 +681,7 @@ class Data:
228 html_device_id = 0 681 html_device_id = 0
229 stamp = 0 682 stamp = 0
230 outfile = '' 683 outfile = ''
684 dev_ubiquitous = ['msleep', 'udelay']
231 def __init__(self, num): 685 def __init__(self, num):
232 idchar = 'abcdefghijklmnopqrstuvwxyz' 686 idchar = 'abcdefghijklmnopqrstuvwxyz'
233 self.testnumber = num 687 self.testnumber = num
@@ -257,6 +711,9 @@ class Data:
257 'row': 0, 'color': '#FFFFCC', 'order': 9} 711 'row': 0, 'color': '#FFFFCC', 'order': 9}
258 } 712 }
259 self.phases = self.sortedPhases() 713 self.phases = self.sortedPhases()
714 self.devicegroups = []
715 for phase in self.phases:
716 self.devicegroups.append([phase])
260 def getStart(self): 717 def getStart(self):
261 return self.dmesg[self.phases[0]]['start'] 718 return self.dmesg[self.phases[0]]['start']
262 def setStart(self, time): 719 def setStart(self, time):
@@ -273,51 +730,61 @@ class Data:
273 for dev in list: 730 for dev in list:
274 d = list[dev] 731 d = list[dev]
275 if(d['pid'] == pid and time >= d['start'] and 732 if(d['pid'] == pid and time >= d['start'] and
276 time <= d['end']): 733 time < d['end']):
277 return False 734 return False
278 return True 735 return True
279 def addIntraDevTraceEvent(self, action, name, pid, time): 736 def targetDevice(self, phaselist, start, end, pid=-1):
280 if(action == 'mutex_lock_try'): 737 tgtdev = ''
281 color = 'red' 738 for phase in phaselist:
282 elif(action == 'mutex_lock_pass'):
283 color = 'green'
284 elif(action == 'mutex_unlock'):
285 color = 'blue'
286 else:
287 # create separate colors based on the name
288 v1 = len(name)*10 % 256
289 v2 = string.count(name, 'e')*100 % 256
290 v3 = ord(name[0])*20 % 256
291 color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3)
292 for phase in self.phases:
293 list = self.dmesg[phase]['list']
294 for dev in list:
295 d = list[dev]
296 if(d['pid'] == pid and time >= d['start'] and
297 time <= d['end']):
298 e = TraceEvent(action, name, color, time)
299 if('traceevents' not in d):
300 d['traceevents'] = []
301 d['traceevents'].append(e)
302 return d
303 break
304 return 0
305 def capIntraDevTraceEvent(self, action, name, pid, time):
306 for phase in self.phases:
307 list = self.dmesg[phase]['list'] 739 list = self.dmesg[phase]['list']
308 for dev in list: 740 for devname in list:
309 d = list[dev] 741 dev = list[devname]
310 if(d['pid'] == pid and time >= d['start'] and 742 if(pid >= 0 and dev['pid'] != pid):
311 time <= d['end']): 743 continue
312 if('traceevents' not in d): 744 devS = dev['start']
313 return 745 devE = dev['end']
314 for e in d['traceevents']: 746 if(start < devS or start >= devE or end <= devS or end > devE):
315 if(e.action == action and 747 continue
316 e.name == name and not e.ready): 748 tgtdev = dev
317 e.length = time - e.time 749 break
318 e.ready = True 750 return tgtdev
319 break 751 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
320 return 752 machstart = self.dmesg['suspend_machine']['start']
753 machend = self.dmesg['resume_machine']['end']
754 tgtdev = self.targetDevice(self.phases, start, end, pid)
755 if not tgtdev and start >= machstart and end < machend:
756 # device calls in machine phases should be serial
757 tgtdev = self.targetDevice(['suspend_machine', 'resume_machine'], start, end)
758 if not tgtdev:
759 if 'scsi_eh' in proc:
760 self.newActionGlobal(proc, start, end, pid)
761 self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
762 else:
763 vprint('IGNORE: %s[%s](%d) [%f - %f] | %s | %s | %s' % (displayname, kprobename,
764 pid, start, end, cdata, rdata, proc))
765 return False
766 # detail block fits within tgtdev
767 if('src' not in tgtdev):
768 tgtdev['src'] = []
769 title = cdata+' '+rdata
770 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
771 m = re.match(mstr, title)
772 if m:
773 c = m.group('caller')
774 a = m.group('args').strip()
775 r = m.group('ret')
776 if len(r) > 6:
777 r = ''
778 else:
779 r = 'ret=%s ' % r
780 l = '%0.3fms' % ((end - start) * 1000)
781 if kprobename in self.dev_ubiquitous:
782 title = '%s(%s) <- %s, %s(%s)' % (displayname, a, c, r, l)
783 else:
784 title = '%s(%s) %s(%s)' % (displayname, a, r, l)
785 e = TraceEvent(title, kprobename, start, end - start)
786 tgtdev['src'].append(e)
787 return True
321 def trimTimeVal(self, t, t0, dT, left): 788 def trimTimeVal(self, t, t0, dT, left):
322 if left: 789 if left:
323 if(t > t0): 790 if(t > t0):
@@ -353,11 +820,11 @@ class Data:
353 cg.end = self.trimTimeVal(cg.end, t0, dT, left) 820 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
354 for line in cg.list: 821 for line in cg.list:
355 line.time = self.trimTimeVal(line.time, t0, dT, left) 822 line.time = self.trimTimeVal(line.time, t0, dT, left)
356 if('traceevents' in d): 823 if('src' in d):
357 for e in d['traceevents']: 824 for e in d['src']:
358 e.time = self.trimTimeVal(e.time, t0, dT, left) 825 e.time = self.trimTimeVal(e.time, t0, dT, left)
359 def normalizeTime(self, tZero): 826 def normalizeTime(self, tZero):
360 # first trim out any standby or freeze clock time 827 # trim out any standby or freeze clock time
361 if(self.tSuspended != self.tResumed): 828 if(self.tSuspended != self.tResumed):
362 if(self.tResumed > tZero): 829 if(self.tResumed > tZero):
363 self.trimTime(self.tSuspended, \ 830 self.trimTime(self.tSuspended, \
@@ -365,29 +832,6 @@ class Data:
365 else: 832 else:
366 self.trimTime(self.tSuspended, \ 833 self.trimTime(self.tSuspended, \
367 self.tResumed-self.tSuspended, False) 834 self.tResumed-self.tSuspended, False)
368 # shift the timeline so that tZero is the new 0
369 self.tSuspended -= tZero
370 self.tResumed -= tZero
371 self.start -= tZero
372 self.end -= tZero
373 for phase in self.phases:
374 p = self.dmesg[phase]
375 p['start'] -= tZero
376 p['end'] -= tZero
377 list = p['list']
378 for name in list:
379 d = list[name]
380 d['start'] -= tZero
381 d['end'] -= tZero
382 if('ftrace' in d):
383 cg = d['ftrace']
384 cg.start -= tZero
385 cg.end -= tZero
386 for line in cg.list:
387 line.time -= tZero
388 if('traceevents' in d):
389 for e in d['traceevents']:
390 e.time -= tZero
391 def newPhaseWithSingleAction(self, phasename, devname, start, end, color): 835 def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
392 for phase in self.phases: 836 for phase in self.phases:
393 self.dmesg[phase]['order'] += 1 837 self.dmesg[phase]['order'] += 1
@@ -417,6 +861,7 @@ class Data:
417 {'list': list, 'start': start, 'end': end, 861 {'list': list, 'start': start, 'end': end,
418 'row': 0, 'color': color, 'order': order} 862 'row': 0, 'color': color, 'order': order}
419 self.phases = self.sortedPhases() 863 self.phases = self.sortedPhases()
864 self.devicegroups.append([phasename])
420 def setPhase(self, phase, ktime, isbegin): 865 def setPhase(self, phase, ktime, isbegin):
421 if(isbegin): 866 if(isbegin):
422 self.dmesg[phase]['start'] = ktime 867 self.dmesg[phase]['start'] = ktime
@@ -442,7 +887,10 @@ class Data:
442 for devname in phaselist: 887 for devname in phaselist:
443 dev = phaselist[devname] 888 dev = phaselist[devname]
444 if(dev['end'] < 0): 889 if(dev['end'] < 0):
445 dev['end'] = end 890 for p in self.phases:
891 if self.dmesg[p]['end'] > dev['start']:
892 dev['end'] = self.dmesg[p]['end']
893 break
446 vprint('%s (%s): callback didnt return' % (devname, phase)) 894 vprint('%s (%s): callback didnt return' % (devname, phase))
447 def deviceFilter(self, devicefilter): 895 def deviceFilter(self, devicefilter):
448 # remove all by the relatives of the filter devnames 896 # remove all by the relatives of the filter devnames
@@ -472,22 +920,58 @@ class Data:
472 # if any calls never returned, clip them at system resume end 920 # if any calls never returned, clip them at system resume end
473 for phase in self.phases: 921 for phase in self.phases:
474 self.fixupInitcalls(phase, self.getEnd()) 922 self.fixupInitcalls(phase, self.getEnd())
475 def newActionGlobal(self, name, start, end): 923 def isInsideTimeline(self, start, end):
924 if(self.start <= start and self.end > start):
925 return True
926 return False
927 def phaseOverlap(self, phases):
928 rmgroups = []
929 newgroup = []
930 for group in self.devicegroups:
931 for phase in phases:
932 if phase not in group:
933 continue
934 for p in group:
935 if p not in newgroup:
936 newgroup.append(p)
937 if group not in rmgroups:
938 rmgroups.append(group)
939 for group in rmgroups:
940 self.devicegroups.remove(group)
941 self.devicegroups.append(newgroup)
942 def newActionGlobal(self, name, start, end, pid=-1, color=''):
943 # if event starts before timeline start, expand timeline
944 if(start < self.start):
945 self.setStart(start)
946 # if event ends after timeline end, expand the timeline
947 if(end > self.end):
948 self.setEnd(end)
476 # which phase is this device callback or action "in" 949 # which phase is this device callback or action "in"
477 targetphase = "none" 950 targetphase = "none"
951 htmlclass = ''
478 overlap = 0.0 952 overlap = 0.0
953 phases = []
479 for phase in self.phases: 954 for phase in self.phases:
480 pstart = self.dmesg[phase]['start'] 955 pstart = self.dmesg[phase]['start']
481 pend = self.dmesg[phase]['end'] 956 pend = self.dmesg[phase]['end']
482 o = max(0, min(end, pend) - max(start, pstart)) 957 o = max(0, min(end, pend) - max(start, pstart))
483 if(o > overlap): 958 if o > 0:
959 phases.append(phase)
960 if o > overlap:
961 if overlap > 0 and phase == 'post_resume':
962 continue
484 targetphase = phase 963 targetphase = phase
485 overlap = o 964 overlap = o
965 if pid == -2:
966 htmlclass = ' bg'
967 if len(phases) > 1:
968 htmlclass = ' bg'
969 self.phaseOverlap(phases)
486 if targetphase in self.phases: 970 if targetphase in self.phases:
487 self.newAction(targetphase, name, -1, '', start, end, '') 971 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
488 return True 972 return (targetphase, newname)
489 return False 973 return False
490 def newAction(self, phase, name, pid, parent, start, end, drv): 974 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
491 # new device callback for a specific phase 975 # new device callback for a specific phase
492 self.html_device_id += 1 976 self.html_device_id += 1
493 devid = '%s%d' % (self.idstr, self.html_device_id) 977 devid = '%s%d' % (self.idstr, self.html_device_id)
@@ -495,8 +979,19 @@ class Data:
495 length = -1.0 979 length = -1.0
496 if(start >= 0 and end >= 0): 980 if(start >= 0 and end >= 0):
497 length = end - start 981 length = end - start
982 if pid == -2:
983 i = 2
984 origname = name
985 while(name in list):
986 name = '%s[%d]' % (origname, i)
987 i += 1
498 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, 988 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
499 'length': length, 'row': 0, 'id': devid, 'drv': drv } 989 'length': length, 'row': 0, 'id': devid, 'drv': drv }
990 if htmlclass:
991 list[name]['htmlclass'] = htmlclass
992 if color:
993 list[name]['color'] = color
994 return name
500 def deviceIDs(self, devlist, phase): 995 def deviceIDs(self, devlist, phase):
501 idlist = [] 996 idlist = []
502 list = self.dmesg[phase]['list'] 997 list = self.dmesg[phase]['list']
@@ -536,10 +1031,21 @@ class Data:
536 vprint(' %16s: %f - %f (%d devices)' % (phase, \ 1031 vprint(' %16s: %f - %f (%d devices)' % (phase, \
537 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) 1032 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
538 vprint(' test end: %f' % self.end) 1033 vprint(' test end: %f' % self.end)
1034 def deviceChildrenAllPhases(self, devname):
1035 devlist = []
1036 for phase in self.phases:
1037 list = self.deviceChildren(devname, phase)
1038 for dev in list:
1039 if dev not in devlist:
1040 devlist.append(dev)
1041 return devlist
539 def masterTopology(self, name, list, depth): 1042 def masterTopology(self, name, list, depth):
540 node = DeviceNode(name, depth) 1043 node = DeviceNode(name, depth)
541 for cname in list: 1044 for cname in list:
542 clist = self.deviceChildren(cname, 'resume') 1045 # avoid recursions
1046 if name == cname:
1047 continue
1048 clist = self.deviceChildrenAllPhases(cname)
543 cnode = self.masterTopology(cname, clist, depth+1) 1049 cnode = self.masterTopology(cname, clist, depth+1)
544 node.children.append(cnode) 1050 node.children.append(cnode)
545 return node 1051 return node
@@ -580,7 +1086,8 @@ class Data:
580 list = self.dmesg[phase]['list'] 1086 list = self.dmesg[phase]['list']
581 for dev in list: 1087 for dev in list:
582 pdev = list[dev]['par'] 1088 pdev = list[dev]['par']
583 if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): 1089 pid = list[dev]['pid']
1090 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
584 continue 1091 continue
585 if pdev and pdev not in real and pdev not in rootlist: 1092 if pdev and pdev not in real and pdev not in rootlist:
586 rootlist.append(pdev) 1093 rootlist.append(pdev)
@@ -589,22 +1096,33 @@ class Data:
589 rootlist = self.rootDeviceList() 1096 rootlist = self.rootDeviceList()
590 master = self.masterTopology('', rootlist, 0) 1097 master = self.masterTopology('', rootlist, 0)
591 return self.printTopology(master) 1098 return self.printTopology(master)
1099 def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
1100 # only select devices that will actually show up in html
1101 self.tdevlist = dict()
1102 for phase in self.dmesg:
1103 devlist = []
1104 list = self.dmesg[phase]['list']
1105 for dev in list:
1106 length = (list[dev]['end'] - list[dev]['start']) * 1000
1107 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
1108 if width != '0.000000' and length >= mindevlen:
1109 devlist.append(dev)
1110 self.tdevlist[phase] = devlist
592 1111
593# Class: TraceEvent 1112# Class: TraceEvent
594# Description: 1113# Description:
595# A container for trace event data found in the ftrace file 1114# A container for trace event data found in the ftrace file
596class TraceEvent: 1115class TraceEvent:
597 ready = False 1116 text = ''
598 name = ''
599 time = 0.0 1117 time = 0.0
600 color = '#FFFFFF'
601 length = 0.0 1118 length = 0.0
602 action = '' 1119 title = ''
603 def __init__(self, a, n, c, t): 1120 row = 0
604 self.action = a 1121 def __init__(self, a, n, t, l):
605 self.name = n 1122 self.title = a
606 self.color = c 1123 self.text = n
607 self.time = t 1124 self.time = t
1125 self.length = l
608 1126
609# Class: FTraceLine 1127# Class: FTraceLine
610# Description: 1128# Description:
@@ -623,11 +1141,14 @@ class FTraceLine:
623 fcall = False 1141 fcall = False
624 freturn = False 1142 freturn = False
625 fevent = False 1143 fevent = False
1144 fkprobe = False
626 depth = 0 1145 depth = 0
627 name = '' 1146 name = ''
628 type = '' 1147 type = ''
629 def __init__(self, t, m, d): 1148 def __init__(self, t, m='', d=''):
630 self.time = float(t) 1149 self.time = float(t)
1150 if not m and not d:
1151 return
631 # is this a trace event 1152 # is this a trace event
632 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)): 1153 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
633 if(d == 'traceevent'): 1154 if(d == 'traceevent'):
@@ -644,6 +1165,18 @@ class FTraceLine:
644 self.type = emm.group('call') 1165 self.type = emm.group('call')
645 else: 1166 else:
646 self.name = msg 1167 self.name = msg
1168 km = re.match('^(?P<n>.*)_cal$', self.type)
1169 if km:
1170 self.fcall = True
1171 self.fkprobe = True
1172 self.type = km.group('n')
1173 return
1174 km = re.match('^(?P<n>.*)_ret$', self.type)
1175 if km:
1176 self.freturn = True
1177 self.fkprobe = True
1178 self.type = km.group('n')
1179 return
647 self.fevent = True 1180 self.fevent = True
648 return 1181 return
649 # convert the duration to seconds 1182 # convert the duration to seconds
@@ -662,7 +1195,7 @@ class FTraceLine:
662 # includes comment with function name 1195 # includes comment with function name
663 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m) 1196 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
664 if(match): 1197 if(match):
665 self.name = match.group('n') 1198 self.name = match.group('n').strip()
666 # function call 1199 # function call
667 else: 1200 else:
668 self.fcall = True 1201 self.fcall = True
@@ -670,19 +1203,19 @@ class FTraceLine:
670 if(m[-1] == '{'): 1203 if(m[-1] == '{'):
671 match = re.match('^(?P<n>.*) *\(.*', m) 1204 match = re.match('^(?P<n>.*) *\(.*', m)
672 if(match): 1205 if(match):
673 self.name = match.group('n') 1206 self.name = match.group('n').strip()
674 # function call with no children (leaf) 1207 # function call with no children (leaf)
675 elif(m[-1] == ';'): 1208 elif(m[-1] == ';'):
676 self.freturn = True 1209 self.freturn = True
677 match = re.match('^(?P<n>.*) *\(.*', m) 1210 match = re.match('^(?P<n>.*) *\(.*', m)
678 if(match): 1211 if(match):
679 self.name = match.group('n') 1212 self.name = match.group('n').strip()
680 # something else (possibly a trace marker) 1213 # something else (possibly a trace marker)
681 else: 1214 else:
682 self.name = m 1215 self.name = m
683 def getDepth(self, str): 1216 def getDepth(self, str):
684 return len(str)/2 1217 return len(str)/2
685 def debugPrint(self, dev): 1218 def debugPrint(self, dev=''):
686 if(self.freturn and self.fcall): 1219 if(self.freturn and self.fcall):
687 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ 1220 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
688 self.depth, self.name, self.length*1000000)) 1221 self.depth, self.name, self.length*1000000))
@@ -692,6 +1225,33 @@ class FTraceLine:
692 else: 1225 else:
693 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ 1226 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
694 self.depth, self.name, self.length*1000000)) 1227 self.depth, self.name, self.length*1000000))
1228 def startMarker(self):
1229 global sysvals
1230 # Is this the starting line of a suspend?
1231 if not self.fevent:
1232 return False
1233 if sysvals.usetracemarkers:
1234 if(self.name == 'SUSPEND START'):
1235 return True
1236 return False
1237 else:
1238 if(self.type == 'suspend_resume' and
1239 re.match('suspend_enter\[.*\] begin', self.name)):
1240 return True
1241 return False
1242 def endMarker(self):
1243 # Is this the ending line of a resume?
1244 if not self.fevent:
1245 return False
1246 if sysvals.usetracemarkers:
1247 if(self.name == 'RESUME COMPLETE'):
1248 return True
1249 return False
1250 else:
1251 if(self.type == 'suspend_resume' and
1252 re.match('thaw_processes\[.*\] end', self.name)):
1253 return True
1254 return False
695 1255
696# Class: FTraceCallGraph 1256# Class: FTraceCallGraph
697# Description: 1257# Description:
@@ -705,54 +1265,124 @@ class FTraceCallGraph:
705 list = [] 1265 list = []
706 invalid = False 1266 invalid = False
707 depth = 0 1267 depth = 0
708 def __init__(self): 1268 pid = 0
1269 def __init__(self, pid):
709 self.start = -1.0 1270 self.start = -1.0
710 self.end = -1.0 1271 self.end = -1.0
711 self.list = [] 1272 self.list = []
712 self.depth = 0 1273 self.depth = 0
713 def setDepth(self, line): 1274 self.pid = pid
1275 def addLine(self, line, debug=False):
1276 # if this is already invalid, just leave
1277 if(self.invalid):
1278 return False
1279 # invalidate on too much data or bad depth
1280 if(len(self.list) >= 1000000 or self.depth < 0):
1281 self.invalidate(line)
1282 return False
1283 # compare current depth with this lines pre-call depth
1284 prelinedep = line.depth
1285 if(line.freturn and not line.fcall):
1286 prelinedep += 1
1287 last = 0
1288 lasttime = line.time
1289 virtualfname = 'execution_misalignment'
1290 if len(self.list) > 0:
1291 last = self.list[-1]
1292 lasttime = last.time
1293 # handle low misalignments by inserting returns
1294 if prelinedep < self.depth:
1295 if debug and last:
1296 print '-------- task %d --------' % self.pid
1297 last.debugPrint()
1298 idx = 0
1299 # add return calls to get the depth down
1300 while prelinedep < self.depth:
1301 if debug:
1302 print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
1303 self.depth -= 1
1304 if idx == 0 and last and last.fcall and not last.freturn:
1305 # special case, turn last call into a leaf
1306 last.depth = self.depth
1307 last.freturn = True
1308 last.length = line.time - last.time
1309 if debug:
1310 last.debugPrint()
1311 else:
1312 vline = FTraceLine(lasttime)
1313 vline.depth = self.depth
1314 vline.name = virtualfname
1315 vline.freturn = True
1316 self.list.append(vline)
1317 if debug:
1318 vline.debugPrint()
1319 idx += 1
1320 if debug:
1321 line.debugPrint()
1322 print ''
1323 # handle high misalignments by inserting calls
1324 elif prelinedep > self.depth:
1325 if debug and last:
1326 print '-------- task %d --------' % self.pid
1327 last.debugPrint()
1328 idx = 0
1329 # add calls to get the depth up
1330 while prelinedep > self.depth:
1331 if debug:
1332 print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
1333 if idx == 0 and line.freturn and not line.fcall:
1334 # special case, turn this return into a leaf
1335 line.fcall = True
1336 prelinedep -= 1
1337 else:
1338 vline = FTraceLine(lasttime)
1339 vline.depth = self.depth
1340 vline.name = virtualfname
1341 vline.fcall = True
1342 if debug:
1343 vline.debugPrint()
1344 self.list.append(vline)
1345 self.depth += 1
1346 if not last:
1347 self.start = vline.time
1348 idx += 1
1349 if debug:
1350 line.debugPrint()
1351 print ''
1352 # process the call and set the new depth
714 if(line.fcall and not line.freturn): 1353 if(line.fcall and not line.freturn):
715 line.depth = self.depth
716 self.depth += 1 1354 self.depth += 1
717 elif(line.freturn and not line.fcall): 1355 elif(line.freturn and not line.fcall):
718 self.depth -= 1 1356 self.depth -= 1
719 line.depth = self.depth 1357 if len(self.list) < 1:
720 else: 1358 self.start = line.time
721 line.depth = self.depth 1359 self.list.append(line)
722 def addLine(self, line, match):
723 if(not self.invalid):
724 self.setDepth(line)
725 if(line.depth == 0 and line.freturn): 1360 if(line.depth == 0 and line.freturn):
726 if(self.start < 0): 1361 if(self.start < 0):
727 self.start = line.time 1362 self.start = line.time
728 self.end = line.time 1363 self.end = line.time
729 self.list.append(line) 1364 if line.fcall:
1365 self.end += line.length
1366 if self.list[0].name == virtualfname:
1367 self.invalid = True
730 return True 1368 return True
731 if(self.invalid):
732 return False
733 if(len(self.list) >= 1000000 or self.depth < 0):
734 if(len(self.list) > 0):
735 first = self.list[0]
736 self.list = []
737 self.list.append(first)
738 self.invalid = True
739 if(not match):
740 return False
741 id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
742 window = '(%f - %f)' % (self.start, line.time)
743 if(self.depth < 0):
744 print('Too much data for '+id+\
745 ' (buffer overflow), ignoring this callback')
746 else:
747 print('Too much data for '+id+\
748 ' '+window+', ignoring this callback')
749 return False
750 self.list.append(line)
751 if(self.start < 0):
752 self.start = line.time
753 return False 1369 return False
1370 def invalidate(self, line):
1371 if(len(self.list) > 0):
1372 first = self.list[0]
1373 self.list = []
1374 self.list.append(first)
1375 self.invalid = True
1376 id = 'task %s' % (self.pid)
1377 window = '(%f - %f)' % (self.start, line.time)
1378 if(self.depth < 0):
1379 vprint('Too much data for '+id+\
1380 ' (buffer overflow), ignoring this callback')
1381 else:
1382 vprint('Too much data for '+id+\
1383 ' '+window+', ignoring this callback')
754 def slice(self, t0, tN): 1384 def slice(self, t0, tN):
755 minicg = FTraceCallGraph() 1385 minicg = FTraceCallGraph(0)
756 count = -1 1386 count = -1
757 firstdepth = 0 1387 firstdepth = 0
758 for l in self.list: 1388 for l in self.list:
@@ -764,13 +1394,26 @@ class FTraceCallGraph:
764 firstdepth = l.depth 1394 firstdepth = l.depth
765 count = 0 1395 count = 0
766 l.depth -= firstdepth 1396 l.depth -= firstdepth
767 minicg.addLine(l, 0) 1397 minicg.addLine(l)
768 if((count == 0 and l.freturn and l.fcall) or 1398 if((count == 0 and l.freturn and l.fcall) or
769 (count > 0 and l.depth <= 0)): 1399 (count > 0 and l.depth <= 0)):
770 break 1400 break
771 count += 1 1401 count += 1
772 return minicg 1402 return minicg
773 def sanityCheck(self): 1403 def repair(self, enddepth):
1404 # bring the depth back to 0 with additional returns
1405 fixed = False
1406 last = self.list[-1]
1407 for i in reversed(range(enddepth)):
1408 t = FTraceLine(last.time)
1409 t.depth = i
1410 t.freturn = True
1411 fixed = self.addLine(t)
1412 if fixed:
1413 self.end = last.time
1414 return True
1415 return False
1416 def postProcess(self, debug=False):
774 stack = dict() 1417 stack = dict()
775 cnt = 0 1418 cnt = 0
776 for l in self.list: 1419 for l in self.list:
@@ -779,98 +1422,317 @@ class FTraceCallGraph:
779 cnt += 1 1422 cnt += 1
780 elif(l.freturn and not l.fcall): 1423 elif(l.freturn and not l.fcall):
781 if(l.depth not in stack): 1424 if(l.depth not in stack):
1425 if debug:
1426 print 'Post Process Error: Depth missing'
1427 l.debugPrint()
782 return False 1428 return False
1429 # transfer total time from return line to call line
783 stack[l.depth].length = l.length 1430 stack[l.depth].length = l.length
784 stack[l.depth] = 0 1431 stack.pop(l.depth)
785 l.length = 0 1432 l.length = 0
786 cnt -= 1 1433 cnt -= 1
787 if(cnt == 0): 1434 if(cnt == 0):
1435 # trace caught the whole call tree
788 return True 1436 return True
789 return False 1437 elif(cnt < 0):
790 def debugPrint(self, filename): 1438 if debug:
791 if(filename == 'stdout'): 1439 print 'Post Process Error: Depth is less than 0'
792 print('[%f - %f]') % (self.start, self.end) 1440 return False
793 for l in self.list: 1441 # trace ended before call tree finished
794 if(l.freturn and l.fcall): 1442 return self.repair(cnt)
795 print('%f (%02d): %s(); (%.3f us)' % (l.time, \ 1443 def deviceMatch(self, pid, data):
796 l.depth, l.name, l.length*1000000)) 1444 found = False
797 elif(l.freturn): 1445 # add the callgraph data to the device hierarchy
798 print('%f (%02d): %s} (%.3f us)' % (l.time, \ 1446 borderphase = {
799 l.depth, l.name, l.length*1000000)) 1447 'dpm_prepare': 'suspend_prepare',
800 else: 1448 'dpm_complete': 'resume_complete'
801 print('%f (%02d): %s() { (%.3f us)' % (l.time, \ 1449 }
802 l.depth, l.name, l.length*1000000)) 1450 if(self.list[0].name in borderphase):
803 print(' ') 1451 p = borderphase[self.list[0].name]
804 else: 1452 list = data.dmesg[p]['list']
805 fp = open(filename, 'w') 1453 for devname in list:
806 print(filename) 1454 dev = list[devname]
807 for l in self.list: 1455 if(pid == dev['pid'] and
808 if(l.freturn and l.fcall): 1456 self.start <= dev['start'] and
809 fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \ 1457 self.end >= dev['end']):
810 l.depth, l.name, l.length*1000000)) 1458 dev['ftrace'] = self.slice(dev['start'], dev['end'])
811 elif(l.freturn): 1459 found = True
812 fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \ 1460 return found
813 l.depth, l.name, l.length*1000000)) 1461 for p in data.phases:
814 else: 1462 if(data.dmesg[p]['start'] <= self.start and
815 fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \ 1463 self.start <= data.dmesg[p]['end']):
816 l.depth, l.name, l.length*1000000)) 1464 list = data.dmesg[p]['list']
817 fp.close() 1465 for devname in list:
1466 dev = list[devname]
1467 if(pid == dev['pid'] and
1468 self.start <= dev['start'] and
1469 self.end >= dev['end']):
1470 dev['ftrace'] = self
1471 found = True
1472 break
1473 break
1474 return found
1475 def newActionFromFunction(self, data):
1476 name = self.list[0].name
1477 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
1478 return
1479 fs = self.start
1480 fe = self.end
1481 if fs < data.start or fe > data.end:
1482 return
1483 phase = ''
1484 for p in data.phases:
1485 if(data.dmesg[p]['start'] <= self.start and
1486 self.start < data.dmesg[p]['end']):
1487 phase = p
1488 break
1489 if not phase:
1490 return
1491 out = data.newActionGlobal(name, fs, fe, -2)
1492 if out:
1493 phase, myname = out
1494 data.dmesg[phase]['list'][myname]['ftrace'] = self
1495 def debugPrint(self):
1496 print('[%f - %f] %s (%d)') % (self.start, self.end, self.list[0].name, self.pid)
1497 for l in self.list:
1498 if(l.freturn and l.fcall):
1499 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
1500 l.depth, l.name, l.length*1000000))
1501 elif(l.freturn):
1502 print('%f (%02d): %s} (%.3f us)' % (l.time, \
1503 l.depth, l.name, l.length*1000000))
1504 else:
1505 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
1506 l.depth, l.name, l.length*1000000))
1507 print(' ')
818 1508
819# Class: Timeline 1509# Class: Timeline
820# Description: 1510# Description:
821# A container for a suspend/resume html timeline. In older versions 1511# A container for a device timeline which calculates
822# of the script there were multiple timelines, but in the latest 1512# all the html properties to display it correctly
823# there is only one.
824class Timeline: 1513class Timeline:
825 html = {} 1514 html = {}
826 scaleH = 0.0 # height of the row as a percent of the timeline height 1515 height = 0 # total timeline height
827 rowH = 0.0 # height of each row in percent of the timeline height 1516 scaleH = 20 # timescale (top) row height
828 row_height_pixels = 30 1517 rowH = 30 # device row height
829 maxrows = 0 1518 bodyH = 0 # body height
830 height = 0 1519 rows = 0 # total timeline rows
831 def __init__(self): 1520 phases = []
1521 rowmaxlines = dict()
1522 rowcount = dict()
1523 rowheight = dict()
1524 def __init__(self, rowheight):
1525 self.rowH = rowheight
832 self.html = { 1526 self.html = {
1527 'header': '',
833 'timeline': '', 1528 'timeline': '',
834 'legend': '', 1529 'legend': '',
835 'scale': ''
836 } 1530 }
837 def setRows(self, rows): 1531 # Function: getDeviceRows
838 self.maxrows = int(rows) 1532 # Description:
839 self.scaleH = 100.0/float(self.maxrows) 1533 # determine how may rows the device funcs will take
840 self.height = self.maxrows*self.row_height_pixels 1534 # Arguments:
841 r = float(self.maxrows - 1) 1535 # rawlist: the list of devices/actions for a single phase
842 if(r < 1.0): 1536 # Output:
843 r = 1.0 1537 # The total number of rows needed to display this phase of the timeline
844 self.rowH = (100.0 - self.scaleH)/r 1538 def getDeviceRows(self, rawlist):
1539 # clear all rows and set them to undefined
1540 lendict = dict()
1541 for item in rawlist:
1542 item.row = -1
1543 lendict[item] = item.length
1544 list = []
1545 for i in sorted(lendict, key=lendict.get, reverse=True):
1546 list.append(i)
1547 remaining = len(list)
1548 rowdata = dict()
1549 row = 1
1550 # try to pack each row with as many ranges as possible
1551 while(remaining > 0):
1552 if(row not in rowdata):
1553 rowdata[row] = []
1554 for i in list:
1555 if(i.row >= 0):
1556 continue
1557 s = i.time
1558 e = i.time + i.length
1559 valid = True
1560 for ritem in rowdata[row]:
1561 rs = ritem.time
1562 re = ritem.time + ritem.length
1563 if(not (((s <= rs) and (e <= rs)) or
1564 ((s >= re) and (e >= re)))):
1565 valid = False
1566 break
1567 if(valid):
1568 rowdata[row].append(i)
1569 i.row = row
1570 remaining -= 1
1571 row += 1
1572 return row
1573 # Function: getPhaseRows
1574 # Description:
1575 # Organize the timeline entries into the smallest
1576 # number of rows possible, with no entry overlapping
1577 # Arguments:
1578 # list: the list of devices/actions for a single phase
1579 # devlist: string list of device names to use
1580 # Output:
1581 # The total number of rows needed to display this phase of the timeline
1582 def getPhaseRows(self, dmesg, devlist):
1583 # clear all rows and set them to undefined
1584 remaining = len(devlist)
1585 rowdata = dict()
1586 row = 0
1587 lendict = dict()
1588 myphases = []
1589 for item in devlist:
1590 if item[0] not in self.phases:
1591 self.phases.append(item[0])
1592 if item[0] not in myphases:
1593 myphases.append(item[0])
1594 self.rowmaxlines[item[0]] = dict()
1595 self.rowheight[item[0]] = dict()
1596 dev = dmesg[item[0]]['list'][item[1]]
1597 dev['row'] = -1
1598 lendict[item] = float(dev['end']) - float(dev['start'])
1599 if 'src' in dev:
1600 dev['devrows'] = self.getDeviceRows(dev['src'])
1601 lenlist = []
1602 for i in sorted(lendict, key=lendict.get, reverse=True):
1603 lenlist.append(i)
1604 orderedlist = []
1605 for item in lenlist:
1606 dev = dmesg[item[0]]['list'][item[1]]
1607 if dev['pid'] == -2:
1608 orderedlist.append(item)
1609 for item in lenlist:
1610 if item not in orderedlist:
1611 orderedlist.append(item)
1612 # try to pack each row with as many ranges as possible
1613 while(remaining > 0):
1614 rowheight = 1
1615 if(row not in rowdata):
1616 rowdata[row] = []
1617 for item in orderedlist:
1618 dev = dmesg[item[0]]['list'][item[1]]
1619 if(dev['row'] < 0):
1620 s = dev['start']
1621 e = dev['end']
1622 valid = True
1623 for ritem in rowdata[row]:
1624 rs = ritem['start']
1625 re = ritem['end']
1626 if(not (((s <= rs) and (e <= rs)) or
1627 ((s >= re) and (e >= re)))):
1628 valid = False
1629 break
1630 if(valid):
1631 rowdata[row].append(dev)
1632 dev['row'] = row
1633 remaining -= 1
1634 if 'devrows' in dev and dev['devrows'] > rowheight:
1635 rowheight = dev['devrows']
1636 for phase in myphases:
1637 self.rowmaxlines[phase][row] = rowheight
1638 self.rowheight[phase][row] = rowheight * self.rowH
1639 row += 1
1640 if(row > self.rows):
1641 self.rows = int(row)
1642 for phase in myphases:
1643 self.rowcount[phase] = row
1644 return row
1645 def phaseRowHeight(self, phase, row):
1646 return self.rowheight[phase][row]
1647 def phaseRowTop(self, phase, row):
1648 top = 0
1649 for i in sorted(self.rowheight[phase]):
1650 if i >= row:
1651 break
1652 top += self.rowheight[phase][i]
1653 return top
1654 # Function: calcTotalRows
1655 # Description:
1656 # Calculate the heights and offsets for the header and rows
1657 def calcTotalRows(self):
1658 maxrows = 0
1659 standardphases = []
1660 for phase in self.phases:
1661 total = 0
1662 for i in sorted(self.rowmaxlines[phase]):
1663 total += self.rowmaxlines[phase][i]
1664 if total > maxrows:
1665 maxrows = total
1666 if total == self.rowcount[phase]:
1667 standardphases.append(phase)
1668 self.height = self.scaleH + (maxrows*self.rowH)
1669 self.bodyH = self.height - self.scaleH
1670 for phase in standardphases:
1671 for i in sorted(self.rowheight[phase]):
1672 self.rowheight[phase][i] = self.bodyH/self.rowcount[phase]
1673 # Function: createTimeScale
1674 # Description:
1675 # Create the timescale for a timeline block
1676 # Arguments:
1677 # m0: start time (mode begin)
1678 # mMax: end time (mode end)
1679 # tTotal: total timeline time
1680 # mode: suspend or resume
1681 # Output:
1682 # The html code needed to display the time scale
1683 def createTimeScale(self, m0, mMax, tTotal, mode):
1684 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1685 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n'
1686 output = '<div class="timescale">\n'
1687 # set scale for timeline
1688 mTotal = mMax - m0
1689 tS = 0.1
1690 if(tTotal <= 0):
1691 return output+'</div>\n'
1692 if(tTotal > 4):
1693 tS = 1
1694 divTotal = int(mTotal/tS) + 1
1695 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
1696 for i in range(divTotal):
1697 htmlline = ''
1698 if(mode == 'resume'):
1699 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
1700 val = '%0.fms' % (float(i)*tS*1000)
1701 htmlline = timescale.format(pos, val)
1702 if(i == 0):
1703 htmlline = rline
1704 else:
1705 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
1706 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
1707 if(i == divTotal - 1):
1708 val = 'Suspend'
1709 htmlline = timescale.format(pos, val)
1710 output += htmlline
1711 output += '</div>\n'
1712 return output
845 1713
846# Class: TestRun 1714# Class: TestProps
847# Description: 1715# Description:
848# A container for a suspend/resume test run. This is necessary as 1716# A list of values describing the properties of these test runs
849# there could be more than one, and they need to be separate. 1717class TestProps:
850class TestRun: 1718 stamp = ''
1719 tracertype = ''
1720 S0i3 = False
1721 fwdata = []
851 ftrace_line_fmt_fg = \ 1722 ftrace_line_fmt_fg = \
852 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ 1723 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
853 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ 1724 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
854 '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' 1725 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
855 ftrace_line_fmt_nop = \ 1726 ftrace_line_fmt_nop = \
856 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ 1727 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
857 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ 1728 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
858 '(?P<msg>.*)' 1729 '(?P<msg>.*)'
859 ftrace_line_fmt = ftrace_line_fmt_nop 1730 ftrace_line_fmt = ftrace_line_fmt_nop
860 cgformat = False 1731 cgformat = False
861 ftemp = dict()
862 ttemp = dict()
863 inthepipe = False
864 tracertype = ''
865 data = 0 1732 data = 0
866 def __init__(self, dataobj): 1733 ktemp = dict()
867 self.data = dataobj 1734 def __init__(self):
868 self.ftemp = dict() 1735 self.ktemp = dict()
869 self.ttemp = dict()
870 def isReady(self):
871 if(tracertype == '' or not data):
872 return False
873 return True
874 def setTracerType(self, tracer): 1736 def setTracerType(self, tracer):
875 self.tracertype = tracer 1737 self.tracertype = tracer
876 if(tracer == 'function_graph'): 1738 if(tracer == 'function_graph'):
@@ -881,6 +1743,19 @@ class TestRun:
881 else: 1743 else:
882 doError('Invalid tracer format: [%s]' % tracer, False) 1744 doError('Invalid tracer format: [%s]' % tracer, False)
883 1745
1746# Class: TestRun
1747# Description:
1748# A container for a suspend/resume test run. This is necessary as
1749# there could be more than one, and they need to be separate.
1750class TestRun:
1751 ftemp = dict()
1752 ttemp = dict()
1753 data = 0
1754 def __init__(self, dataobj):
1755 self.data = dataobj
1756 self.ftemp = dict()
1757 self.ttemp = dict()
1758
884# ----------------- FUNCTIONS -------------------- 1759# ----------------- FUNCTIONS --------------------
885 1760
886# Function: vprint 1761# Function: vprint
@@ -893,104 +1768,16 @@ def vprint(msg):
893 if(sysvals.verbose): 1768 if(sysvals.verbose):
894 print(msg) 1769 print(msg)
895 1770
896# Function: initFtrace
897# Description:
898# Configure ftrace to use trace events and/or a callgraph
899def initFtrace():
900 global sysvals
901
902 tp = sysvals.tpath
903 cf = 'dpm_run_callback'
904 if(sysvals.usetraceeventsonly):
905 cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback'
906 if(sysvals.usecallgraph or sysvals.usetraceevents):
907 print('INITIALIZING FTRACE...')
908 # turn trace off
909 os.system('echo 0 > '+tp+'tracing_on')
910 # set the trace clock to global
911 os.system('echo global > '+tp+'trace_clock')
912 # set trace buffer to a huge value
913 os.system('echo nop > '+tp+'current_tracer')
914 os.system('echo 100000 > '+tp+'buffer_size_kb')
915 # initialize the callgraph trace, unless this is an x2 run
916 if(sysvals.usecallgraph and sysvals.execcount == 1):
917 # set trace type
918 os.system('echo function_graph > '+tp+'current_tracer')
919 os.system('echo "" > '+tp+'set_ftrace_filter')
920 # set trace format options
921 os.system('echo funcgraph-abstime > '+tp+'trace_options')
922 os.system('echo funcgraph-proc > '+tp+'trace_options')
923 # focus only on device suspend and resume
924 os.system('cat '+tp+'available_filter_functions | grep '+\
925 cf+' > '+tp+'set_graph_function')
926 if(sysvals.usetraceevents):
927 # turn trace events on
928 events = iter(sysvals.traceevents)
929 for e in events:
930 os.system('echo 1 > '+sysvals.epath+e+'/enable')
931 # clear the trace buffer
932 os.system('echo "" > '+tp+'trace')
933
934# Function: initFtraceAndroid
935# Description:
936# Configure ftrace to capture trace events
937def initFtraceAndroid():
938 global sysvals
939
940 tp = sysvals.tpath
941 if(sysvals.usetraceevents):
942 print('INITIALIZING FTRACE...')
943 # turn trace off
944 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
945 # set the trace clock to global
946 os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'")
947 # set trace buffer to a huge value
948 os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'")
949 os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'")
950 # turn trace events on
951 events = iter(sysvals.traceevents)
952 for e in events:
953 os.system(sysvals.adb+" shell 'echo 1 > "+\
954 sysvals.epath+e+"/enable'")
955 # clear the trace buffer
956 os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'")
957
958# Function: verifyFtrace
959# Description:
960# Check that ftrace is working on the system
961# Output:
962# True or False
963def verifyFtrace():
964 global sysvals
965 # files needed for any trace data
966 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
967 'trace_marker', 'trace_options', 'tracing_on']
968 # files needed for callgraph trace data
969 tp = sysvals.tpath
970 if(sysvals.usecallgraph):
971 files += [
972 'available_filter_functions',
973 'set_ftrace_filter',
974 'set_graph_function'
975 ]
976 for f in files:
977 if(sysvals.android):
978 out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip()
979 if(out != tp+f):
980 return False
981 else:
982 if(os.path.exists(tp+f) == False):
983 return False
984 return True
985
986# Function: parseStamp 1771# Function: parseStamp
987# Description: 1772# Description:
988# Pull in the stamp comment line from the data file(s), 1773# Pull in the stamp comment line from the data file(s),
989# create the stamp, and add it to the global sysvals object 1774# create the stamp, and add it to the global sysvals object
990# Arguments: 1775# Arguments:
991# m: the valid re.match output for the stamp line 1776# m: the valid re.match output for the stamp line
992def parseStamp(m, data): 1777def parseStamp(line, data):
993 global sysvals 1778 global sysvals
1779
1780 m = re.match(sysvals.stampfmt, line)
994 data.stamp = {'time': '', 'host': '', 'mode': ''} 1781 data.stamp = {'time': '', 'host': '', 'mode': ''}
995 dt = datetime(int(m.group('y'))+2000, int(m.group('m')), 1782 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
996 int(m.group('d')), int(m.group('H')), int(m.group('M')), 1783 int(m.group('d')), int(m.group('H')), int(m.group('M')),
@@ -999,6 +1786,7 @@ def parseStamp(m, data):
999 data.stamp['host'] = m.group('host') 1786 data.stamp['host'] = m.group('host')
1000 data.stamp['mode'] = m.group('mode') 1787 data.stamp['mode'] = m.group('mode')
1001 data.stamp['kernel'] = m.group('kernel') 1788 data.stamp['kernel'] = m.group('kernel')
1789 sysvals.hostname = data.stamp['host']
1002 sysvals.suspendmode = data.stamp['mode'] 1790 sysvals.suspendmode = data.stamp['mode']
1003 if not sysvals.stamp: 1791 if not sysvals.stamp:
1004 sysvals.stamp = data.stamp 1792 sysvals.stamp = data.stamp
@@ -1031,14 +1819,35 @@ def diffStamp(stamp1, stamp2):
1031def doesTraceLogHaveTraceEvents(): 1819def doesTraceLogHaveTraceEvents():
1032 global sysvals 1820 global sysvals
1033 1821
1822 # check for kprobes
1823 sysvals.usekprobes = False
1824 out = os.system('grep -q "_cal: (" '+sysvals.ftracefile)
1825 if(out == 0):
1826 sysvals.usekprobes = True
1827 # check for callgraph data on trace event blocks
1828 out = os.system('grep -q "_cpu_down()" '+sysvals.ftracefile)
1829 if(out == 0):
1830 sysvals.usekprobes = True
1831 out = os.popen('head -1 '+sysvals.ftracefile).read().replace('\n', '')
1832 m = re.match(sysvals.stampfmt, out)
1833 if m and m.group('mode') == 'command':
1834 sysvals.usetraceeventsonly = True
1835 sysvals.usetraceevents = True
1836 return
1837 # figure out what level of trace events are supported
1034 sysvals.usetraceeventsonly = True 1838 sysvals.usetraceeventsonly = True
1035 sysvals.usetraceevents = False 1839 sysvals.usetraceevents = False
1036 for e in sysvals.traceevents: 1840 for e in sysvals.traceevents:
1037 out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read() 1841 out = os.system('grep -q "'+e+': " '+sysvals.ftracefile)
1038 if(not out): 1842 if(out != 0):
1039 sysvals.usetraceeventsonly = False 1843 sysvals.usetraceeventsonly = False
1040 if(e == 'suspend_resume' and out): 1844 if(e == 'suspend_resume' and out == 0):
1041 sysvals.usetraceevents = True 1845 sysvals.usetraceevents = True
1846 # determine is this log is properly formatted
1847 for e in ['SUSPEND START', 'RESUME COMPLETE']:
1848 out = os.system('grep -q "'+e+'" '+sysvals.ftracefile)
1849 if(out != 0):
1850 sysvals.usetracemarkers = False
1042 1851
1043# Function: appendIncompleteTraceLog 1852# Function: appendIncompleteTraceLog
1044# Description: 1853# Description:
@@ -1055,44 +1864,42 @@ def appendIncompleteTraceLog(testruns):
1055 1864
1056 # create TestRun vessels for ftrace parsing 1865 # create TestRun vessels for ftrace parsing
1057 testcnt = len(testruns) 1866 testcnt = len(testruns)
1058 testidx = -1 1867 testidx = 0
1059 testrun = [] 1868 testrun = []
1060 for data in testruns: 1869 for data in testruns:
1061 testrun.append(TestRun(data)) 1870 testrun.append(TestRun(data))
1062 1871
1063 # extract the callgraph and traceevent data 1872 # extract the callgraph and traceevent data
1064 vprint('Analyzing the ftrace data...') 1873 vprint('Analyzing the ftrace data...')
1874 tp = TestProps()
1065 tf = open(sysvals.ftracefile, 'r') 1875 tf = open(sysvals.ftracefile, 'r')
1876 data = 0
1066 for line in tf: 1877 for line in tf:
1067 # remove any latent carriage returns 1878 # remove any latent carriage returns
1068 line = line.replace('\r\n', '') 1879 line = line.replace('\r\n', '')
1069 # grab the time stamp first (signifies the start of the test run) 1880 # grab the time stamp
1070 m = re.match(sysvals.stampfmt, line) 1881 m = re.match(sysvals.stampfmt, line)
1071 if(m): 1882 if(m):
1072 testidx += 1 1883 tp.stamp = line
1073 parseStamp(m, testrun[testidx].data)
1074 continue
1075 # pull out any firmware data
1076 if(re.match(sysvals.firmwarefmt, line)):
1077 continue
1078 # if we havent found a test time stamp yet keep spinning til we do
1079 if(testidx < 0):
1080 continue 1884 continue
1081 # determine the trace data type (required for further parsing) 1885 # determine the trace data type (required for further parsing)
1082 m = re.match(sysvals.tracertypefmt, line) 1886 m = re.match(sysvals.tracertypefmt, line)
1083 if(m): 1887 if(m):
1084 tracer = m.group('t') 1888 tp.setTracerType(m.group('t'))
1085 testrun[testidx].setTracerType(tracer) 1889 continue
1890 # device properties line
1891 if(re.match(sysvals.devpropfmt, line)):
1892 devProps(line)
1086 continue 1893 continue
1087 # parse only valid lines, if this isnt one move on 1894 # parse only valid lines, if this is not one move on
1088 m = re.match(testrun[testidx].ftrace_line_fmt, line) 1895 m = re.match(tp.ftrace_line_fmt, line)
1089 if(not m): 1896 if(not m):
1090 continue 1897 continue
1091 # gather the basic message data from the line 1898 # gather the basic message data from the line
1092 m_time = m.group('time') 1899 m_time = m.group('time')
1093 m_pid = m.group('pid') 1900 m_pid = m.group('pid')
1094 m_msg = m.group('msg') 1901 m_msg = m.group('msg')
1095 if(testrun[testidx].cgformat): 1902 if(tp.cgformat):
1096 m_param3 = m.group('dur') 1903 m_param3 = m.group('dur')
1097 else: 1904 else:
1098 m_param3 = 'traceevent' 1905 m_param3 = 'traceevent'
@@ -1104,119 +1911,114 @@ def appendIncompleteTraceLog(testruns):
1104 # the line should be a call, return, or event 1911 # the line should be a call, return, or event
1105 if(not t.fcall and not t.freturn and not t.fevent): 1912 if(not t.fcall and not t.freturn and not t.fevent):
1106 continue 1913 continue
1107 # only parse the ftrace data during suspend/resume 1914 # look for the suspend start marker
1108 data = testrun[testidx].data 1915 if(t.startMarker()):
1109 if(not testrun[testidx].inthepipe): 1916 data = testrun[testidx].data
1110 # look for the suspend start marker 1917 parseStamp(tp.stamp, data)
1111 if(t.fevent): 1918 data.setStart(t.time)
1112 if(t.name == 'SUSPEND START'): 1919 continue
1113 testrun[testidx].inthepipe = True 1920 if(not data):
1114 data.setStart(t.time) 1921 continue
1922 # find the end of resume
1923 if(t.endMarker()):
1924 data.setEnd(t.time)
1925 testidx += 1
1926 if(testidx >= testcnt):
1927 break
1928 continue
1929 # trace event processing
1930 if(t.fevent):
1931 # general trace events have two types, begin and end
1932 if(re.match('(?P<name>.*) begin$', t.name)):
1933 isbegin = True
1934 elif(re.match('(?P<name>.*) end$', t.name)):
1935 isbegin = False
1936 else:
1115 continue 1937 continue
1116 else: 1938 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1117 # trace event processing 1939 if(m):
1118 if(t.fevent): 1940 val = m.group('val')
1119 if(t.name == 'RESUME COMPLETE'): 1941 if val == '0':
1120 testrun[testidx].inthepipe = False 1942 name = m.group('name')
1121 data.setEnd(t.time)
1122 if(testidx == testcnt - 1):
1123 break
1124 continue
1125 # general trace events have two types, begin and end
1126 if(re.match('(?P<name>.*) begin$', t.name)):
1127 isbegin = True
1128 elif(re.match('(?P<name>.*) end$', t.name)):
1129 isbegin = False
1130 else: 1943 else:
1131 continue 1944 name = m.group('name')+'['+val+']'
1132 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 1945 else:
1133 if(m): 1946 m = re.match('(?P<name>.*) .*', t.name)
1134 val = m.group('val') 1947 name = m.group('name')
1135 if val == '0': 1948 # special processing for trace events
1136 name = m.group('name') 1949 if re.match('dpm_prepare\[.*', name):
1137 else: 1950 continue
1138 name = m.group('name')+'['+val+']' 1951 elif re.match('machine_suspend.*', name):
1952 continue
1953 elif re.match('suspend_enter\[.*', name):
1954 if(not isbegin):
1955 data.dmesg['suspend_prepare']['end'] = t.time
1956 continue
1957 elif re.match('dpm_suspend\[.*', name):
1958 if(not isbegin):
1959 data.dmesg['suspend']['end'] = t.time
1960 continue
1961 elif re.match('dpm_suspend_late\[.*', name):
1962 if(isbegin):
1963 data.dmesg['suspend_late']['start'] = t.time
1139 else: 1964 else:
1140 m = re.match('(?P<name>.*) .*', t.name) 1965 data.dmesg['suspend_late']['end'] = t.time
1141 name = m.group('name') 1966 continue
1142 # special processing for trace events 1967 elif re.match('dpm_suspend_noirq\[.*', name):
1143 if re.match('dpm_prepare\[.*', name): 1968 if(isbegin):
1144 continue 1969 data.dmesg['suspend_noirq']['start'] = t.time
1145 elif re.match('machine_suspend.*', name):
1146 continue
1147 elif re.match('suspend_enter\[.*', name):
1148 if(not isbegin):
1149 data.dmesg['suspend_prepare']['end'] = t.time
1150 continue
1151 elif re.match('dpm_suspend\[.*', name):
1152 if(not isbegin):
1153 data.dmesg['suspend']['end'] = t.time
1154 continue
1155 elif re.match('dpm_suspend_late\[.*', name):
1156 if(isbegin):
1157 data.dmesg['suspend_late']['start'] = t.time
1158 else:
1159 data.dmesg['suspend_late']['end'] = t.time
1160 continue
1161 elif re.match('dpm_suspend_noirq\[.*', name):
1162 if(isbegin):
1163 data.dmesg['suspend_noirq']['start'] = t.time
1164 else:
1165 data.dmesg['suspend_noirq']['end'] = t.time
1166 continue
1167 elif re.match('dpm_resume_noirq\[.*', name):
1168 if(isbegin):
1169 data.dmesg['resume_machine']['end'] = t.time
1170 data.dmesg['resume_noirq']['start'] = t.time
1171 else:
1172 data.dmesg['resume_noirq']['end'] = t.time
1173 continue
1174 elif re.match('dpm_resume_early\[.*', name):
1175 if(isbegin):
1176 data.dmesg['resume_early']['start'] = t.time
1177 else:
1178 data.dmesg['resume_early']['end'] = t.time
1179 continue
1180 elif re.match('dpm_resume\[.*', name):
1181 if(isbegin):
1182 data.dmesg['resume']['start'] = t.time
1183 else:
1184 data.dmesg['resume']['end'] = t.time
1185 continue
1186 elif re.match('dpm_complete\[.*', name):
1187 if(isbegin):
1188 data.dmesg['resume_complete']['start'] = t.time
1189 else:
1190 data.dmesg['resume_complete']['end'] = t.time
1191 continue
1192 # is this trace event outside of the devices calls
1193 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1194 # global events (outside device calls) are simply graphed
1195 if(isbegin):
1196 # store each trace event in ttemp
1197 if(name not in testrun[testidx].ttemp):
1198 testrun[testidx].ttemp[name] = []
1199 testrun[testidx].ttemp[name].append(\
1200 {'begin': t.time, 'end': t.time})
1201 else:
1202 # finish off matching trace event in ttemp
1203 if(name in testrun[testidx].ttemp):
1204 testrun[testidx].ttemp[name][-1]['end'] = t.time
1205 else: 1970 else:
1206 if(isbegin): 1971 data.dmesg['suspend_noirq']['end'] = t.time
1207 data.addIntraDevTraceEvent('', name, pid, t.time) 1972 continue
1208 else: 1973 elif re.match('dpm_resume_noirq\[.*', name):
1209 data.capIntraDevTraceEvent('', name, pid, t.time) 1974 if(isbegin):
1210 # call/return processing 1975 data.dmesg['resume_machine']['end'] = t.time
1211 elif sysvals.usecallgraph: 1976 data.dmesg['resume_noirq']['start'] = t.time
1212 # create a callgraph object for the data 1977 else:
1213 if(pid not in testrun[testidx].ftemp): 1978 data.dmesg['resume_noirq']['end'] = t.time
1214 testrun[testidx].ftemp[pid] = [] 1979 continue
1215 testrun[testidx].ftemp[pid].append(FTraceCallGraph()) 1980 elif re.match('dpm_resume_early\[.*', name):
1216 # when the call is finished, see which device matches it 1981 if(isbegin):
1217 cg = testrun[testidx].ftemp[pid][-1] 1982 data.dmesg['resume_early']['start'] = t.time
1218 if(cg.addLine(t, m)): 1983 else:
1219 testrun[testidx].ftemp[pid].append(FTraceCallGraph()) 1984 data.dmesg['resume_early']['end'] = t.time
1985 continue
1986 elif re.match('dpm_resume\[.*', name):
1987 if(isbegin):
1988 data.dmesg['resume']['start'] = t.time
1989 else:
1990 data.dmesg['resume']['end'] = t.time
1991 continue
1992 elif re.match('dpm_complete\[.*', name):
1993 if(isbegin):
1994 data.dmesg['resume_complete']['start'] = t.time
1995 else:
1996 data.dmesg['resume_complete']['end'] = t.time
1997 continue
1998 # skip trace events inside devices calls
1999 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2000 continue
2001 # global events (outside device calls) are simply graphed
2002 if(isbegin):
2003 # store each trace event in ttemp
2004 if(name not in testrun[testidx].ttemp):
2005 testrun[testidx].ttemp[name] = []
2006 testrun[testidx].ttemp[name].append(\
2007 {'begin': t.time, 'end': t.time})
2008 else:
2009 # finish off matching trace event in ttemp
2010 if(name in testrun[testidx].ttemp):
2011 testrun[testidx].ttemp[name][-1]['end'] = t.time
2012 # call/return processing
2013 elif sysvals.usecallgraph:
2014 # create a callgraph object for the data
2015 if(pid not in testrun[testidx].ftemp):
2016 testrun[testidx].ftemp[pid] = []
2017 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
2018 # when the call is finished, see which device matches it
2019 cg = testrun[testidx].ftemp[pid][-1]
2020 if(cg.addLine(t)):
2021 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
1220 tf.close() 2022 tf.close()
1221 2023
1222 for test in testrun: 2024 for test in testrun:
@@ -1224,20 +2026,14 @@ def appendIncompleteTraceLog(testruns):
1224 if(sysvals.usetraceevents): 2026 if(sysvals.usetraceevents):
1225 for name in test.ttemp: 2027 for name in test.ttemp:
1226 for event in test.ttemp[name]: 2028 for event in test.ttemp[name]:
1227 begin = event['begin'] 2029 test.data.newActionGlobal(name, event['begin'], event['end'])
1228 end = event['end']
1229 # if event starts before timeline start, expand timeline
1230 if(begin < test.data.start):
1231 test.data.setStart(begin)
1232 # if event ends after timeline end, expand the timeline
1233 if(end > test.data.end):
1234 test.data.setEnd(end)
1235 test.data.newActionGlobal(name, begin, end)
1236 2030
1237 # add the callgraph data to the device hierarchy 2031 # add the callgraph data to the device hierarchy
1238 for pid in test.ftemp: 2032 for pid in test.ftemp:
1239 for cg in test.ftemp[pid]: 2033 for cg in test.ftemp[pid]:
1240 if(not cg.sanityCheck()): 2034 if len(cg.list) < 1 or cg.invalid:
2035 continue
2036 if(not cg.postProcess()):
1241 id = 'task %s cpu %s' % (pid, m.group('cpu')) 2037 id = 'task %s cpu %s' % (pid, m.group('cpu'))
1242 vprint('Sanity check failed for '+\ 2038 vprint('Sanity check failed for '+\
1243 id+', ignoring this callback') 2039 id+', ignoring this callback')
@@ -1259,14 +2055,6 @@ def appendIncompleteTraceLog(testruns):
1259 if(sysvals.verbose): 2055 if(sysvals.verbose):
1260 test.data.printDetails() 2056 test.data.printDetails()
1261 2057
1262
1263 # add the time in between the tests as a new phase so we can see it
1264 if(len(testruns) > 1):
1265 t1e = testruns[0].getEnd()
1266 t2s = testruns[-1].getStart()
1267 testruns[-1].newPhaseWithSingleAction('user mode', \
1268 'user mode', t1e, t2s, '#FF9966')
1269
1270# Function: parseTraceLog 2058# Function: parseTraceLog
1271# Description: 2059# Description:
1272# Analyze an ftrace log output file generated from this app during 2060# Analyze an ftrace log output file generated from this app during
@@ -1280,9 +2068,16 @@ def parseTraceLog():
1280 2068
1281 vprint('Analyzing the ftrace data...') 2069 vprint('Analyzing the ftrace data...')
1282 if(os.path.exists(sysvals.ftracefile) == False): 2070 if(os.path.exists(sysvals.ftracefile) == False):
1283 doError('%s doesnt exist' % sysvals.ftracefile, False) 2071 doError('%s does not exist' % sysvals.ftracefile, False)
2072
2073 sysvals.setupAllKprobes()
2074 tracewatch = ['suspend_enter']
2075 if sysvals.usekprobes:
2076 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2077 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
1284 2078
1285 # extract the callgraph and traceevent data 2079 # extract the callgraph and traceevent data
2080 tp = TestProps()
1286 testruns = [] 2081 testruns = []
1287 testdata = [] 2082 testdata = []
1288 testrun = 0 2083 testrun = 0
@@ -1295,27 +2090,17 @@ def parseTraceLog():
1295 # stamp line: each stamp means a new test run 2090 # stamp line: each stamp means a new test run
1296 m = re.match(sysvals.stampfmt, line) 2091 m = re.match(sysvals.stampfmt, line)
1297 if(m): 2092 if(m):
1298 data = Data(len(testdata)) 2093 tp.stamp = line
1299 testdata.append(data)
1300 testrun = TestRun(data)
1301 testruns.append(testrun)
1302 parseStamp(m, data)
1303 continue
1304 if(not data):
1305 continue 2094 continue
1306 # firmware line: pull out any firmware data 2095 # firmware line: pull out any firmware data
1307 m = re.match(sysvals.firmwarefmt, line) 2096 m = re.match(sysvals.firmwarefmt, line)
1308 if(m): 2097 if(m):
1309 data.fwSuspend = int(m.group('s')) 2098 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
1310 data.fwResume = int(m.group('r'))
1311 if(data.fwSuspend > 0 or data.fwResume > 0):
1312 data.fwValid = True
1313 continue 2099 continue
1314 # tracer type line: determine the trace data type 2100 # tracer type line: determine the trace data type
1315 m = re.match(sysvals.tracertypefmt, line) 2101 m = re.match(sysvals.tracertypefmt, line)
1316 if(m): 2102 if(m):
1317 tracer = m.group('t') 2103 tp.setTracerType(m.group('t'))
1318 testrun.setTracerType(tracer)
1319 continue 2104 continue
1320 # post resume time line: did this test run include post-resume data 2105 # post resume time line: did this test run include post-resume data
1321 m = re.match(sysvals.postresumefmt, line) 2106 m = re.match(sysvals.postresumefmt, line)
@@ -1324,15 +2109,20 @@ def parseTraceLog():
1324 if(t > 0): 2109 if(t > 0):
1325 sysvals.postresumetime = t 2110 sysvals.postresumetime = t
1326 continue 2111 continue
2112 # device properties line
2113 if(re.match(sysvals.devpropfmt, line)):
2114 devProps(line)
2115 continue
1327 # ftrace line: parse only valid lines 2116 # ftrace line: parse only valid lines
1328 m = re.match(testrun.ftrace_line_fmt, line) 2117 m = re.match(tp.ftrace_line_fmt, line)
1329 if(not m): 2118 if(not m):
1330 continue 2119 continue
1331 # gather the basic message data from the line 2120 # gather the basic message data from the line
1332 m_time = m.group('time') 2121 m_time = m.group('time')
2122 m_proc = m.group('proc')
1333 m_pid = m.group('pid') 2123 m_pid = m.group('pid')
1334 m_msg = m.group('msg') 2124 m_msg = m.group('msg')
1335 if(testrun.cgformat): 2125 if(tp.cgformat):
1336 m_param3 = m.group('dur') 2126 m_param3 = m.group('dur')
1337 else: 2127 else:
1338 m_param3 = 'traceevent' 2128 m_param3 = 'traceevent'
@@ -1344,24 +2134,38 @@ def parseTraceLog():
1344 # the line should be a call, return, or event 2134 # the line should be a call, return, or event
1345 if(not t.fcall and not t.freturn and not t.fevent): 2135 if(not t.fcall and not t.freturn and not t.fevent):
1346 continue 2136 continue
1347 # only parse the ftrace data during suspend/resume 2137 # find the start of suspend
1348 if(not testrun.inthepipe): 2138 if(t.startMarker()):
1349 # look for the suspend start marker 2139 phase = 'suspend_prepare'
1350 if(t.fevent): 2140 data = Data(len(testdata))
1351 if(t.name == 'SUSPEND START'): 2141 testdata.append(data)
1352 testrun.inthepipe = True 2142 testrun = TestRun(data)
1353 data.setStart(t.time) 2143 testruns.append(testrun)
2144 parseStamp(tp.stamp, data)
2145 if len(tp.fwdata) > data.testnumber:
2146 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2147 if(data.fwSuspend > 0 or data.fwResume > 0):
2148 data.fwValid = True
2149 data.setStart(t.time)
2150 continue
2151 if(not data):
2152 continue
2153 # find the end of resume
2154 if(t.endMarker()):
2155 if(sysvals.usetracemarkers and sysvals.postresumetime > 0):
2156 phase = 'post_resume'
2157 data.newPhase(phase, t.time, t.time, '#F0F0F0', -1)
2158 data.setEnd(t.time)
2159 if(not sysvals.usetracemarkers):
2160 # no trace markers? then quit and be sure to finish recording
2161 # the event we used to trigger resume end
2162 if(len(testrun.ttemp['thaw_processes']) > 0):
2163 # if an entry exists, assume this is its end
2164 testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2165 break
1354 continue 2166 continue
1355 # trace event processing 2167 # trace event processing
1356 if(t.fevent): 2168 if(t.fevent):
1357 if(t.name == 'RESUME COMPLETE'):
1358 if(sysvals.postresumetime > 0):
1359 phase = 'post_resume'
1360 data.newPhase(phase, t.time, t.time, '#FF9966', -1)
1361 else:
1362 testrun.inthepipe = False
1363 data.setEnd(t.time)
1364 continue
1365 if(phase == 'post_resume'): 2169 if(phase == 'post_resume'):
1366 data.setEnd(t.time) 2170 data.setEnd(t.time)
1367 if(t.type == 'suspend_resume'): 2171 if(t.type == 'suspend_resume'):
@@ -1383,8 +2187,7 @@ def parseTraceLog():
1383 m = re.match('(?P<name>.*) .*', t.name) 2187 m = re.match('(?P<name>.*) .*', t.name)
1384 name = m.group('name') 2188 name = m.group('name')
1385 # ignore these events 2189 # ignore these events
1386 if(re.match('acpi_suspend\[.*', t.name) or 2190 if(name.split('[')[0] in tracewatch):
1387 re.match('suspend_enter\[.*', name)):
1388 continue 2191 continue
1389 # -- phase changes -- 2192 # -- phase changes --
1390 # suspend_prepare start 2193 # suspend_prepare start
@@ -1418,7 +2221,7 @@ def parseTraceLog():
1418 data.dmesg[phase]['end'] = t.time 2221 data.dmesg[phase]['end'] = t.time
1419 data.tSuspended = t.time 2222 data.tSuspended = t.time
1420 else: 2223 else:
1421 if(sysvals.suspendmode in ['mem', 'disk']): 2224 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
1422 data.dmesg['suspend_machine']['end'] = t.time 2225 data.dmesg['suspend_machine']['end'] = t.time
1423 data.tSuspended = t.time 2226 data.tSuspended = t.time
1424 phase = 'resume_machine' 2227 phase = 'resume_machine'
@@ -1426,6 +2229,15 @@ def parseTraceLog():
1426 data.tResumed = t.time 2229 data.tResumed = t.time
1427 data.tLow = data.tResumed - data.tSuspended 2230 data.tLow = data.tResumed - data.tSuspended
1428 continue 2231 continue
2232 # acpi_suspend
2233 elif(re.match('acpi_suspend\[.*', t.name)):
2234 # acpi_suspend[0] S0i3
2235 if(re.match('acpi_suspend\[0\] begin', t.name)):
2236 if(sysvals.suspendmode == 'mem'):
2237 tp.S0i3 = True
2238 data.dmesg['suspend_machine']['end'] = t.time
2239 data.tSuspended = t.time
2240 continue
1429 # resume_noirq start 2241 # resume_noirq start
1430 elif(re.match('dpm_resume_noirq\[.*', t.name)): 2242 elif(re.match('dpm_resume_noirq\[.*', t.name)):
1431 phase = 'resume_noirq' 2243 phase = 'resume_noirq'
@@ -1449,30 +2261,25 @@ def parseTraceLog():
1449 if(isbegin): 2261 if(isbegin):
1450 data.dmesg[phase]['start'] = t.time 2262 data.dmesg[phase]['start'] = t.time
1451 continue 2263 continue
1452 2264 # skip trace events inside devices calls
1453 # is this trace event outside of the devices calls 2265 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1454 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): 2266 continue
1455 # global events (outside device calls) are simply graphed 2267 # global events (outside device calls) are graphed
1456 if(name not in testrun.ttemp): 2268 if(name not in testrun.ttemp):
1457 testrun.ttemp[name] = [] 2269 testrun.ttemp[name] = []
1458 if(isbegin): 2270 if(isbegin):
1459 # create a new list entry 2271 # create a new list entry
1460 testrun.ttemp[name].append(\ 2272 testrun.ttemp[name].append(\
1461 {'begin': t.time, 'end': t.time}) 2273 {'begin': t.time, 'end': t.time, 'pid': pid})
1462 else:
1463 if(len(testrun.ttemp[name]) > 0):
1464 # if an antry exists, assume this is its end
1465 testrun.ttemp[name][-1]['end'] = t.time
1466 elif(phase == 'post_resume'):
1467 # post resume events can just have ends
1468 testrun.ttemp[name].append({
1469 'begin': data.dmesg[phase]['start'],
1470 'end': t.time})
1471 else: 2274 else:
1472 if(isbegin): 2275 if(len(testrun.ttemp[name]) > 0):
1473 data.addIntraDevTraceEvent('', name, pid, t.time) 2276 # if an entry exists, assume this is its end
1474 else: 2277 testrun.ttemp[name][-1]['end'] = t.time
1475 data.capIntraDevTraceEvent('', name, pid, t.time) 2278 elif(phase == 'post_resume'):
2279 # post resume events can just have ends
2280 testrun.ttemp[name].append({
2281 'begin': data.dmesg[phase]['start'],
2282 'end': t.time})
1476 # device callback start 2283 # device callback start
1477 elif(t.type == 'device_pm_callback_start'): 2284 elif(t.type == 'device_pm_callback_start'):
1478 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ 2285 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
@@ -1495,75 +2302,127 @@ def parseTraceLog():
1495 dev = list[n] 2302 dev = list[n]
1496 dev['length'] = t.time - dev['start'] 2303 dev['length'] = t.time - dev['start']
1497 dev['end'] = t.time 2304 dev['end'] = t.time
2305 # kprobe event processing
2306 elif(t.fkprobe):
2307 kprobename = t.type
2308 kprobedata = t.name
2309 key = (kprobename, pid)
2310 # displayname is generated from kprobe data
2311 displayname = ''
2312 if(t.fcall):
2313 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2314 if not displayname:
2315 continue
2316 if(key not in tp.ktemp):
2317 tp.ktemp[key] = []
2318 tp.ktemp[key].append({
2319 'pid': pid,
2320 'begin': t.time,
2321 'end': t.time,
2322 'name': displayname,
2323 'cdata': kprobedata,
2324 'proc': m_proc,
2325 })
2326 elif(t.freturn):
2327 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2328 continue
2329 e = tp.ktemp[key][-1]
2330 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2331 tp.ktemp[key].pop()
2332 else:
2333 e['end'] = t.time
2334 e['rdata'] = kprobedata
1498 # callgraph processing 2335 # callgraph processing
1499 elif sysvals.usecallgraph: 2336 elif sysvals.usecallgraph:
1500 # this shouldn't happen, but JIC, ignore callgraph data post-res
1501 if(phase == 'post_resume'):
1502 continue
1503 # create a callgraph object for the data 2337 # create a callgraph object for the data
1504 if(pid not in testrun.ftemp): 2338 key = (m_proc, pid)
1505 testrun.ftemp[pid] = [] 2339 if(key not in testrun.ftemp):
1506 testrun.ftemp[pid].append(FTraceCallGraph()) 2340 testrun.ftemp[key] = []
2341 testrun.ftemp[key].append(FTraceCallGraph(pid))
1507 # when the call is finished, see which device matches it 2342 # when the call is finished, see which device matches it
1508 cg = testrun.ftemp[pid][-1] 2343 cg = testrun.ftemp[key][-1]
1509 if(cg.addLine(t, m)): 2344 if(cg.addLine(t)):
1510 testrun.ftemp[pid].append(FTraceCallGraph()) 2345 testrun.ftemp[key].append(FTraceCallGraph(pid))
1511 tf.close() 2346 tf.close()
1512 2347
2348 if sysvals.suspendmode == 'command':
2349 for test in testruns:
2350 for p in test.data.phases:
2351 if p == 'resume_complete':
2352 test.data.dmesg[p]['start'] = test.data.start
2353 test.data.dmesg[p]['end'] = test.data.end
2354 else:
2355 test.data.dmesg[p]['start'] = test.data.start
2356 test.data.dmesg[p]['end'] = test.data.start
2357 test.data.tSuspended = test.data.start
2358 test.data.tResumed = test.data.start
2359 test.data.tLow = 0
2360 test.data.fwValid = False
2361
1513 for test in testruns: 2362 for test in testruns:
1514 # add the traceevent data to the device hierarchy 2363 # add the traceevent data to the device hierarchy
1515 if(sysvals.usetraceevents): 2364 if(sysvals.usetraceevents):
2365 # add actual trace funcs
1516 for name in test.ttemp: 2366 for name in test.ttemp:
1517 for event in test.ttemp[name]: 2367 for event in test.ttemp[name]:
1518 begin = event['begin'] 2368 test.data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
1519 end = event['end'] 2369 # add the kprobe based virtual tracefuncs as actual devices
1520 # if event starts before timeline start, expand timeline 2370 for key in tp.ktemp:
1521 if(begin < test.data.start): 2371 name, pid = key
1522 test.data.setStart(begin) 2372 if name not in sysvals.tracefuncs:
1523 # if event ends after timeline end, expand the timeline
1524 if(end > test.data.end):
1525 test.data.setEnd(end)
1526 test.data.newActionGlobal(name, begin, end)
1527
1528 # add the callgraph data to the device hierarchy
1529 borderphase = {
1530 'dpm_prepare': 'suspend_prepare',
1531 'dpm_complete': 'resume_complete'
1532 }
1533 for pid in test.ftemp:
1534 for cg in test.ftemp[pid]:
1535 if len(cg.list) < 2:
1536 continue 2373 continue
1537 if(not cg.sanityCheck()): 2374 for e in tp.ktemp[key]:
1538 id = 'task %s cpu %s' % (pid, m.group('cpu')) 2375 kb, ke = e['begin'], e['end']
1539 vprint('Sanity check failed for '+\ 2376 if kb == ke or not test.data.isInsideTimeline(kb, ke):
1540 id+', ignoring this callback') 2377 continue
2378 test.data.newActionGlobal(e['name'], kb, ke, pid)
2379 # add config base kprobes and dev kprobes
2380 for key in tp.ktemp:
2381 name, pid = key
2382 if name in sysvals.tracefuncs:
1541 continue 2383 continue
1542 callstart = cg.start 2384 for e in tp.ktemp[key]:
1543 callend = cg.end 2385 kb, ke = e['begin'], e['end']
1544 if(cg.list[0].name in borderphase): 2386 if kb == ke or not test.data.isInsideTimeline(kb, ke):
1545 p = borderphase[cg.list[0].name] 2387 continue
1546 list = test.data.dmesg[p]['list'] 2388 color = sysvals.kprobeColor(e['name'])
1547 for devname in list: 2389 if name not in sysvals.dev_tracefuncs:
1548 dev = list[devname] 2390 # config base kprobe
1549 if(pid == dev['pid'] and 2391 test.data.newActionGlobal(e['name'], kb, ke, -2, color)
1550 callstart <= dev['start'] and 2392 elif sysvals.usedevsrc:
1551 callend >= dev['end']): 2393 # dev kprobe
1552 dev['ftrace'] = cg.slice(dev['start'], dev['end']) 2394 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
1553 continue 2395 ke, e['cdata'], e['rdata'])
1554 if(cg.list[0].name != 'dpm_run_callback'): 2396 if sysvals.usecallgraph:
1555 continue 2397 # add the callgraph data to the device hierarchy
1556 for p in test.data.phases: 2398 sortlist = dict()
1557 if(test.data.dmesg[p]['start'] <= callstart and 2399 for key in test.ftemp:
1558 callstart <= test.data.dmesg[p]['end']): 2400 proc, pid = key
1559 list = test.data.dmesg[p]['list'] 2401 for cg in test.ftemp[key]:
1560 for devname in list: 2402 if len(cg.list) < 1 or cg.invalid:
1561 dev = list[devname] 2403 continue
1562 if(pid == dev['pid'] and 2404 if(not cg.postProcess()):
1563 callstart <= dev['start'] and 2405 id = 'task %s' % (pid)
1564 callend >= dev['end']): 2406 vprint('Sanity check failed for '+\
1565 dev['ftrace'] = cg 2407 id+', ignoring this callback')
1566 break 2408 continue
2409 # match cg data to devices
2410 if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, test.data):
2411 sortkey = '%f%f%d' % (cg.start, cg.end, pid)
2412 sortlist[sortkey] = cg
2413 # create blocks for orphan cg data
2414 for sortkey in sorted(sortlist):
2415 cg = sortlist[sortkey]
2416 name = cg.list[0].name
2417 if sysvals.isCallgraphFunc(name):
2418 vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
2419 cg.newActionFromFunction(test.data)
2420
2421 if sysvals.suspendmode == 'command':
2422 if(sysvals.verbose):
2423 for data in testdata:
2424 data.printDetails()
2425 return testdata
1567 2426
1568 # fill in any missing phases 2427 # fill in any missing phases
1569 for data in testdata: 2428 for data in testdata:
@@ -1587,14 +2446,52 @@ def parseTraceLog():
1587 if(sysvals.verbose): 2446 if(sysvals.verbose):
1588 data.printDetails() 2447 data.printDetails()
1589 2448
1590 # add the time in between the tests as a new phase so we can see it
1591 if(len(testdata) > 1):
1592 t1e = testdata[0].getEnd()
1593 t2s = testdata[-1].getStart()
1594 testdata[-1].newPhaseWithSingleAction('user mode', \
1595 'user mode', t1e, t2s, '#FF9966')
1596 return testdata 2449 return testdata
1597 2450
2451# Function: loadRawKernelLog
2452# Description:
2453# Load a raw kernel log that wasn't created by this tool, it might be
2454# possible to extract a valid suspend/resume log
2455def loadRawKernelLog(dmesgfile):
2456 global sysvals
2457
2458 stamp = {'time': '', 'host': '', 'mode': 'mem', 'kernel': ''}
2459 stamp['time'] = datetime.now().strftime('%B %d %Y, %I:%M:%S %p')
2460 stamp['host'] = sysvals.hostname
2461
2462 testruns = []
2463 data = 0
2464 lf = open(dmesgfile, 'r')
2465 for line in lf:
2466 line = line.replace('\r\n', '')
2467 idx = line.find('[')
2468 if idx > 1:
2469 line = line[idx:]
2470 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2471 if(not m):
2472 continue
2473 msg = m.group("msg")
2474 m = re.match('PM: Syncing filesystems.*', msg)
2475 if(m):
2476 if(data):
2477 testruns.append(data)
2478 data = Data(len(testruns))
2479 data.stamp = stamp
2480 if(data):
2481 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
2482 if(m):
2483 stamp['kernel'] = m.group('k')
2484 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
2485 if(m):
2486 stamp['mode'] = m.group('m')
2487 data.dmesgtext.append(line)
2488 if(data):
2489 testruns.append(data)
2490 sysvals.stamp = stamp
2491 sysvals.suspendmode = stamp['mode']
2492 lf.close()
2493 return testruns
2494
1598# Function: loadKernelLog 2495# Function: loadKernelLog
1599# Description: 2496# Description:
1600# [deprecated for kernel 3.15.0 or newer] 2497# [deprecated for kernel 3.15.0 or newer]
@@ -1607,9 +2504,10 @@ def loadKernelLog():
1607 2504
1608 vprint('Analyzing the dmesg data...') 2505 vprint('Analyzing the dmesg data...')
1609 if(os.path.exists(sysvals.dmesgfile) == False): 2506 if(os.path.exists(sysvals.dmesgfile) == False):
1610 doError('%s doesnt exist' % sysvals.dmesgfile, False) 2507 doError('%s does not exist' % sysvals.dmesgfile, False)
1611 2508
1612 # there can be multiple test runs in a single file delineated by stamps 2509 # there can be multiple test runs in a single file
2510 tp = TestProps()
1613 testruns = [] 2511 testruns = []
1614 data = 0 2512 data = 0
1615 lf = open(sysvals.dmesgfile, 'r') 2513 lf = open(sysvals.dmesgfile, 'r')
@@ -1620,35 +2518,43 @@ def loadKernelLog():
1620 line = line[idx:] 2518 line = line[idx:]
1621 m = re.match(sysvals.stampfmt, line) 2519 m = re.match(sysvals.stampfmt, line)
1622 if(m): 2520 if(m):
1623 if(data): 2521 tp.stamp = line
1624 testruns.append(data)
1625 data = Data(len(testruns))
1626 parseStamp(m, data)
1627 continue
1628 if(not data):
1629 continue 2522 continue
1630 m = re.match(sysvals.firmwarefmt, line) 2523 m = re.match(sysvals.firmwarefmt, line)
1631 if(m): 2524 if(m):
1632 data.fwSuspend = int(m.group('s')) 2525 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
1633 data.fwResume = int(m.group('r'))
1634 if(data.fwSuspend > 0 or data.fwResume > 0):
1635 data.fwValid = True
1636 continue 2526 continue
1637 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 2527 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1638 if(m): 2528 if(not m):
1639 data.dmesgtext.append(line) 2529 continue
1640 if(re.match('ACPI: resume from mwait', m.group('msg'))): 2530 msg = m.group("msg")
1641 print('NOTE: This suspend appears to be freeze rather than'+\ 2531 if(re.match('PM: Syncing filesystems.*', msg)):
1642 ' %s, it will be treated as such' % sysvals.suspendmode) 2532 if(data):
1643 sysvals.suspendmode = 'freeze' 2533 testruns.append(data)
1644 else: 2534 data = Data(len(testruns))
1645 vprint('ignoring dmesg line: %s' % line.replace('\n', '')) 2535 parseStamp(tp.stamp, data)
1646 testruns.append(data) 2536 if len(tp.fwdata) > data.testnumber:
2537 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2538 if(data.fwSuspend > 0 or data.fwResume > 0):
2539 data.fwValid = True
2540 if(re.match('ACPI: resume from mwait', msg)):
2541 print('NOTE: This suspend appears to be freeze rather than'+\
2542 ' %s, it will be treated as such' % sysvals.suspendmode)
2543 sysvals.suspendmode = 'freeze'
2544 if(not data):
2545 continue
2546 data.dmesgtext.append(line)
2547 if(data):
2548 testruns.append(data)
1647 lf.close() 2549 lf.close()
1648 2550
1649 if(not data): 2551 if(len(testruns) < 1):
1650 print('ERROR: analyze_suspend header missing from dmesg log') 2552 # bad log, but see if you can extract something meaningful anyway
1651 sys.exit() 2553 testruns = loadRawKernelLog(sysvals.dmesgfile)
2554
2555 if(len(testruns) < 1):
2556 doError(' dmesg log is completely unreadable: %s' \
2557 % sysvals.dmesgfile, False)
1652 2558
1653 # fix lines with same timestamp/function with the call and return swapped 2559 # fix lines with same timestamp/function with the call and return swapped
1654 for data in testruns: 2560 for data in testruns:
@@ -1865,7 +2771,8 @@ def parseKernelLog(data):
1865 actions[a] = [] 2771 actions[a] = []
1866 actions[a].append({'begin': ktime, 'end': ktime}) 2772 actions[a].append({'begin': ktime, 'end': ktime})
1867 if(re.match(at[a]['emsg'], msg)): 2773 if(re.match(at[a]['emsg'], msg)):
1868 actions[a][-1]['end'] = ktime 2774 if(a in actions):
2775 actions[a][-1]['end'] = ktime
1869 # now look for CPU on/off events 2776 # now look for CPU on/off events
1870 if(re.match('Disabling non-boot CPUs .*', msg)): 2777 if(re.match('Disabling non-boot CPUs .*', msg)):
1871 # start of first cpu suspend 2778 # start of first cpu suspend
@@ -1912,15 +2819,7 @@ def parseKernelLog(data):
1912 # fill in any actions we've found 2819 # fill in any actions we've found
1913 for name in actions: 2820 for name in actions:
1914 for event in actions[name]: 2821 for event in actions[name]:
1915 begin = event['begin'] 2822 data.newActionGlobal(name, event['begin'], event['end'])
1916 end = event['end']
1917 # if event starts before timeline start, expand timeline
1918 if(begin < data.start):
1919 data.setStart(begin)
1920 # if event ends after timeline end, expand the timeline
1921 if(end > data.end):
1922 data.setEnd(end)
1923 data.newActionGlobal(name, begin, end)
1924 2823
1925 if(sysvals.verbose): 2824 if(sysvals.verbose):
1926 data.printDetails() 2825 data.printDetails()
@@ -1929,92 +2828,6 @@ def parseKernelLog(data):
1929 data.fixupInitcallsThatDidntReturn() 2828 data.fixupInitcallsThatDidntReturn()
1930 return True 2829 return True
1931 2830
1932# Function: setTimelineRows
1933# Description:
1934# Organize the timeline entries into the smallest
1935# number of rows possible, with no entry overlapping
1936# Arguments:
1937# list: the list of devices/actions for a single phase
1938# sortedkeys: cronologically sorted key list to use
1939# Output:
1940# The total number of rows needed to display this phase of the timeline
1941def setTimelineRows(list, sortedkeys):
1942
1943 # clear all rows and set them to undefined
1944 remaining = len(list)
1945 rowdata = dict()
1946 row = 0
1947 for item in list:
1948 list[item]['row'] = -1
1949
1950 # try to pack each row with as many ranges as possible
1951 while(remaining > 0):
1952 if(row not in rowdata):
1953 rowdata[row] = []
1954 for item in sortedkeys:
1955 if(list[item]['row'] < 0):
1956 s = list[item]['start']
1957 e = list[item]['end']
1958 valid = True
1959 for ritem in rowdata[row]:
1960 rs = ritem['start']
1961 re = ritem['end']
1962 if(not (((s <= rs) and (e <= rs)) or
1963 ((s >= re) and (e >= re)))):
1964 valid = False
1965 break
1966 if(valid):
1967 rowdata[row].append(list[item])
1968 list[item]['row'] = row
1969 remaining -= 1
1970 row += 1
1971 return row
1972
1973# Function: createTimeScale
1974# Description:
1975# Create the timescale header for the html timeline
1976# Arguments:
1977# t0: start time (suspend begin)
1978# tMax: end time (resume end)
1979# tSuspend: time when suspend occurs, i.e. the zero time
1980# Output:
1981# The html code needed to display the time scale
1982def createTimeScale(t0, tMax, tSuspended):
1983 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1984 output = '<div id="timescale">\n'
1985
1986 # set scale for timeline
1987 tTotal = tMax - t0
1988 tS = 0.1
1989 if(tTotal <= 0):
1990 return output
1991 if(tTotal > 4):
1992 tS = 1
1993 if(tSuspended < 0):
1994 for i in range(int(tTotal/tS)+1):
1995 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal))
1996 if(i > 0):
1997 val = '%0.fms' % (float(i)*tS*1000)
1998 else:
1999 val = ''
2000 output += timescale.format(pos, val)
2001 else:
2002 tSuspend = tSuspended - t0
2003 divTotal = int(tTotal/tS) + 1
2004 divSuspend = int(tSuspend/tS)
2005 s0 = (tSuspend - tS*divSuspend)*100/tTotal
2006 for i in range(divTotal):
2007 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0)
2008 if((i == 0) and (s0 < 3)):
2009 val = ''
2010 elif(i == divSuspend):
2011 val = 'S/R'
2012 else:
2013 val = '%0.fms' % (float(i-divSuspend)*tS*1000)
2014 output += timescale.format(pos, val)
2015 output += '</div>\n'
2016 return output
2017
2018# Function: createHTMLSummarySimple 2831# Function: createHTMLSummarySimple
2019# Description: 2832# Description:
2020# Create summary html file for a series of tests 2833# Create summary html file for a series of tests
@@ -2146,6 +2959,32 @@ def createHTMLSummarySimple(testruns, htmlfile):
2146 hf.write('</body>\n</html>\n') 2959 hf.write('</body>\n</html>\n')
2147 hf.close() 2960 hf.close()
2148 2961
2962def htmlTitle():
2963 global sysvals
2964 modename = {
2965 'freeze': 'Freeze (S0)',
2966 'standby': 'Standby (S1)',
2967 'mem': 'Suspend (S3)',
2968 'disk': 'Hibernate (S4)'
2969 }
2970 kernel = sysvals.stamp['kernel']
2971 host = sysvals.hostname[0].upper()+sysvals.hostname[1:]
2972 mode = sysvals.suspendmode
2973 if sysvals.suspendmode in modename:
2974 mode = modename[sysvals.suspendmode]
2975 return host+' '+mode+' '+kernel
2976
2977def ordinal(value):
2978 suffix = 'th'
2979 if value < 10 or value > 19:
2980 if value % 10 == 1:
2981 suffix = 'st'
2982 elif value % 10 == 2:
2983 suffix = 'nd'
2984 elif value % 10 == 3:
2985 suffix = 'rd'
2986 return '%d%s' % (value, suffix)
2987
2149# Function: createHTML 2988# Function: createHTML
2150# Description: 2989# Description:
2151# Create the output html file from the resident test data 2990# Create the output html file from the resident test data
@@ -2156,6 +2995,10 @@ def createHTMLSummarySimple(testruns, htmlfile):
2156def createHTML(testruns): 2995def createHTML(testruns):
2157 global sysvals 2996 global sysvals
2158 2997
2998 if len(testruns) < 1:
2999 print('ERROR: Not enough test data to build a timeline')
3000 return
3001
2159 for data in testruns: 3002 for data in testruns:
2160 data.normalizeTime(testruns[-1].tSuspended) 3003 data.normalizeTime(testruns[-1].tSuspended)
2161 3004
@@ -2163,16 +3006,18 @@ def createHTML(testruns):
2163 if len(testruns) > 1: 3006 if len(testruns) > 1:
2164 x2changes = ['1', 'relative'] 3007 x2changes = ['1', 'relative']
2165 # html function templates 3008 # html function templates
3009 headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version
2166 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' 3010 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
2167 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0] 3011 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
2168 html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n' 3012 html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
2169 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n' 3013 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
2170 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n' 3014 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
2171 html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n' 3015 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;">\n'
2172 html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n' 3016 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'
2173 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n' 3017 html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{5}</div>\n'
3018 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
2174 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n' 3019 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
2175 html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n' 3020 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
2176 html_timetotal = '<table class="time1">\n<tr>'\ 3021 html_timetotal = '<table class="time1">\n<tr>'\
2177 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\ 3022 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
2178 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\ 3023 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
@@ -2182,6 +3027,10 @@ def createHTML(testruns):
2182 '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\ 3027 '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
2183 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\ 3028 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
2184 '</tr>\n</table>\n' 3029 '</tr>\n</table>\n'
3030 html_timetotal3 = '<table class="time1">\n<tr>'\
3031 '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3032 '<td class="yellow">Command: <b>{1}</b></td>'\
3033 '</tr>\n</table>\n'
2185 html_timegroups = '<table class="time2">\n<tr>'\ 3034 html_timegroups = '<table class="time2">\n<tr>'\
2186 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\ 3035 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\
2187 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\ 3036 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
@@ -2189,12 +3038,21 @@ def createHTML(testruns):
2189 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\ 3038 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
2190 '</tr>\n</table>\n' 3039 '</tr>\n</table>\n'
2191 3040
3041 # html format variables
3042 rowheight = 30
3043 devtextS = '14px'
3044 devtextH = '30px'
3045 hoverZ = 'z-index:10;'
3046
3047 if sysvals.usedevsrc:
3048 hoverZ = ''
3049
2192 # device timeline 3050 # device timeline
2193 vprint('Creating Device Timeline...') 3051 vprint('Creating Device Timeline...')
2194 devtl = Timeline() 3052
3053 devtl = Timeline(rowheight)
2195 3054
2196 # Generate the header for this timeline 3055 # Generate the header for this timeline
2197 textnum = ['First', 'Second']
2198 for data in testruns: 3056 for data in testruns:
2199 tTotal = data.end - data.start 3057 tTotal = data.end - data.start
2200 tEnd = data.dmesg['resume_complete']['end'] 3058 tEnd = data.dmesg['resume_complete']['end']
@@ -2203,7 +3061,17 @@ def createHTML(testruns):
2203 sys.exit() 3061 sys.exit()
2204 if(data.tLow > 0): 3062 if(data.tLow > 0):
2205 low_time = '%.0f'%(data.tLow*1000) 3063 low_time = '%.0f'%(data.tLow*1000)
2206 if data.fwValid: 3064 if sysvals.suspendmode == 'command':
3065 run_time = '%.0f'%((data.end-data.start)*1000)
3066 if sysvals.testcommand:
3067 testdesc = sysvals.testcommand
3068 else:
3069 testdesc = 'unknown'
3070 if(len(testruns) > 1):
3071 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3072 thtml = html_timetotal3.format(run_time, testdesc)
3073 devtl.html['header'] += thtml
3074 elif data.fwValid:
2207 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \ 3075 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \
2208 (data.fwSuspend/1000000.0)) 3076 (data.fwSuspend/1000000.0))
2209 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \ 3077 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \
@@ -2211,7 +3079,7 @@ def createHTML(testruns):
2211 testdesc1 = 'Total' 3079 testdesc1 = 'Total'
2212 testdesc2 = '' 3080 testdesc2 = ''
2213 if(len(testruns) > 1): 3081 if(len(testruns) > 1):
2214 testdesc1 = testdesc2 = textnum[data.testnumber] 3082 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
2215 testdesc2 += ' ' 3083 testdesc2 += ' '
2216 if(data.tLow == 0): 3084 if(data.tLow == 0):
2217 thtml = html_timetotal.format(suspend_time, \ 3085 thtml = html_timetotal.format(suspend_time, \
@@ -2219,28 +3087,28 @@ def createHTML(testruns):
2219 else: 3087 else:
2220 thtml = html_timetotal2.format(suspend_time, low_time, \ 3088 thtml = html_timetotal2.format(suspend_time, low_time, \
2221 resume_time, testdesc1) 3089 resume_time, testdesc1)
2222 devtl.html['timeline'] += thtml 3090 devtl.html['header'] += thtml
2223 sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \ 3091 sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \
2224 data.getStart())*1000) 3092 data.getStart())*1000)
2225 sftime = '%.3f'%(data.fwSuspend / 1000000.0) 3093 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
2226 rftime = '%.3f'%(data.fwResume / 1000000.0) 3094 rftime = '%.3f'%(data.fwResume / 1000000.0)
2227 rktime = '%.3f'%((data.getEnd() - \ 3095 rktime = '%.3f'%((data.dmesg['resume_complete']['end'] - \
2228 data.dmesg['resume_machine']['start'])*1000) 3096 data.dmesg['resume_machine']['start'])*1000)
2229 devtl.html['timeline'] += html_timegroups.format(sktime, \ 3097 devtl.html['header'] += html_timegroups.format(sktime, \
2230 sftime, rftime, rktime, testdesc2) 3098 sftime, rftime, rktime, testdesc2)
2231 else: 3099 else:
2232 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000) 3100 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
2233 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000) 3101 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
2234 testdesc = 'Kernel' 3102 testdesc = 'Kernel'
2235 if(len(testruns) > 1): 3103 if(len(testruns) > 1):
2236 testdesc = textnum[data.testnumber]+' '+testdesc 3104 testdesc = ordinal(data.testnumber+1)+' '+testdesc
2237 if(data.tLow == 0): 3105 if(data.tLow == 0):
2238 thtml = html_timetotal.format(suspend_time, \ 3106 thtml = html_timetotal.format(suspend_time, \
2239 resume_time, testdesc) 3107 resume_time, testdesc)
2240 else: 3108 else:
2241 thtml = html_timetotal2.format(suspend_time, low_time, \ 3109 thtml = html_timetotal2.format(suspend_time, low_time, \
2242 resume_time, testdesc) 3110 resume_time, testdesc)
2243 devtl.html['timeline'] += thtml 3111 devtl.html['header'] += thtml
2244 3112
2245 # time scale for potentially multiple datasets 3113 # time scale for potentially multiple datasets
2246 t0 = testruns[0].start 3114 t0 = testruns[0].start
@@ -2249,153 +3117,241 @@ def createHTML(testruns):
2249 tTotal = tMax - t0 3117 tTotal = tMax - t0
2250 3118
2251 # determine the maximum number of rows we need to draw 3119 # determine the maximum number of rows we need to draw
2252 timelinerows = 0
2253 for data in testruns: 3120 for data in testruns:
2254 for phase in data.dmesg: 3121 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
2255 list = data.dmesg[phase]['list'] 3122 for group in data.devicegroups:
2256 rows = setTimelineRows(list, list) 3123 devlist = []
2257 data.dmesg[phase]['row'] = rows 3124 for phase in group:
2258 if(rows > timelinerows): 3125 for devname in data.tdevlist[phase]:
2259 timelinerows = rows 3126 devlist.append((phase,devname))
2260 3127 devtl.getPhaseRows(data.dmesg, devlist)
2261 # calculate the timeline height and create bounding box, add buttons 3128 devtl.calcTotalRows()
2262 devtl.setRows(timelinerows + 1) 3129
2263 devtl.html['timeline'] += html_devlist1 3130 # create bounding box, add buttons
2264 if len(testruns) > 1: 3131 if sysvals.suspendmode != 'command':
2265 devtl.html['timeline'] += html_devlist2 3132 devtl.html['timeline'] += html_devlist1
3133 if len(testruns) > 1:
3134 devtl.html['timeline'] += html_devlist2
2266 devtl.html['timeline'] += html_zoombox 3135 devtl.html['timeline'] += html_zoombox
2267 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) 3136 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
2268 3137
2269 # draw the colored boxes for each of the phases 3138 # draw the full timeline
2270 for data in testruns: 3139 phases = {'suspend':[],'resume':[]}
2271 for b in data.dmesg: 3140 for phase in data.dmesg:
2272 phase = data.dmesg[b] 3141 if 'resume' in phase:
2273 length = phase['end']-phase['start'] 3142 phases['resume'].append(phase)
2274 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 3143 else:
2275 width = '%.3f' % ((length*100.0)/tTotal) 3144 phases['suspend'].append(phase)
2276 devtl.html['timeline'] += html_phase.format(left, width, \
2277 '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \
2278 data.dmesg[b]['color'], '')
2279 3145
2280 # draw the time scale, try to make the number of labels readable 3146 # draw each test run chronologically
2281 devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended)
2282 devtl.html['timeline'] += devtl.html['scale']
2283 for data in testruns: 3147 for data in testruns:
2284 for b in data.dmesg: 3148 # if nore than one test, draw a block to represent user mode
2285 phaselist = data.dmesg[b]['list'] 3149 if(data.testnumber > 0):
2286 for d in phaselist: 3150 m0 = testruns[data.testnumber-1].end
2287 name = d 3151 mMax = testruns[data.testnumber].start
2288 drv = '' 3152 mTotal = mMax - m0
2289 dev = phaselist[d] 3153 name = 'usermode%d' % data.testnumber
2290 if(d in sysvals.altdevname): 3154 top = '%d' % devtl.scaleH
2291 name = sysvals.altdevname[d] 3155 left = '%f' % (((m0-t0)*100.0)/tTotal)
2292 if('drv' in dev and dev['drv']): 3156 width = '%f' % ((mTotal*100.0)/tTotal)
2293 drv = ' {%s}' % dev['drv'] 3157 title = 'user mode (%0.3f ms) ' % (mTotal*1000)
2294 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 3158 devtl.html['timeline'] += html_device.format(name, \
2295 top = '%.3f' % ((dev['row']*height) + devtl.scaleH) 3159 title, left, top, '%d'%devtl.bodyH, width, '', '', '')
2296 left = '%.3f' % (((dev['start']-t0)*100)/tTotal) 3160 # now draw the actual timeline blocks
2297 width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal) 3161 for dir in phases:
2298 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) 3162 # draw suspend and resume blocks separately
2299 color = 'rgba(204,204,204,0.5)' 3163 bname = '%s%d' % (dir[0], data.testnumber)
2300 devtl.html['timeline'] += html_device.format(dev['id'], \ 3164 if dir == 'suspend':
2301 d+drv+length+b, left, top, '%.3f'%height, width, name+drv) 3165 m0 = testruns[data.testnumber].start
2302 3166 mMax = testruns[data.testnumber].tSuspended
2303 # draw any trace events found 3167 mTotal = mMax - m0
2304 for data in testruns: 3168 left = '%f' % (((m0-t0)*100.0)/tTotal)
2305 for b in data.dmesg: 3169 else:
2306 phaselist = data.dmesg[b]['list'] 3170 m0 = testruns[data.testnumber].tSuspended
2307 for name in phaselist: 3171 mMax = testruns[data.testnumber].end
2308 dev = phaselist[name] 3172 mTotal = mMax - m0
2309 if('traceevents' in dev): 3173 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
2310 vprint('Debug trace events found for device %s' % name) 3174 # if a timeline block is 0 length, skip altogether
2311 vprint('%20s %20s %10s %8s' % ('action', \ 3175 if mTotal == 0:
3176 continue
3177 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3178 devtl.html['timeline'] += html_tblock.format(bname, left, width)
3179 for b in sorted(phases[dir]):
3180 # draw the phase color background
3181 phase = data.dmesg[b]
3182 length = phase['end']-phase['start']
3183 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
3184 width = '%f' % ((length*100.0)/mTotal)
3185 devtl.html['timeline'] += html_phase.format(left, width, \
3186 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
3187 data.dmesg[b]['color'], '')
3188 # draw the devices for this phase
3189 phaselist = data.dmesg[b]['list']
3190 for d in data.tdevlist[b]:
3191 name = d
3192 drv = ''
3193 dev = phaselist[d]
3194 xtraclass = ''
3195 xtrainfo = ''
3196 xtrastyle = ''
3197 if 'htmlclass' in dev:
3198 xtraclass = dev['htmlclass']
3199 xtrainfo = dev['htmlclass']
3200 if 'color' in dev:
3201 xtrastyle = 'background-color:%s;' % dev['color']
3202 if(d in sysvals.devprops):
3203 name = sysvals.devprops[d].altName(d)
3204 xtraclass = sysvals.devprops[d].xtraClass()
3205 xtrainfo = sysvals.devprops[d].xtraInfo()
3206 if('drv' in dev and dev['drv']):
3207 drv = ' {%s}' % dev['drv']
3208 rowheight = devtl.phaseRowHeight(b, dev['row'])
3209 rowtop = devtl.phaseRowTop(b, dev['row'])
3210 top = '%.3f' % (rowtop + devtl.scaleH)
3211 left = '%f' % (((dev['start']-m0)*100)/mTotal)
3212 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
3213 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
3214 if sysvals.suspendmode == 'command':
3215 title = name+drv+xtrainfo+length+'cmdexec'
3216 else:
3217 title = name+drv+xtrainfo+length+b
3218 devtl.html['timeline'] += html_device.format(dev['id'], \
3219 title, left, top, '%.3f'%rowheight, width, \
3220 d+drv, xtraclass, xtrastyle)
3221 if('src' not in dev):
3222 continue
3223 # draw any trace events for this device
3224 vprint('Debug trace events found for device %s' % d)
3225 vprint('%20s %20s %10s %8s' % ('title', \
2312 'name', 'time(ms)', 'length(ms)')) 3226 'name', 'time(ms)', 'length(ms)'))
2313 for e in dev['traceevents']: 3227 for e in dev['src']:
2314 vprint('%20s %20s %10.3f %8.3f' % (e.action, \ 3228 vprint('%20s %20s %10.3f %8.3f' % (e.title, \
2315 e.name, e.time*1000, e.length*1000)) 3229 e.text, e.time*1000, e.length*1000))
2316 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 3230 height = devtl.rowH
2317 top = '%.3f' % ((dev['row']*height) + devtl.scaleH) 3231 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
2318 left = '%.3f' % (((e.time-t0)*100)/tTotal) 3232 left = '%f' % (((e.time-m0)*100)/mTotal)
2319 width = '%.3f' % (e.length*100/tTotal) 3233 width = '%f' % (e.length*100/mTotal)
2320 color = 'rgba(204,204,204,0.5)' 3234 color = 'rgba(204,204,204,0.5)'
2321 devtl.html['timeline'] += \ 3235 devtl.html['timeline'] += \
2322 html_traceevent.format(e.action+' '+e.name, \ 3236 html_traceevent.format(e.title, \
2323 left, top, '%.3f'%height, \ 3237 left, top, '%.3f'%height, \
2324 width, e.color, '') 3238 width, e.text)
3239 # draw the time scale, try to make the number of labels readable
3240 devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir)
3241 devtl.html['timeline'] += '</div>\n'
2325 3242
2326 # timeline is finished 3243 # timeline is finished
2327 devtl.html['timeline'] += '</div>\n</div>\n' 3244 devtl.html['timeline'] += '</div>\n</div>\n'
2328 3245
2329 # draw a legend which describes the phases by color 3246 # draw a legend which describes the phases by color
2330 data = testruns[-1] 3247 if sysvals.suspendmode != 'command':
2331 devtl.html['legend'] = '<div class="legend">\n' 3248 data = testruns[-1]
2332 pdelta = 100.0/len(data.phases) 3249 devtl.html['legend'] = '<div class="legend">\n'
2333 pmargin = pdelta / 4.0 3250 pdelta = 100.0/len(data.phases)
2334 for phase in data.phases: 3251 pmargin = pdelta / 4.0
2335 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) 3252 for phase in data.phases:
2336 name = string.replace(phase, '_', ' &nbsp;') 3253 tmp = phase.split('_')
2337 devtl.html['legend'] += html_legend.format(order, \ 3254 id = tmp[0][0]
2338 data.dmesg[phase]['color'], name) 3255 if(len(tmp) > 1):
2339 devtl.html['legend'] += '</div>\n' 3256 id += tmp[1][0]
3257 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3258 name = string.replace(phase, '_', ' &nbsp;')
3259 devtl.html['legend'] += html_legend.format(order, \
3260 data.dmesg[phase]['color'], name, id)
3261 devtl.html['legend'] += '</div>\n'
2340 3262
2341 hf = open(sysvals.htmlfile, 'w') 3263 hf = open(sysvals.htmlfile, 'w')
2342 thread_height = 0 3264
3265 if not sysvals.cgexp:
3266 cgchk = 'checked'
3267 cgnchk = 'not(:checked)'
3268 else:
3269 cgchk = 'not(:checked)'
3270 cgnchk = 'checked'
2343 3271
2344 # write the html header first (html head, css code, up to body start) 3272 # write the html header first (html head, css code, up to body start)
2345 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\ 3273 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
2346 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 3274 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2347 <title>AnalyzeSuspend</title>\n\ 3275 <title>'+htmlTitle()+'</title>\n\
2348 <style type=\'text/css\'>\n\ 3276 <style type=\'text/css\'>\n\
2349 body {overflow-y: scroll;}\n\ 3277 body {overflow-y:scroll;}\n\
2350 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\ 3278 .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\
2351 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\ 3279 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
2352 .callgraph article * {padding-left: 28px;}\n\ 3280 .callgraph article * {padding-left:28px;}\n\
2353 h1 {color:black;font: bold 30px Times;}\n\ 3281 h1 {color:black;font:bold 30px Times;}\n\
2354 t0 {color:black;font: bold 30px Times;}\n\ 3282 t0 {color:black;font:bold 30px Times;}\n\
2355 t1 {color:black;font: 30px Times;}\n\ 3283 t1 {color:black;font:30px Times;}\n\
2356 t2 {color:black;font: 25px Times;}\n\ 3284 t2 {color:black;font:25px Times;}\n\
2357 t3 {color:black;font: 20px Times;white-space:nowrap;}\n\ 3285 t3 {color:black;font:20px Times;white-space:nowrap;}\n\
2358 t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\ 3286 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
3287 cS {color:blue;font:bold 11px Times;}\n\
3288 cR {color:red;font:bold 11px Times;}\n\
2359 table {width:100%;}\n\ 3289 table {width:100%;}\n\
2360 .gray {background-color:rgba(80,80,80,0.1);}\n\ 3290 .gray {background-color:rgba(80,80,80,0.1);}\n\
2361 .green {background-color:rgba(204,255,204,0.4);}\n\ 3291 .green {background-color:rgba(204,255,204,0.4);}\n\
2362 .purple {background-color:rgba(128,0,128,0.2);}\n\ 3292 .purple {background-color:rgba(128,0,128,0.2);}\n\
2363 .yellow {background-color:rgba(255,255,204,0.4);}\n\ 3293 .yellow {background-color:rgba(255,255,204,0.4);}\n\
2364 .time1 {font: 22px Arial;border:1px solid;}\n\ 3294 .time1 {font:22px Arial;border:1px solid;}\n\
2365 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ 3295 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
2366 td {text-align: center;}\n\ 3296 td {text-align:center;}\n\
2367 r {color:#500000;font:15px Tahoma;}\n\ 3297 r {color:#500000;font:15px Tahoma;}\n\
2368 n {color:#505050;font:15px Tahoma;}\n\ 3298 n {color:#505050;font:15px Tahoma;}\n\
2369 .tdhl {color: red;}\n\ 3299 .tdhl {color:red;}\n\
2370 .hide {display: none;}\n\ 3300 .hide {display:none;}\n\
2371 .pf {display: none;}\n\ 3301 .pf {display:none;}\n\
2372 .pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ 3302 .pf:'+cgchk+' + label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
2373 .pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ 3303 .pf:'+cgnchk+' ~ label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
2374 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\ 3304 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
2375 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\ 3305 .zoombox {position:relative;width:100%;overflow-x:scroll;}\n\
2376 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\ 3306 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
2377 .thread {position: absolute; height: '+'%.3f'%thread_height+'%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\ 3307 .thread {position:absolute;height:0%;overflow:hidden;line-height:'+devtextH+';font-size:'+devtextS+';border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
2378 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\ 3308 .thread.sync {background-color:'+sysvals.synccolor+';}\n\
2379 .hover {background-color:white;border:1px solid red;z-index:10;}\n\ 3309 .thread.bg {background-color:'+sysvals.kprobecolor+';}\n\
2380 .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\ 3310 .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
2381 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\ 3311 .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
3312 .hover.sync {background-color:white;}\n\
3313 .hover.bg {background-color:white;}\n\
3314 .traceevent {position:absolute;font-size:10px;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,rgba(204,204,204,1),rgba(150,150,150,1));}\n\
3315 .traceevent:hover {background:white;}\n\
3316 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
2382 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\ 3317 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
2383 .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\ 3318 .t {z-index:2;position:absolute;pointer-events:none;top:0%;height:100%;border-right:1px solid black;}\n\
2384 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\ 3319 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
2385 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\ 3320 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
2386 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ 3321 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
3322 .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
2387 .devlist {position:'+x2changes[1]+';width:190px;}\n\ 3323 .devlist {position:'+x2changes[1]+';width:190px;}\n\
2388 #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\ 3324 a:link {color:white;text-decoration:none;}\n\
3325 a:visited {color:white;}\n\
3326 a:hover {color:white;}\n\
3327 a:active {color:white;}\n\
3328 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
3329 #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\
3330 .tblock {position:absolute;height:100%;}\n\
3331 .bg {z-index:1;}\n\
2389 </style>\n</head>\n<body>\n' 3332 </style>\n</head>\n<body>\n'
2390 hf.write(html_header) 3333
3334 # no header or css if its embedded
3335 if(sysvals.embedded):
3336 hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
3337 (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \
3338 data.fwSuspend/1000000, data.fwResume/1000000))
3339 else:
3340 hf.write(html_header)
2391 3341
2392 # write the test title and general info header 3342 # write the test title and general info header
2393 if(sysvals.stamp['time'] != ""): 3343 if(sysvals.stamp['time'] != ""):
3344 hf.write(headline_version)
3345 if sysvals.addlogs and sysvals.dmesgfile:
3346 hf.write('<button id="showdmesg" class="logbtn">dmesg</button>')
3347 if sysvals.addlogs and sysvals.ftracefile:
3348 hf.write('<button id="showftrace" class="logbtn">ftrace</button>')
2394 hf.write(headline_stamp.format(sysvals.stamp['host'], 3349 hf.write(headline_stamp.format(sysvals.stamp['host'],
2395 sysvals.stamp['kernel'], sysvals.stamp['mode'], \ 3350 sysvals.stamp['kernel'], sysvals.stamp['mode'], \
2396 sysvals.stamp['time'])) 3351 sysvals.stamp['time']))
2397 3352
2398 # write the device timeline 3353 # write the device timeline
3354 hf.write(devtl.html['header'])
2399 hf.write(devtl.html['timeline']) 3355 hf.write(devtl.html['timeline'])
2400 hf.write(devtl.html['legend']) 3356 hf.write(devtl.html['legend'])
2401 hf.write('<div id="devicedetailtitle"></div>\n') 3357 hf.write('<div id="devicedetailtitle"></div>\n')
@@ -2410,12 +3366,15 @@ def createHTML(testruns):
2410 width = '%.3f' % ((length*100.0)/tTotal) 3366 width = '%.3f' % ((length*100.0)/tTotal)
2411 hf.write(html_phaselet.format(b, left, width, \ 3367 hf.write(html_phaselet.format(b, left, width, \
2412 data.dmesg[b]['color'])) 3368 data.dmesg[b]['color']))
3369 if sysvals.suspendmode == 'command':
3370 hf.write(html_phaselet.format('cmdexec', '0', '0', \
3371 data.dmesg['resume_complete']['color']))
2413 hf.write('</div>\n') 3372 hf.write('</div>\n')
2414 hf.write('</div>\n') 3373 hf.write('</div>\n')
2415 3374
2416 # write the ftrace data (callgraph) 3375 # write the ftrace data (callgraph)
2417 data = testruns[-1] 3376 data = testruns[-1]
2418 if(sysvals.usecallgraph): 3377 if(sysvals.usecallgraph and not sysvals.embedded):
2419 hf.write('<section id="callgraphs" class="callgraph">\n') 3378 hf.write('<section id="callgraphs" class="callgraph">\n')
2420 # write out the ftrace data converted to html 3379 # write out the ftrace data converted to html
2421 html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n' 3380 html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
@@ -2428,22 +3387,29 @@ def createHTML(testruns):
2428 for devname in data.sortedDevices(p): 3387 for devname in data.sortedDevices(p):
2429 if('ftrace' not in list[devname]): 3388 if('ftrace' not in list[devname]):
2430 continue 3389 continue
2431 name = devname
2432 if(devname in sysvals.altdevname):
2433 name = sysvals.altdevname[devname]
2434 devid = list[devname]['id'] 3390 devid = list[devname]['id']
2435 cg = list[devname]['ftrace'] 3391 cg = list[devname]['ftrace']
2436 flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \ 3392 clen = (cg.end - cg.start) * 1000
2437 ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000) 3393 if clen < sysvals.mincglen:
3394 continue
3395 fmt = '<r>(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')</r>'
3396 flen = fmt % (clen, cg.start, cg.end)
3397 name = devname
3398 if(devname in sysvals.devprops):
3399 name = sysvals.devprops[devname].altName(devname)
3400 if sysvals.suspendmode == 'command':
3401 ftitle = name
3402 else:
3403 ftitle = name+' '+p
2438 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \ 3404 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
2439 num, name+' '+p, flen)) 3405 num, ftitle, flen))
2440 num += 1 3406 num += 1
2441 for line in cg.list: 3407 for line in cg.list:
2442 if(line.length < 0.000000001): 3408 if(line.length < 0.000000001):
2443 flen = '' 3409 flen = ''
2444 else: 3410 else:
2445 flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \ 3411 fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>'
2446 line.time*1000) 3412 flen = fmt % (line.length*1000, line.time)
2447 if(line.freturn and line.fcall): 3413 if(line.freturn and line.fcall):
2448 hf.write(html_func_leaf.format(line.name, flen)) 3414 hf.write(html_func_leaf.format(line.name, flen))
2449 elif(line.freturn): 3415 elif(line.freturn):
@@ -2453,9 +3419,40 @@ def createHTML(testruns):
2453 num += 1 3419 num += 1
2454 hf.write(html_func_end) 3420 hf.write(html_func_end)
2455 hf.write('\n\n </section>\n') 3421 hf.write('\n\n </section>\n')
2456 # write the footer and close 3422
2457 addScriptCode(hf, testruns) 3423 # add the dmesg log as a hidden div
2458 hf.write('</body>\n</html>\n') 3424 if sysvals.addlogs and sysvals.dmesgfile:
3425 hf.write('<div id="dmesglog" style="display:none;">\n')
3426 lf = open(sysvals.dmesgfile, 'r')
3427 for line in lf:
3428 hf.write(line)
3429 lf.close()
3430 hf.write('</div>\n')
3431 # add the ftrace log as a hidden div
3432 if sysvals.addlogs and sysvals.ftracefile:
3433 hf.write('<div id="ftracelog" style="display:none;">\n')
3434 lf = open(sysvals.ftracefile, 'r')
3435 for line in lf:
3436 hf.write(line)
3437 lf.close()
3438 hf.write('</div>\n')
3439
3440 if(not sysvals.embedded):
3441 # write the footer and close
3442 addScriptCode(hf, testruns)
3443 hf.write('</body>\n</html>\n')
3444 else:
3445 # embedded out will be loaded in a page, skip the js
3446 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
3447 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
3448 # add js code in a div entry for later evaluation
3449 detail = 'var bounds = [%f,%f];\n' % (t0, tMax)
3450 detail += 'var devtable = [\n'
3451 for data in testruns:
3452 topo = data.deviceTopology()
3453 detail += '\t"%s",\n' % (topo)
3454 detail += '];\n'
3455 hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n')
2459 hf.close() 3456 hf.close()
2460 return True 3457 return True
2461 3458
@@ -2466,8 +3463,8 @@ def createHTML(testruns):
2466# hf: the open html file pointer 3463# hf: the open html file pointer
2467# testruns: array of Data objects from parseKernelLog or parseTraceLog 3464# testruns: array of Data objects from parseKernelLog or parseTraceLog
2468def addScriptCode(hf, testruns): 3465def addScriptCode(hf, testruns):
2469 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000 3466 t0 = testruns[0].start * 1000
2470 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000 3467 tMax = testruns[-1].end * 1000
2471 # create an array in javascript memory with the device details 3468 # create an array in javascript memory with the device details
2472 detail = ' var devtable = [];\n' 3469 detail = ' var devtable = [];\n'
2473 for data in testruns: 3470 for data in testruns:
@@ -2477,8 +3474,43 @@ def addScriptCode(hf, testruns):
2477 # add the code which will manipulate the data in the browser 3474 # add the code which will manipulate the data in the browser
2478 script_code = \ 3475 script_code = \
2479 '<script type="text/javascript">\n'+detail+\ 3476 '<script type="text/javascript">\n'+detail+\
3477 ' var resolution = -1;\n'\
3478 ' function redrawTimescale(t0, tMax, tS) {\n'\
3479 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cR><-R</cR></div>\';\n'\
3480 ' var tTotal = tMax - t0;\n'\
3481 ' var list = document.getElementsByClassName("tblock");\n'\
3482 ' for (var i = 0; i < list.length; i++) {\n'\
3483 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
3484 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
3485 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
3486 ' var mMax = m0 + mTotal;\n'\
3487 ' var html = "";\n'\
3488 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
3489 ' if(divTotal > 1000) continue;\n'\
3490 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
3491 ' var pos = 0.0, val = 0.0;\n'\
3492 ' for (var j = 0; j < divTotal; j++) {\n'\
3493 ' var htmlline = "";\n'\
3494 ' if(list[i].id[5] == "r") {\n'\
3495 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
3496 ' val = (j)*tS;\n'\
3497 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3498 ' if(j == 0)\n'\
3499 ' htmlline = rline;\n'\
3500 ' } else {\n'\
3501 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
3502 ' val = (j-divTotal+1)*tS;\n'\
3503 ' if(j == divTotal - 1)\n'\
3504 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S-></cS></div>\';\n'\
3505 ' else\n'\
3506 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3507 ' }\n'\
3508 ' html += htmlline;\n'\
3509 ' }\n'\
3510 ' timescale.innerHTML = html;\n'\
3511 ' }\n'\
3512 ' }\n'\
2480 ' function zoomTimeline() {\n'\ 3513 ' function zoomTimeline() {\n'\
2481 ' var timescale = document.getElementById("timescale");\n'\
2482 ' var dmesg = document.getElementById("dmesg");\n'\ 3514 ' var dmesg = document.getElementById("dmesg");\n'\
2483 ' var zoombox = document.getElementById("dmesgzoombox");\n'\ 3515 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
2484 ' var val = parseFloat(dmesg.style.width);\n'\ 3516 ' var val = parseFloat(dmesg.style.width);\n'\
@@ -2486,7 +3518,7 @@ def addScriptCode(hf, testruns):
2486 ' var sh = window.outerWidth / 2;\n'\ 3518 ' var sh = window.outerWidth / 2;\n'\
2487 ' if(this.id == "zoomin") {\n'\ 3519 ' if(this.id == "zoomin") {\n'\
2488 ' newval = val * 1.2;\n'\ 3520 ' newval = val * 1.2;\n'\
2489 ' if(newval > 40000) newval = 40000;\n'\ 3521 ' if(newval > 910034) newval = 910034;\n'\
2490 ' dmesg.style.width = newval+"%";\n'\ 3522 ' dmesg.style.width = newval+"%";\n'\
2491 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\ 3523 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
2492 ' } else if (this.id == "zoomout") {\n'\ 3524 ' } else if (this.id == "zoomout") {\n'\
@@ -2498,19 +3530,17 @@ def addScriptCode(hf, testruns):
2498 ' zoombox.scrollLeft = 0;\n'\ 3530 ' zoombox.scrollLeft = 0;\n'\
2499 ' dmesg.style.width = "100%";\n'\ 3531 ' dmesg.style.width = "100%";\n'\
2500 ' }\n'\ 3532 ' }\n'\
2501 ' var html = "";\n'\ 3533 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
2502 ' var t0 = bounds[0];\n'\ 3534 ' var t0 = bounds[0];\n'\
2503 ' var tMax = bounds[1];\n'\ 3535 ' var tMax = bounds[1];\n'\
2504 ' var tTotal = tMax - t0;\n'\ 3536 ' var tTotal = tMax - t0;\n'\
2505 ' var wTotal = tTotal * 100.0 / newval;\n'\ 3537 ' var wTotal = tTotal * 100.0 / newval;\n'\
2506 ' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\ 3538 ' var idx = 7*window.innerWidth/1100;\n'\
2507 ' if(tS < 1) tS = 1;\n'\ 3539 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
2508 ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\ 3540 ' if(i >= tS.length) i = tS.length - 1;\n'\
2509 ' var pos = (tMax - s) * 100.0 / tTotal;\n'\ 3541 ' if(tS[i] == resolution) return;\n'\
2510 ' var name = (s == 0)?"S/R":(s+"ms");\n'\ 3542 ' resolution = tS[i];\n'\
2511 ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\ 3543 ' redrawTimescale(t0, tMax, tS[i]);\n'\
2512 ' }\n'\
2513 ' timescale.innerHTML = html;\n'\
2514 ' }\n'\ 3544 ' }\n'\
2515 ' function deviceHover() {\n'\ 3545 ' function deviceHover() {\n'\
2516 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\ 3546 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
@@ -2523,12 +3553,13 @@ def addScriptCode(hf, testruns):
2523 ' cpu = parseInt(name.slice(8));\n'\ 3553 ' cpu = parseInt(name.slice(8));\n'\
2524 ' for (var i = 0; i < dev.length; i++) {\n'\ 3554 ' for (var i = 0; i < dev.length; i++) {\n'\
2525 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\ 3555 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
3556 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
2526 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 3557 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2527 ' (name == dname))\n'\ 3558 ' (name == dname))\n'\
2528 ' {\n'\ 3559 ' {\n'\
2529 ' dev[i].className = "thread hover";\n'\ 3560 ' dev[i].className = "hover "+cname;\n'\
2530 ' } else {\n'\ 3561 ' } else {\n'\
2531 ' dev[i].className = "thread";\n'\ 3562 ' dev[i].className = cname;\n'\
2532 ' }\n'\ 3563 ' }\n'\
2533 ' }\n'\ 3564 ' }\n'\
2534 ' }\n'\ 3565 ' }\n'\
@@ -2536,7 +3567,7 @@ def addScriptCode(hf, testruns):
2536 ' var dmesg = document.getElementById("dmesg");\n'\ 3567 ' var dmesg = document.getElementById("dmesg");\n'\
2537 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 3568 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2538 ' for (var i = 0; i < dev.length; i++) {\n'\ 3569 ' for (var i = 0; i < dev.length; i++) {\n'\
2539 ' dev[i].className = "thread";\n'\ 3570 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
2540 ' }\n'\ 3571 ' }\n'\
2541 ' }\n'\ 3572 ' }\n'\
2542 ' function deviceTitle(title, total, cpu) {\n'\ 3573 ' function deviceTitle(title, total, cpu) {\n'\
@@ -2547,7 +3578,7 @@ def addScriptCode(hf, testruns):
2547 ' total[2] = (total[2]+total[4])/2;\n'\ 3578 ' total[2] = (total[2]+total[4])/2;\n'\
2548 ' }\n'\ 3579 ' }\n'\
2549 ' var devtitle = document.getElementById("devicedetailtitle");\n'\ 3580 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
2550 ' var name = title.slice(0, title.indexOf(" "));\n'\ 3581 ' var name = title.slice(0, title.indexOf(" ("));\n'\
2551 ' if(cpu >= 0) name = "CPU"+cpu;\n'\ 3582 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
2552 ' var driver = "";\n'\ 3583 ' var driver = "";\n'\
2553 ' var tS = "<t2>(</t2>";\n'\ 3584 ' var tS = "<t2>(</t2>";\n'\
@@ -2579,6 +3610,8 @@ def addScriptCode(hf, testruns):
2579 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 3610 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2580 ' var idlist = [];\n'\ 3611 ' var idlist = [];\n'\
2581 ' var pdata = [[]];\n'\ 3612 ' var pdata = [[]];\n'\
3613 ' if(document.getElementById("devicedetail1"))\n'\
3614 ' pdata = [[], []];\n'\
2582 ' var pd = pdata[0];\n'\ 3615 ' var pd = pdata[0];\n'\
2583 ' var total = [0.0, 0.0, 0.0];\n'\ 3616 ' var total = [0.0, 0.0, 0.0];\n'\
2584 ' for (var i = 0; i < dev.length; i++) {\n'\ 3617 ' for (var i = 0; i < dev.length; i++) {\n'\
@@ -2634,6 +3667,7 @@ def addScriptCode(hf, testruns):
2634 ' var cglist = document.getElementById("callgraphs");\n'\ 3667 ' var cglist = document.getElementById("callgraphs");\n'\
2635 ' if(!cglist) return;\n'\ 3668 ' if(!cglist) return;\n'\
2636 ' var cg = cglist.getElementsByClassName("atop");\n'\ 3669 ' var cg = cglist.getElementsByClassName("atop");\n'\
3670 ' if(cg.length < 10) return;\n'\
2637 ' for (var i = 0; i < cg.length; i++) {\n'\ 3671 ' for (var i = 0; i < cg.length; i++) {\n'\
2638 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\ 3672 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
2639 ' cg[i].style.display = "block";\n'\ 3673 ' cg[i].style.display = "block";\n'\
@@ -2658,15 +3692,32 @@ def addScriptCode(hf, testruns):
2658 ' dt = devtable[1];\n'\ 3692 ' dt = devtable[1];\n'\
2659 ' win.document.write(html+dt);\n'\ 3693 ' win.document.write(html+dt);\n'\
2660 ' }\n'\ 3694 ' }\n'\
3695 ' function logWindow(e) {\n'\
3696 ' var name = e.target.id.slice(4);\n'\
3697 ' var win = window.open();\n'\
3698 ' var log = document.getElementById(name+"log");\n'\
3699 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
3700 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
3701 ' win.document.close();\n'\
3702 ' }\n'\
3703 ' function onClickPhase(e) {\n'\
3704 ' }\n'\
3705 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
2661 ' window.addEventListener("load", function () {\n'\ 3706 ' window.addEventListener("load", function () {\n'\
2662 ' var dmesg = document.getElementById("dmesg");\n'\ 3707 ' var dmesg = document.getElementById("dmesg");\n'\
2663 ' dmesg.style.width = "100%"\n'\ 3708 ' dmesg.style.width = "100%"\n'\
2664 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ 3709 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
2665 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ 3710 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
2666 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ 3711 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
2667 ' var devlist = document.getElementsByClassName("devlist");\n'\ 3712 ' var list = document.getElementsByClassName("square");\n'\
2668 ' for (var i = 0; i < devlist.length; i++)\n'\ 3713 ' for (var i = 0; i < list.length; i++)\n'\
2669 ' devlist[i].onclick = devListWindow;\n'\ 3714 ' list[i].onclick = onClickPhase;\n'\
3715 ' var list = document.getElementsByClassName("logbtn");\n'\
3716 ' for (var i = 0; i < list.length; i++)\n'\
3717 ' list[i].onclick = logWindow;\n'\
3718 ' list = document.getElementsByClassName("devlist");\n'\
3719 ' for (var i = 0; i < list.length; i++)\n'\
3720 ' list[i].onclick = devListWindow;\n'\
2670 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 3721 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2671 ' for (var i = 0; i < dev.length; i++) {\n'\ 3722 ' for (var i = 0; i < dev.length; i++) {\n'\
2672 ' dev[i].onclick = deviceDetail;\n'\ 3723 ' dev[i].onclick = deviceDetail;\n'\
@@ -2685,141 +3736,87 @@ def addScriptCode(hf, testruns):
2685def executeSuspend(): 3736def executeSuspend():
2686 global sysvals 3737 global sysvals
2687 3738
2688 detectUSB(False)
2689 t0 = time.time()*1000 3739 t0 = time.time()*1000
2690 tp = sysvals.tpath 3740 tp = sysvals.tpath
3741 fwdata = []
3742 # mark the start point in the kernel ring buffer just as we start
3743 sysvals.initdmesg()
3744 # start ftrace
3745 if(sysvals.usecallgraph or sysvals.usetraceevents):
3746 print('START TRACING')
3747 sysvals.fsetVal('1', 'tracing_on')
2691 # execute however many s/r runs requested 3748 # execute however many s/r runs requested
2692 for count in range(1,sysvals.execcount+1): 3749 for count in range(1,sysvals.execcount+1):
2693 # clear the kernel ring buffer just as we start
2694 os.system('dmesg -C')
2695 # enable callgraph ftrace only for the second run
2696 if(sysvals.usecallgraph and count == 2):
2697 # set trace type
2698 os.system('echo function_graph > '+tp+'current_tracer')
2699 os.system('echo "" > '+tp+'set_ftrace_filter')
2700 # set trace format options
2701 os.system('echo funcgraph-abstime > '+tp+'trace_options')
2702 os.system('echo funcgraph-proc > '+tp+'trace_options')
2703 # focus only on device suspend and resume
2704 os.system('cat '+tp+'available_filter_functions | '+\
2705 'grep dpm_run_callback > '+tp+'set_graph_function')
2706 # if this is test2 and there's a delay, start here 3750 # if this is test2 and there's a delay, start here
2707 if(count > 1 and sysvals.x2delay > 0): 3751 if(count > 1 and sysvals.x2delay > 0):
2708 tN = time.time()*1000 3752 tN = time.time()*1000
2709 while (tN - t0) < sysvals.x2delay: 3753 while (tN - t0) < sysvals.x2delay:
2710 tN = time.time()*1000 3754 tN = time.time()*1000
2711 time.sleep(0.001) 3755 time.sleep(0.001)
2712 # start ftrace
2713 if(sysvals.usecallgraph or sysvals.usetraceevents):
2714 print('START TRACING')
2715 os.system('echo 1 > '+tp+'tracing_on')
2716 # initiate suspend 3756 # initiate suspend
2717 if(sysvals.usecallgraph or sysvals.usetraceevents): 3757 if(sysvals.usecallgraph or sysvals.usetraceevents):
2718 os.system('echo SUSPEND START > '+tp+'trace_marker') 3758 sysvals.fsetVal('SUSPEND START', 'trace_marker')
2719 if(sysvals.rtcwake): 3759 if sysvals.suspendmode == 'command':
2720 print('SUSPEND START') 3760 print('COMMAND START')
2721 print('will autoresume in %d seconds' % sysvals.rtcwaketime) 3761 if(sysvals.rtcwake):
2722 sysvals.rtcWakeAlarm() 3762 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
3763 sysvals.rtcWakeAlarmOn()
3764 os.system(sysvals.testcommand)
2723 else: 3765 else:
2724 print('SUSPEND START (press a key to resume)') 3766 if(sysvals.rtcwake):
2725 pf = open(sysvals.powerfile, 'w') 3767 print('SUSPEND START')
2726 pf.write(sysvals.suspendmode) 3768 print('will autoresume in %d seconds' % sysvals.rtcwaketime)
2727 # execution will pause here 3769 sysvals.rtcWakeAlarmOn()
2728 pf.close() 3770 else:
3771 print('SUSPEND START (press a key to resume)')
3772 pf = open(sysvals.powerfile, 'w')
3773 pf.write(sysvals.suspendmode)
3774 # execution will pause here
3775 try:
3776 pf.close()
3777 except:
3778 pass
2729 t0 = time.time()*1000 3779 t0 = time.time()*1000
3780 if(sysvals.rtcwake):
3781 sysvals.rtcWakeAlarmOff()
2730 # return from suspend 3782 # return from suspend
2731 print('RESUME COMPLETE') 3783 print('RESUME COMPLETE')
2732 if(sysvals.usecallgraph or sysvals.usetraceevents): 3784 if(sysvals.usecallgraph or sysvals.usetraceevents):
2733 os.system('echo RESUME COMPLETE > '+tp+'trace_marker') 3785 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
2734 # see if there's firmware timing data to be had 3786 if(sysvals.suspendmode == 'mem'):
2735 t = sysvals.postresumetime 3787 fwdata.append(getFPDT(False))
2736 if(t > 0): 3788 # look for post resume events after the last test run
2737 print('Waiting %d seconds for POST-RESUME trace events...' % t) 3789 t = sysvals.postresumetime
2738 time.sleep(t) 3790 if(t > 0):
2739 # stop ftrace 3791 print('Waiting %d seconds for POST-RESUME trace events...' % t)
2740 if(sysvals.usecallgraph or sysvals.usetraceevents): 3792 time.sleep(t)
2741 os.system('echo 0 > '+tp+'tracing_on') 3793 # stop ftrace
2742 print('CAPTURING TRACE') 3794 if(sysvals.usecallgraph or sysvals.usetraceevents):
2743 writeDatafileHeader(sysvals.ftracefile) 3795 sysvals.fsetVal('0', 'tracing_on')
2744 os.system('cat '+tp+'trace >> '+sysvals.ftracefile) 3796 print('CAPTURING TRACE')
2745 os.system('echo "" > '+tp+'trace') 3797 writeDatafileHeader(sysvals.ftracefile, fwdata)
2746 # grab a copy of the dmesg output 3798 os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
2747 print('CAPTURING DMESG') 3799 sysvals.fsetVal('', 'trace')
2748 writeDatafileHeader(sysvals.dmesgfile) 3800 devProps()
2749 os.system('dmesg -c >> '+sysvals.dmesgfile) 3801 # grab a copy of the dmesg output
2750 3802 print('CAPTURING DMESG')
2751def writeDatafileHeader(filename): 3803 writeDatafileHeader(sysvals.dmesgfile, fwdata)
3804 sysvals.getdmesg()
3805
3806def writeDatafileHeader(filename, fwdata):
2752 global sysvals 3807 global sysvals
2753 3808
2754 fw = getFPDT(False)
2755 prt = sysvals.postresumetime 3809 prt = sysvals.postresumetime
2756 fp = open(filename, 'a') 3810 fp = open(filename, 'a')
2757 fp.write(sysvals.teststamp+'\n') 3811 fp.write(sysvals.teststamp+'\n')
2758 if(fw): 3812 if(sysvals.suspendmode == 'mem'):
2759 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) 3813 for fw in fwdata:
3814 if(fw):
3815 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
2760 if(prt > 0): 3816 if(prt > 0):
2761 fp.write('# post resume time %u\n' % prt) 3817 fp.write('# post resume time %u\n' % prt)
2762 fp.close() 3818 fp.close()
2763 3819
2764# Function: executeAndroidSuspend
2765# Description:
2766# Execute system suspend through the sysfs interface
2767# on a remote android device, then transfer the output
2768# dmesg and ftrace files to the local output directory.
2769def executeAndroidSuspend():
2770 global sysvals
2771
2772 # check to see if the display is currently off
2773 tp = sysvals.tpath
2774 out = os.popen(sysvals.adb+\
2775 ' shell dumpsys power | grep mScreenOn').read().strip()
2776 # if so we need to turn it on so we can issue a new suspend
2777 if(out.endswith('false')):
2778 print('Waking the device up for the test...')
2779 # send the KEYPAD_POWER keyevent to wake it up
2780 os.system(sysvals.adb+' shell input keyevent 26')
2781 # wait a few seconds so the user can see the device wake up
2782 time.sleep(3)
2783 # execute however many s/r runs requested
2784 for count in range(1,sysvals.execcount+1):
2785 # clear the kernel ring buffer just as we start
2786 os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1')
2787 # start ftrace
2788 if(sysvals.usetraceevents):
2789 print('START TRACING')
2790 os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'")
2791 # initiate suspend
2792 for count in range(1,sysvals.execcount+1):
2793 if(sysvals.usetraceevents):
2794 os.system(sysvals.adb+\
2795 " shell 'echo SUSPEND START > "+tp+"trace_marker'")
2796 print('SUSPEND START (press a key on the device to resume)')
2797 os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\
2798 " > "+sysvals.powerfile+"'")
2799 # execution will pause here, then adb will exit
2800 while(True):
2801 check = os.popen(sysvals.adb+\
2802 ' shell pwd 2>/dev/null').read().strip()
2803 if(len(check) > 0):
2804 break
2805 time.sleep(1)
2806 if(sysvals.usetraceevents):
2807 os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\
2808 "trace_marker'")
2809 # return from suspend
2810 print('RESUME COMPLETE')
2811 # stop ftrace
2812 if(sysvals.usetraceevents):
2813 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
2814 print('CAPTURING TRACE')
2815 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile)
2816 os.system(sysvals.adb+' shell cat '+tp+\
2817 'trace >> '+sysvals.ftracefile)
2818 # grab a copy of the dmesg output
2819 print('CAPTURING DMESG')
2820 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile)
2821 os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile)
2822
2823# Function: setUSBDevicesAuto 3820# Function: setUSBDevicesAuto
2824# Description: 3821# Description:
2825# Set the autosuspend control parameter of all USB devices to auto 3822# Set the autosuspend control parameter of all USB devices to auto
@@ -2829,7 +3826,7 @@ def executeAndroidSuspend():
2829def setUSBDevicesAuto(): 3826def setUSBDevicesAuto():
2830 global sysvals 3827 global sysvals
2831 3828
2832 rootCheck() 3829 rootCheck(True)
2833 for dirname, dirnames, filenames in os.walk('/sys/devices'): 3830 for dirname, dirnames, filenames in os.walk('/sys/devices'):
2834 if(re.match('.*/usb[0-9]*.*', dirname) and 3831 if(re.match('.*/usb[0-9]*.*', dirname) and
2835 'idVendor' in filenames and 'idProduct' in filenames): 3832 'idVendor' in filenames and 'idProduct' in filenames):
@@ -2874,9 +3871,7 @@ def ms2nice(val):
2874# Description: 3871# Description:
2875# Detect all the USB hosts and devices currently connected and add 3872# Detect all the USB hosts and devices currently connected and add
2876# a list of USB device names to sysvals for better timeline readability 3873# a list of USB device names to sysvals for better timeline readability
2877# Arguments: 3874def detectUSB():
2878# output: True to output the info to stdout, False otherwise
2879def detectUSB(output):
2880 global sysvals 3875 global sysvals
2881 3876
2882 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} 3877 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
@@ -2887,18 +3882,18 @@ def detectUSB(output):
2887 'runtime_suspended_time':'', 3882 'runtime_suspended_time':'',
2888 'active_duration':'', 3883 'active_duration':'',
2889 'connected_duration':''} 3884 'connected_duration':''}
2890 if(output): 3885
2891 print('LEGEND') 3886 print('LEGEND')
2892 print('---------------------------------------------------------------------------------------------') 3887 print('---------------------------------------------------------------------------------------------')
2893 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)') 3888 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
2894 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)') 3889 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
2895 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)') 3890 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
2896 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)') 3891 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
2897 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)') 3892 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
2898 print(' U = runtime usage count') 3893 print(' U = runtime usage count')
2899 print('---------------------------------------------------------------------------------------------') 3894 print('---------------------------------------------------------------------------------------------')
2900 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT') 3895 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
2901 print('---------------------------------------------------------------------------------------------') 3896 print('---------------------------------------------------------------------------------------------')
2902 3897
2903 for dirname, dirnames, filenames in os.walk('/sys/devices'): 3898 for dirname, dirnames, filenames in os.walk('/sys/devices'):
2904 if(re.match('.*/usb[0-9]*.*', dirname) and 3899 if(re.match('.*/usb[0-9]*.*', dirname) and
@@ -2907,35 +3902,149 @@ def detectUSB(output):
2907 field[i] = os.popen('cat %s/%s 2>/dev/null' % \ 3902 field[i] = os.popen('cat %s/%s 2>/dev/null' % \
2908 (dirname, i)).read().replace('\n', '') 3903 (dirname, i)).read().replace('\n', '')
2909 name = dirname.split('/')[-1] 3904 name = dirname.split('/')[-1]
2910 if(len(field['product']) > 0): 3905 for i in power:
2911 sysvals.altdevname[name] = \ 3906 power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
2912 '%s [%s]' % (field['product'], name) 3907 (dirname, i)).read().replace('\n', '')
3908 if(re.match('usb[0-9]*', name)):
3909 first = '%-8s' % name
2913 else: 3910 else:
2914 sysvals.altdevname[name] = \ 3911 first = '%8s' % name
2915 '%s:%s [%s]' % (field['idVendor'], \ 3912 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
2916 field['idProduct'], name) 3913 (first, field['idVendor'], field['idProduct'], \
2917 if(output): 3914 field['product'][0:20], field['speed'], \
2918 for i in power: 3915 yesno(power['async']), \
2919 power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \ 3916 yesno(power['control']), \
2920 (dirname, i)).read().replace('\n', '') 3917 yesno(power['persist']), \
2921 if(re.match('usb[0-9]*', name)): 3918 yesno(power['runtime_enabled']), \
2922 first = '%-8s' % name 3919 yesno(power['runtime_status']), \
2923 else: 3920 power['runtime_usage'], \
2924 first = '%8s' % name 3921 power['autosuspend'], \
2925 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \ 3922 ms2nice(power['runtime_active_time']), \
2926 (first, field['idVendor'], field['idProduct'], \ 3923 ms2nice(power['runtime_suspended_time']), \
2927 field['product'][0:20], field['speed'], \ 3924 ms2nice(power['active_duration']), \
2928 yesno(power['async']), \ 3925 ms2nice(power['connected_duration'])))
2929 yesno(power['control']), \ 3926
2930 yesno(power['persist']), \ 3927# Function: devProps
2931 yesno(power['runtime_enabled']), \ 3928# Description:
2932 yesno(power['runtime_status']), \ 3929# Retrieve a list of properties for all devices in the trace log
2933 power['runtime_usage'], \ 3930def devProps(data=0):
2934 power['autosuspend'], \ 3931 global sysvals
2935 ms2nice(power['runtime_active_time']), \ 3932 props = dict()
2936 ms2nice(power['runtime_suspended_time']), \ 3933
2937 ms2nice(power['active_duration']), \ 3934 if data:
2938 ms2nice(power['connected_duration']))) 3935 idx = data.index(': ') + 2
3936 if idx >= len(data):
3937 return
3938 devlist = data[idx:].split(';')
3939 for dev in devlist:
3940 f = dev.split(',')
3941 if len(f) < 3:
3942 continue
3943 dev = f[0]
3944 props[dev] = DevProps()
3945 props[dev].altname = f[1]
3946 if int(f[2]):
3947 props[dev].async = True
3948 else:
3949 props[dev].async = False
3950 sysvals.devprops = props
3951 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
3952 sysvals.testcommand = props['testcommandstring'].altname
3953 return
3954
3955 if(os.path.exists(sysvals.ftracefile) == False):
3956 doError('%s does not exist' % sysvals.ftracefile, False)
3957
3958 # first get the list of devices we need properties for
3959 msghead = 'Additional data added by AnalyzeSuspend'
3960 alreadystamped = False
3961 tp = TestProps()
3962 tf = open(sysvals.ftracefile, 'r')
3963 for line in tf:
3964 if msghead in line:
3965 alreadystamped = True
3966 continue
3967 # determine the trace data type (required for further parsing)
3968 m = re.match(sysvals.tracertypefmt, line)
3969 if(m):
3970 tp.setTracerType(m.group('t'))
3971 continue
3972 # parse only valid lines, if this is not one move on
3973 m = re.match(tp.ftrace_line_fmt, line)
3974 if(not m or 'device_pm_callback_start' not in line):
3975 continue
3976 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
3977 if(not m):
3978 continue
3979 drv, dev, par = m.group('drv'), m.group('d'), m.group('p')
3980 if dev not in props:
3981 props[dev] = DevProps()
3982 tf.close()
3983
3984 if not alreadystamped and sysvals.suspendmode == 'command':
3985 out = '#\n# '+msghead+'\n# Device Properties: '
3986 out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
3987 with open(sysvals.ftracefile, 'a') as fp:
3988 fp.write(out+'\n')
3989 sysvals.devprops = props
3990 return
3991
3992 # now get the syspath for each of our target devices
3993 for dirname, dirnames, filenames in os.walk('/sys/devices'):
3994 if(re.match('.*/power', dirname) and 'async' in filenames):
3995 dev = dirname.split('/')[-2]
3996 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
3997 props[dev].syspath = dirname[:-6]
3998
3999 # now fill in the properties for our target devices
4000 for dev in props:
4001 dirname = props[dev].syspath
4002 if not dirname or not os.path.exists(dirname):
4003 continue
4004 with open(dirname+'/power/async') as fp:
4005 text = fp.read()
4006 props[dev].async = False
4007 if 'enabled' in text:
4008 props[dev].async = True
4009 fields = os.listdir(dirname)
4010 if 'product' in fields:
4011 with open(dirname+'/product') as fp:
4012 props[dev].altname = fp.read()
4013 elif 'name' in fields:
4014 with open(dirname+'/name') as fp:
4015 props[dev].altname = fp.read()
4016 elif 'model' in fields:
4017 with open(dirname+'/model') as fp:
4018 props[dev].altname = fp.read()
4019 elif 'description' in fields:
4020 with open(dirname+'/description') as fp:
4021 props[dev].altname = fp.read()
4022 elif 'id' in fields:
4023 with open(dirname+'/id') as fp:
4024 props[dev].altname = fp.read()
4025 elif 'idVendor' in fields and 'idProduct' in fields:
4026 idv, idp = '', ''
4027 with open(dirname+'/idVendor') as fp:
4028 idv = fp.read().strip()
4029 with open(dirname+'/idProduct') as fp:
4030 idp = fp.read().strip()
4031 props[dev].altname = '%s:%s' % (idv, idp)
4032
4033 if props[dev].altname:
4034 out = props[dev].altname.strip().replace('\n', ' ')
4035 out = out.replace(',', ' ')
4036 out = out.replace(';', ' ')
4037 props[dev].altname = out
4038
4039 # and now write the data to the ftrace file
4040 if not alreadystamped:
4041 out = '#\n# '+msghead+'\n# Device Properties: '
4042 for dev in sorted(props):
4043 out += props[dev].out(dev)
4044 with open(sysvals.ftracefile, 'a') as fp:
4045 fp.write(out+'\n')
4046
4047 sysvals.devprops = props
2939 4048
2940# Function: getModes 4049# Function: getModes
2941# Description: 4050# Description:
@@ -2945,15 +4054,10 @@ def detectUSB(output):
2945def getModes(): 4054def getModes():
2946 global sysvals 4055 global sysvals
2947 modes = '' 4056 modes = ''
2948 if(not sysvals.android): 4057 if(os.path.exists(sysvals.powerfile)):
2949 if(os.path.exists(sysvals.powerfile)): 4058 fp = open(sysvals.powerfile, 'r')
2950 fp = open(sysvals.powerfile, 'r') 4059 modes = string.split(fp.read())
2951 modes = string.split(fp.read()) 4060 fp.close()
2952 fp.close()
2953 else:
2954 line = os.popen(sysvals.adb+' shell cat '+\
2955 sysvals.powerfile).read().strip()
2956 modes = string.split(line)
2957 return modes 4061 return modes
2958 4062
2959# Function: getFPDT 4063# Function: getFPDT
@@ -2971,22 +4075,22 @@ def getFPDT(output):
2971 prectype[0] = 'Basic S3 Resume Performance Record' 4075 prectype[0] = 'Basic S3 Resume Performance Record'
2972 prectype[1] = 'Basic S3 Suspend Performance Record' 4076 prectype[1] = 'Basic S3 Suspend Performance Record'
2973 4077
2974 rootCheck() 4078 rootCheck(True)
2975 if(not os.path.exists(sysvals.fpdtpath)): 4079 if(not os.path.exists(sysvals.fpdtpath)):
2976 if(output): 4080 if(output):
2977 doError('file doesnt exist: %s' % sysvals.fpdtpath, False) 4081 doError('file does not exist: %s' % sysvals.fpdtpath, False)
2978 return False 4082 return False
2979 if(not os.access(sysvals.fpdtpath, os.R_OK)): 4083 if(not os.access(sysvals.fpdtpath, os.R_OK)):
2980 if(output): 4084 if(output):
2981 doError('file isnt readable: %s' % sysvals.fpdtpath, False) 4085 doError('file is not readable: %s' % sysvals.fpdtpath, False)
2982 return False 4086 return False
2983 if(not os.path.exists(sysvals.mempath)): 4087 if(not os.path.exists(sysvals.mempath)):
2984 if(output): 4088 if(output):
2985 doError('file doesnt exist: %s' % sysvals.mempath, False) 4089 doError('file does not exist: %s' % sysvals.mempath, False)
2986 return False 4090 return False
2987 if(not os.access(sysvals.mempath, os.R_OK)): 4091 if(not os.access(sysvals.mempath, os.R_OK)):
2988 if(output): 4092 if(output):
2989 doError('file isnt readable: %s' % sysvals.mempath, False) 4093 doError('file is not readable: %s' % sysvals.mempath, False)
2990 return False 4094 return False
2991 4095
2992 fp = open(sysvals.fpdtpath, 'rb') 4096 fp = open(sysvals.fpdtpath, 'rb')
@@ -3027,15 +4131,19 @@ def getFPDT(output):
3027 while(i < len(records)): 4131 while(i < len(records)):
3028 header = struct.unpack('HBB', records[i:i+4]) 4132 header = struct.unpack('HBB', records[i:i+4])
3029 if(header[0] not in rectype): 4133 if(header[0] not in rectype):
4134 i += header[1]
3030 continue 4135 continue
3031 if(header[1] != 16): 4136 if(header[1] != 16):
4137 i += header[1]
3032 continue 4138 continue
3033 addr = struct.unpack('Q', records[i+8:i+16])[0] 4139 addr = struct.unpack('Q', records[i+8:i+16])[0]
3034 try: 4140 try:
3035 fp.seek(addr) 4141 fp.seek(addr)
3036 first = fp.read(8) 4142 first = fp.read(8)
3037 except: 4143 except:
3038 doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False) 4144 if(output):
4145 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
4146 return [0, 0]
3039 rechead = struct.unpack('4sI', first) 4147 rechead = struct.unpack('4sI', first)
3040 recdata = fp.read(rechead[1]-8) 4148 recdata = fp.read(rechead[1]-8)
3041 if(rechead[0] == 'FBPT'): 4149 if(rechead[0] == 'FBPT'):
@@ -3090,89 +4198,60 @@ def getFPDT(output):
3090# print the results to the terminal 4198# print the results to the terminal
3091# Output: 4199# Output:
3092# True if the test will work, False if not 4200# True if the test will work, False if not
3093def statusCheck(): 4201def statusCheck(probecheck=False):
3094 global sysvals 4202 global sysvals
3095 status = True 4203 status = True
3096 4204
3097 if(sysvals.android): 4205 print('Checking this system (%s)...' % platform.node())
3098 print('Checking the android system ...')
3099 else:
3100 print('Checking this system (%s)...' % platform.node())
3101
3102 # check if adb is connected to a device
3103 if(sysvals.android):
3104 res = 'NO'
3105 out = os.popen(sysvals.adb+' get-state').read().strip()
3106 if(out == 'device'):
3107 res = 'YES'
3108 print(' is android device connected: %s' % res)
3109 if(res != 'YES'):
3110 print(' Please connect the device before using this tool')
3111 return False
3112 4206
3113 # check we have root access 4207 # check we have root access
3114 res = 'NO (No features of this tool will work!)' 4208 res = sysvals.colorText('NO (No features of this tool will work!)')
3115 if(sysvals.android): 4209 if(rootCheck(False)):
3116 out = os.popen(sysvals.adb+' shell id').read().strip() 4210 res = 'YES'
3117 if('root' in out):
3118 res = 'YES'
3119 else:
3120 if(os.environ['USER'] == 'root'):
3121 res = 'YES'
3122 print(' have root access: %s' % res) 4211 print(' have root access: %s' % res)
3123 if(res != 'YES'): 4212 if(res != 'YES'):
3124 if(sysvals.android): 4213 print(' Try running this script with sudo')
3125 print(' Try running "adb root" to restart the daemon as root')
3126 else:
3127 print(' Try running this script with sudo')
3128 return False 4214 return False
3129 4215
3130 # check sysfs is mounted 4216 # check sysfs is mounted
3131 res = 'NO (No features of this tool will work!)' 4217 res = sysvals.colorText('NO (No features of this tool will work!)')
3132 if(sysvals.android): 4218 if(os.path.exists(sysvals.powerfile)):
3133 out = os.popen(sysvals.adb+' shell ls '+\ 4219 res = 'YES'
3134 sysvals.powerfile).read().strip()
3135 if(out == sysvals.powerfile):
3136 res = 'YES'
3137 else:
3138 if(os.path.exists(sysvals.powerfile)):
3139 res = 'YES'
3140 print(' is sysfs mounted: %s' % res) 4220 print(' is sysfs mounted: %s' % res)
3141 if(res != 'YES'): 4221 if(res != 'YES'):
3142 return False 4222 return False
3143 4223
3144 # check target mode is a valid mode 4224 # check target mode is a valid mode
3145 res = 'NO' 4225 if sysvals.suspendmode != 'command':
3146 modes = getModes() 4226 res = sysvals.colorText('NO')
3147 if(sysvals.suspendmode in modes): 4227 modes = getModes()
3148 res = 'YES' 4228 if(sysvals.suspendmode in modes):
3149 else: 4229 res = 'YES'
3150 status = False 4230 else:
3151 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 4231 status = False
3152 if(res == 'NO'): 4232 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
3153 print(' valid power modes are: %s' % modes) 4233 if(res == 'NO'):
3154 print(' please choose one with -m') 4234 print(' valid power modes are: %s' % modes)
3155 4235 print(' please choose one with -m')
3156 # check if the tool can unlock the device
3157 if(sysvals.android):
3158 res = 'YES'
3159 out1 = os.popen(sysvals.adb+\
3160 ' shell dumpsys power | grep mScreenOn').read().strip()
3161 out2 = os.popen(sysvals.adb+\
3162 ' shell input').read().strip()
3163 if(not out1.startswith('mScreenOn') or not out2.startswith('usage')):
3164 res = 'NO (wake the android device up before running the test)'
3165 print(' can I unlock the screen: %s' % res)
3166 4236
3167 # check if ftrace is available 4237 # check if ftrace is available
3168 res = 'NO' 4238 res = sysvals.colorText('NO')
3169 ftgood = verifyFtrace() 4239 ftgood = sysvals.verifyFtrace()
3170 if(ftgood): 4240 if(ftgood):
3171 res = 'YES' 4241 res = 'YES'
3172 elif(sysvals.usecallgraph): 4242 elif(sysvals.usecallgraph):
3173 status = False 4243 status = False
3174 print(' is ftrace supported: %s' % res) 4244 print(' is ftrace supported: %s' % res)
3175 4245
4246 # check if kprobes are available
4247 res = sysvals.colorText('NO')
4248 sysvals.usekprobes = sysvals.verifyKprobes()
4249 if(sysvals.usekprobes):
4250 res = 'YES'
4251 else:
4252 sysvals.usedevsrc = False
4253 print(' are kprobes supported: %s' % res)
4254
3176 # what data source are we using 4255 # what data source are we using
3177 res = 'DMESG' 4256 res = 'DMESG'
3178 if(ftgood): 4257 if(ftgood):
@@ -3180,14 +4259,8 @@ def statusCheck():
3180 sysvals.usetraceevents = False 4259 sysvals.usetraceevents = False
3181 for e in sysvals.traceevents: 4260 for e in sysvals.traceevents:
3182 check = False 4261 check = False
3183 if(sysvals.android): 4262 if(os.path.exists(sysvals.epath+e)):
3184 out = os.popen(sysvals.adb+' shell ls -d '+\ 4263 check = True
3185 sysvals.epath+e).read().strip()
3186 if(out == sysvals.epath+e):
3187 check = True
3188 else:
3189 if(os.path.exists(sysvals.epath+e)):
3190 check = True
3191 if(not check): 4264 if(not check):
3192 sysvals.usetraceeventsonly = False 4265 sysvals.usetraceeventsonly = False
3193 if(e == 'suspend_resume' and check): 4266 if(e == 'suspend_resume' and check):
@@ -3199,13 +4272,48 @@ def statusCheck():
3199 print(' timeline data source: %s' % res) 4272 print(' timeline data source: %s' % res)
3200 4273
3201 # check if rtcwake 4274 # check if rtcwake
3202 res = 'NO' 4275 res = sysvals.colorText('NO')
3203 if(sysvals.rtcpath != ''): 4276 if(sysvals.rtcpath != ''):
3204 res = 'YES' 4277 res = 'YES'
3205 elif(sysvals.rtcwake): 4278 elif(sysvals.rtcwake):
3206 status = False 4279 status = False
3207 print(' is rtcwake supported: %s' % res) 4280 print(' is rtcwake supported: %s' % res)
3208 4281
4282 if not probecheck:
4283 return status
4284
4285 if (sysvals.usecallgraph and len(sysvals.debugfuncs) > 0) or len(sysvals.kprobes) > 0:
4286 sysvals.initFtrace(True)
4287
4288 # verify callgraph debugfuncs
4289 if sysvals.usecallgraph and len(sysvals.debugfuncs) > 0:
4290 print(' verifying these ftrace callgraph functions work:')
4291 sysvals.setFtraceFilterFunctions(sysvals.debugfuncs)
4292 fp = open(sysvals.tpath+'set_graph_function', 'r')
4293 flist = fp.read().split('\n')
4294 fp.close()
4295 for func in sysvals.debugfuncs:
4296 res = sysvals.colorText('NO')
4297 if func in flist:
4298 res = 'YES'
4299 else:
4300 for i in flist:
4301 if ' [' in i and func == i.split(' ')[0]:
4302 res = 'YES'
4303 break
4304 print(' %s: %s' % (func, res))
4305
4306 # verify kprobes
4307 if len(sysvals.kprobes) > 0:
4308 print(' verifying these kprobes work:')
4309 for name in sorted(sysvals.kprobes):
4310 if name in sysvals.tracefuncs:
4311 continue
4312 res = sysvals.colorText('NO')
4313 if sysvals.testKprobe(sysvals.kprobes[name]):
4314 res = 'YES'
4315 print(' %s: %s' % (name, res))
4316
3209 return status 4317 return status
3210 4318
3211# Function: doError 4319# Function: doError
@@ -3226,7 +4334,7 @@ def doError(msg, help):
3226# Arguments: 4334# Arguments:
3227# msg: the warning message to print 4335# msg: the warning message to print
3228# file: If not empty, a filename to request be sent to the owner for debug 4336# file: If not empty, a filename to request be sent to the owner for debug
3229def doWarning(msg, file): 4337def doWarning(msg, file=''):
3230 print('/* %s */') % msg 4338 print('/* %s */') % msg
3231 if(file): 4339 if(file):
3232 print('/* For a fix, please send this'+\ 4340 print('/* For a fix, please send this'+\
@@ -3235,18 +4343,25 @@ def doWarning(msg, file):
3235# Function: rootCheck 4343# Function: rootCheck
3236# Description: 4344# Description:
3237# quick check to see if we have root access 4345# quick check to see if we have root access
3238def rootCheck(): 4346def rootCheck(fatal):
3239 if(os.environ['USER'] != 'root'): 4347 global sysvals
3240 doError('This script must be run as root', False) 4348 if(os.access(sysvals.powerfile, os.W_OK)):
4349 return True
4350 if fatal:
4351 doError('This command must be run as root', False)
4352 return False
3241 4353
3242# Function: getArgInt 4354# Function: getArgInt
3243# Description: 4355# Description:
3244# pull out an integer argument from the command line with checks 4356# pull out an integer argument from the command line with checks
3245def getArgInt(name, args, min, max): 4357def getArgInt(name, args, min, max, main=True):
3246 try: 4358 if main:
3247 arg = args.next() 4359 try:
3248 except: 4360 arg = args.next()
3249 doError(name+': no argument supplied', True) 4361 except:
4362 doError(name+': no argument supplied', True)
4363 else:
4364 arg = args
3250 try: 4365 try:
3251 val = int(arg) 4366 val = int(arg)
3252 except: 4367 except:
@@ -3255,6 +4370,25 @@ def getArgInt(name, args, min, max):
3255 doError(name+': value should be between %d and %d' % (min, max), True) 4370 doError(name+': value should be between %d and %d' % (min, max), True)
3256 return val 4371 return val
3257 4372
4373# Function: getArgFloat
4374# Description:
4375# pull out a float argument from the command line with checks
4376def getArgFloat(name, args, min, max, main=True):
4377 if main:
4378 try:
4379 arg = args.next()
4380 except:
4381 doError(name+': no argument supplied', True)
4382 else:
4383 arg = args
4384 try:
4385 val = float(arg)
4386 except:
4387 doError(name+': non-numerical value given', True)
4388 if(val < min or val > max):
4389 doError(name+': value should be between %f and %f' % (min, max), True)
4390 return val
4391
3258# Function: rerunTest 4392# Function: rerunTest
3259# Description: 4393# Description:
3260# generate an output from an existing set of ftrace/dmesg logs 4394# generate an output from an existing set of ftrace/dmesg logs
@@ -3282,15 +4416,12 @@ def rerunTest():
3282# Function: runTest 4416# Function: runTest
3283# Description: 4417# Description:
3284# execute a suspend/resume, gather the logs, and generate the output 4418# execute a suspend/resume, gather the logs, and generate the output
3285def runTest(subdir): 4419def runTest(subdir, testpath=''):
3286 global sysvals 4420 global sysvals
3287 4421
3288 # prepare for the test 4422 # prepare for the test
3289 if(not sysvals.android): 4423 sysvals.initFtrace()
3290 initFtrace() 4424 sysvals.initTestOutput(subdir, testpath)
3291 else:
3292 initFtraceAndroid()
3293 sysvals.initTestOutput(subdir)
3294 4425
3295 vprint('Output files:\n %s' % sysvals.dmesgfile) 4426 vprint('Output files:\n %s' % sysvals.dmesgfile)
3296 if(sysvals.usecallgraph or 4427 if(sysvals.usecallgraph or
@@ -3300,10 +4431,8 @@ def runTest(subdir):
3300 vprint(' %s' % sysvals.htmlfile) 4431 vprint(' %s' % sysvals.htmlfile)
3301 4432
3302 # execute the test 4433 # execute the test
3303 if(not sysvals.android): 4434 executeSuspend()
3304 executeSuspend() 4435 sysvals.cleanupFtrace()
3305 else:
3306 executeAndroidSuspend()
3307 4436
3308 # analyze the data and create the html output 4437 # analyze the data and create the html output
3309 print('PROCESSING DATA') 4438 print('PROCESSING DATA')
@@ -3367,6 +4496,153 @@ def runSummary(subdir, output):
3367 4496
3368 createHTMLSummarySimple(testruns, subdir+'/summary.html') 4497 createHTMLSummarySimple(testruns, subdir+'/summary.html')
3369 4498
4499# Function: checkArgBool
4500# Description:
4501# check if a boolean string value is true or false
4502def checkArgBool(value):
4503 yes = ['1', 'true', 'yes', 'on']
4504 if value.lower() in yes:
4505 return True
4506 return False
4507
4508# Function: configFromFile
4509# Description:
4510# Configure the script via the info in a config file
4511def configFromFile(file):
4512 global sysvals
4513 Config = ConfigParser.ConfigParser()
4514
4515 ignorekprobes = False
4516 Config.read(file)
4517 sections = Config.sections()
4518 if 'Settings' in sections:
4519 for opt in Config.options('Settings'):
4520 value = Config.get('Settings', opt).lower()
4521 if(opt.lower() == 'verbose'):
4522 sysvals.verbose = checkArgBool(value)
4523 elif(opt.lower() == 'addlogs'):
4524 sysvals.addlogs = checkArgBool(value)
4525 elif(opt.lower() == 'dev'):
4526 sysvals.usedevsrc = checkArgBool(value)
4527 elif(opt.lower() == 'ignorekprobes'):
4528 ignorekprobes = checkArgBool(value)
4529 elif(opt.lower() == 'x2'):
4530 if checkArgBool(value):
4531 sysvals.execcount = 2
4532 elif(opt.lower() == 'callgraph'):
4533 sysvals.usecallgraph = checkArgBool(value)
4534 elif(opt.lower() == 'callgraphfunc'):
4535 sysvals.debugfuncs = []
4536 if value:
4537 value = value.split(',')
4538 for i in value:
4539 sysvals.debugfuncs.append(i.strip())
4540 elif(opt.lower() == 'expandcg'):
4541 sysvals.cgexp = checkArgBool(value)
4542 elif(opt.lower() == 'srgap'):
4543 if checkArgBool(value):
4544 sysvals.srgap = 5
4545 elif(opt.lower() == 'mode'):
4546 sysvals.suspendmode = value
4547 elif(opt.lower() == 'command'):
4548 sysvals.testcommand = value
4549 elif(opt.lower() == 'x2delay'):
4550 sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
4551 elif(opt.lower() == 'postres'):
4552 sysvals.postresumetime = getArgInt('-postres', value, 0, 3600, False)
4553 elif(opt.lower() == 'rtcwake'):
4554 sysvals.rtcwake = True
4555 sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
4556 elif(opt.lower() == 'timeprec'):
4557 sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
4558 elif(opt.lower() == 'mindev'):
4559 sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
4560 elif(opt.lower() == 'mincg'):
4561 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
4562 elif(opt.lower() == 'kprobecolor'):
4563 try:
4564 val = int(value, 16)
4565 sysvals.kprobecolor = '#'+value
4566 except:
4567 sysvals.kprobecolor = value
4568 elif(opt.lower() == 'synccolor'):
4569 try:
4570 val = int(value, 16)
4571 sysvals.synccolor = '#'+value
4572 except:
4573 sysvals.synccolor = value
4574 elif(opt.lower() == 'output-dir'):
4575 args = dict()
4576 n = datetime.now()
4577 args['date'] = n.strftime('%y%m%d')
4578 args['time'] = n.strftime('%H%M%S')
4579 args['hostname'] = sysvals.hostname
4580 sysvals.outdir = value.format(**args)
4581
4582 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
4583 doError('No command supplied for mode "command"', False)
4584 if sysvals.usedevsrc and sysvals.usecallgraph:
4585 doError('dev and callgraph cannot both be true', False)
4586 if sysvals.usecallgraph and sysvals.execcount > 1:
4587 doError('-x2 is not compatible with -f', False)
4588
4589 if ignorekprobes:
4590 return
4591
4592 kprobes = dict()
4593 archkprobe = 'Kprobe_'+platform.machine()
4594 if archkprobe in sections:
4595 for name in Config.options(archkprobe):
4596 kprobes[name] = Config.get(archkprobe, name)
4597 if 'Kprobe' in sections:
4598 for name in Config.options('Kprobe'):
4599 kprobes[name] = Config.get('Kprobe', name)
4600
4601 for name in kprobes:
4602 function = name
4603 format = name
4604 color = ''
4605 args = dict()
4606 data = kprobes[name].split()
4607 i = 0
4608 for val in data:
4609 # bracketted strings are special formatting, read them separately
4610 if val[0] == '[' and val[-1] == ']':
4611 for prop in val[1:-1].split(','):
4612 p = prop.split('=')
4613 if p[0] == 'color':
4614 try:
4615 color = int(p[1], 16)
4616 color = '#'+p[1]
4617 except:
4618 color = p[1]
4619 continue
4620 # first real arg should be the format string
4621 if i == 0:
4622 format = val
4623 # all other args are actual function args
4624 else:
4625 d = val.split('=')
4626 args[d[0]] = d[1]
4627 i += 1
4628 if not function or not format:
4629 doError('Invalid kprobe: %s' % name, False)
4630 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
4631 if arg not in args:
4632 doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
4633 if name in sysvals.kprobes:
4634 doError('Duplicate kprobe found "%s"' % (name), False)
4635 vprint('Adding KPROBE: %s %s %s %s' % (name, function, format, args))
4636 sysvals.kprobes[name] = {
4637 'name': name,
4638 'func': function,
4639 'format': format,
4640 'args': args,
4641 'mask': re.sub('{(?P<n>[a-z,A-Z,0-9]*)}', '.*', format)
4642 }
4643 if color:
4644 sysvals.kprobes[name]['color'] = color
4645
3370# Function: printHelp 4646# Function: printHelp
3371# Description: 4647# Description:
3372# print out the help text 4648# print out the help text
@@ -3375,7 +4651,7 @@ def printHelp():
3375 modes = getModes() 4651 modes = getModes()
3376 4652
3377 print('') 4653 print('')
3378 print('AnalyzeSuspend v%.1f' % sysvals.version) 4654 print('AnalyzeSuspend v%s' % sysvals.version)
3379 print('Usage: sudo analyze_suspend.py <options>') 4655 print('Usage: sudo analyze_suspend.py <options>')
3380 print('') 4656 print('')
3381 print('Description:') 4657 print('Description:')
@@ -3396,27 +4672,38 @@ def printHelp():
3396 print(' [general]') 4672 print(' [general]')
3397 print(' -h Print this help text') 4673 print(' -h Print this help text')
3398 print(' -v Print the current tool version') 4674 print(' -v Print the current tool version')
4675 print(' -config file Pull arguments and config options from a file')
3399 print(' -verbose Print extra information during execution and analysis') 4676 print(' -verbose Print extra information during execution and analysis')
3400 print(' -status Test to see if the system is enabled to run this tool') 4677 print(' -status Test to see if the system is enabled to run this tool')
3401 print(' -modes List available suspend modes') 4678 print(' -modes List available suspend modes')
3402 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode) 4679 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
3403 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)') 4680 print(' -o subdir Override the output subdirectory')
3404 print(' [advanced]') 4681 print(' [advanced]')
4682 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
4683 print(' -addlogs Add the dmesg and ftrace logs to the html output')
4684 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
4685 print(' be created in a new subdirectory with a summary page.')
4686 print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
4687 print(' -cmd {s} Instead of suspend/resume, run a command, e.g. "sync -d"')
4688 print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
4689 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
4690 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
4691 print(' [debug]')
3405 print(' -f Use ftrace to create device callgraphs (default: disabled)') 4692 print(' -f Use ftrace to create device callgraphs (default: disabled)')
3406 print(' -filter "d1 d2 ..." Filter out all but this list of dev names') 4693 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
4694 print(' -flist Print the list of functions currently being captured in ftrace')
4695 print(' -flistall Print all functions capable of being captured in ftrace')
4696 print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
4697 print(' -filter "d1 d2 ..." Filter out all but this list of device names')
4698 print(' -dev Display common low level functions in the timeline')
4699 print(' [post-resume task analysis]')
3407 print(' -x2 Run two suspend/resumes back to back (default: disabled)') 4700 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
3408 print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)') 4701 print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
3409 print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)') 4702 print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)')
3410 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
3411 print(' be created in a new subdirectory with a summary page.')
3412 print(' [utilities]') 4703 print(' [utilities]')
3413 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') 4704 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
3414 print(' -usbtopo Print out the current USB topology with power info') 4705 print(' -usbtopo Print out the current USB topology with power info')
3415 print(' -usbauto Enable autosuspend for all connected USB devices') 4706 print(' -usbauto Enable autosuspend for all connected USB devices')
3416 print(' [android testing]')
3417 print(' -adb binary Use the given adb binary to run the test on an android device.')
3418 print(' The device should already be connected and with root access.')
3419 print(' Commands will be executed on the device using "adb shell"')
3420 print(' [re-analyze data from previous runs]') 4707 print(' [re-analyze data from previous runs]')
3421 print(' -ftrace ftracefile Create HTML output using ftrace input') 4708 print(' -ftrace ftracefile Create HTML output using ftrace input')
3422 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)') 4709 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)')
@@ -3430,6 +4717,7 @@ if __name__ == '__main__':
3430 cmd = '' 4717 cmd = ''
3431 cmdarg = '' 4718 cmdarg = ''
3432 multitest = {'run': False, 'count': 0, 'delay': 0} 4719 multitest = {'run': False, 'count': 0, 'delay': 0}
4720 simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
3433 # loop through the command line arguments 4721 # loop through the command line arguments
3434 args = iter(sys.argv[1:]) 4722 args = iter(sys.argv[1:])
3435 for arg in args: 4723 for arg in args:
@@ -3438,58 +4726,85 @@ if __name__ == '__main__':
3438 val = args.next() 4726 val = args.next()
3439 except: 4727 except:
3440 doError('No mode supplied', True) 4728 doError('No mode supplied', True)
4729 if val == 'command' and not sysvals.testcommand:
4730 doError('No command supplied for mode "command"', True)
3441 sysvals.suspendmode = val 4731 sysvals.suspendmode = val
3442 elif(arg == '-adb'): 4732 elif(arg in simplecmds):
3443 try: 4733 cmd = arg[1:]
3444 val = args.next() 4734 elif(arg == '-h'):
3445 except: 4735 printHelp()
3446 doError('No adb binary supplied', True) 4736 sys.exit()
3447 if(not os.path.exists(val)): 4737 elif(arg == '-v'):
3448 doError('file doesnt exist: %s' % val, False) 4738 print("Version %s" % sysvals.version)
3449 if(not os.access(val, os.X_OK)): 4739 sys.exit()
3450 doError('file isnt executable: %s' % val, False)
3451 try:
3452 check = os.popen(val+' version').read().strip()
3453 except:
3454 doError('adb version failed to execute', False)
3455 if(not re.match('Android Debug Bridge .*', check)):
3456 doError('adb version failed to execute', False)
3457 sysvals.adb = val
3458 sysvals.android = True
3459 elif(arg == '-x2'): 4740 elif(arg == '-x2'):
3460 if(sysvals.postresumetime > 0):
3461 doError('-x2 is not compatible with -postres', False)
3462 sysvals.execcount = 2 4741 sysvals.execcount = 2
4742 if(sysvals.usecallgraph):
4743 doError('-x2 is not compatible with -f', False)
3463 elif(arg == '-x2delay'): 4744 elif(arg == '-x2delay'):
3464 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000) 4745 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
3465 elif(arg == '-postres'): 4746 elif(arg == '-postres'):
3466 if(sysvals.execcount != 1):
3467 doError('-x2 is not compatible with -postres', False)
3468 sysvals.postresumetime = getArgInt('-postres', args, 0, 3600) 4747 sysvals.postresumetime = getArgInt('-postres', args, 0, 3600)
3469 elif(arg == '-f'): 4748 elif(arg == '-f'):
3470 sysvals.usecallgraph = True 4749 sysvals.usecallgraph = True
3471 elif(arg == '-modes'): 4750 if(sysvals.execcount > 1):
3472 cmd = 'modes' 4751 doError('-x2 is not compatible with -f', False)
3473 elif(arg == '-fpdt'): 4752 if(sysvals.usedevsrc):
3474 cmd = 'fpdt' 4753 doError('-dev is not compatible with -f', False)
3475 elif(arg == '-usbtopo'): 4754 elif(arg == '-addlogs'):
3476 cmd = 'usbtopo' 4755 sysvals.addlogs = True
3477 elif(arg == '-usbauto'):
3478 cmd = 'usbauto'
3479 elif(arg == '-status'):
3480 cmd = 'status'
3481 elif(arg == '-verbose'): 4756 elif(arg == '-verbose'):
3482 sysvals.verbose = True 4757 sysvals.verbose = True
3483 elif(arg == '-v'): 4758 elif(arg == '-dev'):
3484 print("Version %.1f" % sysvals.version) 4759 sysvals.usedevsrc = True
3485 sys.exit() 4760 if(sysvals.usecallgraph):
4761 doError('-dev is not compatible with -f', False)
3486 elif(arg == '-rtcwake'): 4762 elif(arg == '-rtcwake'):
3487 sysvals.rtcwake = True 4763 sysvals.rtcwake = True
3488 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600) 4764 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
4765 elif(arg == '-timeprec'):
4766 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
4767 elif(arg == '-mindev'):
4768 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
4769 elif(arg == '-mincg'):
4770 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
4771 elif(arg == '-cmd'):
4772 try:
4773 val = args.next()
4774 except:
4775 doError('No command string supplied', True)
4776 sysvals.testcommand = val
4777 sysvals.suspendmode = 'command'
4778 elif(arg == '-expandcg'):
4779 sysvals.cgexp = True
4780 elif(arg == '-srgap'):
4781 sysvals.srgap = 5
3489 elif(arg == '-multi'): 4782 elif(arg == '-multi'):
3490 multitest['run'] = True 4783 multitest['run'] = True
3491 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000) 4784 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
3492 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600) 4785 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
4786 elif(arg == '-o'):
4787 try:
4788 val = args.next()
4789 except:
4790 doError('No subdirectory name supplied', True)
4791 sysvals.outdir = val
4792 elif(arg == '-config'):
4793 try:
4794 val = args.next()
4795 except:
4796 doError('No text file supplied', True)
4797 if(os.path.exists(val) == False):
4798 doError('%s does not exist' % val, False)
4799 configFromFile(val)
4800 elif(arg == '-fadd'):
4801 try:
4802 val = args.next()
4803 except:
4804 doError('No text file supplied', True)
4805 if(os.path.exists(val) == False):
4806 doError('%s does not exist' % val, False)
4807 sysvals.addFtraceFilterFunctions(val)
3493 elif(arg == '-dmesg'): 4808 elif(arg == '-dmesg'):
3494 try: 4809 try:
3495 val = args.next() 4810 val = args.next()
@@ -3498,17 +4813,16 @@ if __name__ == '__main__':
3498 sysvals.notestrun = True 4813 sysvals.notestrun = True
3499 sysvals.dmesgfile = val 4814 sysvals.dmesgfile = val
3500 if(os.path.exists(sysvals.dmesgfile) == False): 4815 if(os.path.exists(sysvals.dmesgfile) == False):
3501 doError('%s doesnt exist' % sysvals.dmesgfile, False) 4816 doError('%s does not exist' % sysvals.dmesgfile, False)
3502 elif(arg == '-ftrace'): 4817 elif(arg == '-ftrace'):
3503 try: 4818 try:
3504 val = args.next() 4819 val = args.next()
3505 except: 4820 except:
3506 doError('No ftrace file supplied', True) 4821 doError('No ftrace file supplied', True)
3507 sysvals.notestrun = True 4822 sysvals.notestrun = True
3508 sysvals.usecallgraph = True
3509 sysvals.ftracefile = val 4823 sysvals.ftracefile = val
3510 if(os.path.exists(sysvals.ftracefile) == False): 4824 if(os.path.exists(sysvals.ftracefile) == False):
3511 doError('%s doesnt exist' % sysvals.ftracefile, False) 4825 doError('%s does not exist' % sysvals.ftracefile, False)
3512 elif(arg == '-summary'): 4826 elif(arg == '-summary'):
3513 try: 4827 try:
3514 val = args.next() 4828 val = args.next()
@@ -3518,35 +4832,35 @@ if __name__ == '__main__':
3518 cmdarg = val 4832 cmdarg = val
3519 sysvals.notestrun = True 4833 sysvals.notestrun = True
3520 if(os.path.isdir(val) == False): 4834 if(os.path.isdir(val) == False):
3521 doError('%s isnt accesible' % val, False) 4835 doError('%s is not accesible' % val, False)
3522 elif(arg == '-filter'): 4836 elif(arg == '-filter'):
3523 try: 4837 try:
3524 val = args.next() 4838 val = args.next()
3525 except: 4839 except:
3526 doError('No devnames supplied', True) 4840 doError('No devnames supplied', True)
3527 sysvals.setDeviceFilter(val) 4841 sysvals.setDeviceFilter(val)
3528 elif(arg == '-h'):
3529 printHelp()
3530 sys.exit()
3531 else: 4842 else:
3532 doError('Invalid argument: '+arg, True) 4843 doError('Invalid argument: '+arg, True)
3533 4844
4845 # callgraph size cannot exceed device size
4846 if sysvals.mincglen < sysvals.mindevlen:
4847 sysvals.mincglen = sysvals.mindevlen
4848
3534 # just run a utility command and exit 4849 # just run a utility command and exit
3535 if(cmd != ''): 4850 if(cmd != ''):
3536 if(cmd == 'status'): 4851 if(cmd == 'status'):
3537 statusCheck() 4852 statusCheck(True)
3538 elif(cmd == 'fpdt'): 4853 elif(cmd == 'fpdt'):
3539 if(sysvals.android):
3540 doError('cannot read FPDT on android device', False)
3541 getFPDT(True) 4854 getFPDT(True)
3542 elif(cmd == 'usbtopo'): 4855 elif(cmd == 'usbtopo'):
3543 if(sysvals.android): 4856 detectUSB()
3544 doError('cannot read USB topology '+\
3545 'on an android device', False)
3546 detectUSB(True)
3547 elif(cmd == 'modes'): 4857 elif(cmd == 'modes'):
3548 modes = getModes() 4858 modes = getModes()
3549 print modes 4859 print modes
4860 elif(cmd == 'flist'):
4861 sysvals.getFtraceFilterFunctions(True)
4862 elif(cmd == 'flistall'):
4863 sysvals.getFtraceFilterFunctions(False)
3550 elif(cmd == 'usbauto'): 4864 elif(cmd == 'usbauto'):
3551 setUSBDevicesAuto() 4865 setUSBDevicesAuto()
3552 elif(cmd == 'summary'): 4866 elif(cmd == 'summary'):
@@ -3554,15 +4868,6 @@ if __name__ == '__main__':
3554 runSummary(cmdarg, True) 4868 runSummary(cmdarg, True)
3555 sys.exit() 4869 sys.exit()
3556 4870
3557 # run test on android device
3558 if(sysvals.android):
3559 if(sysvals.usecallgraph):
3560 doError('ftrace (-f) is not yet supported '+\
3561 'in the android kernel', False)
3562 if(sysvals.notestrun):
3563 doError('cannot analyze test files on the '+\
3564 'android device', False)
3565
3566 # if instructed, re-analyze existing data files 4871 # if instructed, re-analyze existing data files
3567 if(sysvals.notestrun): 4872 if(sysvals.notestrun):
3568 rerunTest() 4873 rerunTest()
@@ -3574,18 +4879,20 @@ if __name__ == '__main__':
3574 sys.exit() 4879 sys.exit()
3575 4880
3576 if multitest['run']: 4881 if multitest['run']:
3577 # run multiple tests in a separte subdirectory 4882 # run multiple tests in a separate subdirectory
3578 s = 'x%d' % multitest['count'] 4883 s = 'x%d' % multitest['count']
3579 subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S') 4884 if not sysvals.outdir:
3580 os.mkdir(subdir) 4885 sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
4886 if not os.path.isdir(sysvals.outdir):
4887 os.mkdir(sysvals.outdir)
3581 for i in range(multitest['count']): 4888 for i in range(multitest['count']):
3582 if(i != 0): 4889 if(i != 0):
3583 print('Waiting %d seconds...' % (multitest['delay'])) 4890 print('Waiting %d seconds...' % (multitest['delay']))
3584 time.sleep(multitest['delay']) 4891 time.sleep(multitest['delay'])
3585 print('TEST (%d/%d) START' % (i+1, multitest['count'])) 4892 print('TEST (%d/%d) START' % (i+1, multitest['count']))
3586 runTest(subdir) 4893 runTest(sysvals.outdir)
3587 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) 4894 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
3588 runSummary(subdir, False) 4895 runSummary(sysvals.outdir, False)
3589 else: 4896 else:
3590 # run the test in the current directory 4897 # run the test in the current directory
3591 runTest(".") 4898 runTest('.', sysvals.outdir)