]> git.proxmox.com Git - mirror_ubuntu-artful-kernel.git/blame - scripts/analyze_suspend.py
Merge branches 'for-4.11/upstream-fixes', 'for-4.12/accutouch', 'for-4.12/cp2112...
[mirror_ubuntu-artful-kernel.git] / scripts / analyze_suspend.py
CommitLineData
ee8b09cd
TB
1#!/usr/bin/python
2#
3# Tool for analyzing suspend/resume timing
4# Copyright (c) 2013, Intel Corporation.
5#
6# This program is free software; you can redistribute it and/or modify it
7# under the terms and conditions of the GNU General Public License,
8# version 2, as published by the Free Software Foundation.
9#
10# This program is distributed in the hope it will be useful, but WITHOUT
11# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
13# more details.
14#
15# You should have received a copy of the GNU General Public License along with
16# this program; if not, write to the Free Software Foundation, Inc.,
17# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
18#
19# Authors:
20# Todd Brandt <todd.e.brandt@linux.intel.com>
21#
af1e45e6
TB
22# Links:
23# Home Page
24# https://01.org/suspendresume
25# Source repo
26# https://github.com/01org/suspendresume
af1e45e6 27#
ee8b09cd
TB
28# Description:
29# This tool is designed to assist kernel and OS developers in optimizing
30# their linux stack's suspend/resume time. Using a kernel image built
31# with a few extra options enabled, the tool will execute a suspend and
32# will capture dmesg and ftrace data until resume is complete. This data
33# is transformed into a device timeline and a callgraph to give a quick
34# and detailed view of which devices and callbacks are taking the most
35# time in suspend/resume. The output is a single html file which can be
36# viewed in firefox or chrome.
37#
38# The following kernel build options are required:
39# CONFIG_PM_DEBUG=y
40# CONFIG_PM_SLEEP_DEBUG=y
41# CONFIG_FTRACE=y
42# CONFIG_FUNCTION_TRACER=y
43# CONFIG_FUNCTION_GRAPH_TRACER=y
af1e45e6
TB
44# CONFIG_KPROBES=y
45# CONFIG_KPROBES_ON_FTRACE=y
ee8b09cd 46#
b8432c6f 47# For kernel versions older than 3.15:
ee8b09cd
TB
48# The following additional kernel parameters are required:
49# (e.g. in file /etc/default/grub)
50# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
51#
52
b8432c6f
TB
53# ----------------- LIBRARIES --------------------
54
ee8b09cd
TB
55import sys
56import time
57import os
58import string
59import re
ee8b09cd 60import platform
b8432c6f 61from datetime import datetime
ee8b09cd 62import struct
af1e45e6 63import ConfigParser
203f1f98 64from threading import Thread
1ea39643 65from subprocess import call, Popen, PIPE
ee8b09cd 66
b8432c6f 67# ----------------- CLASSES --------------------
ee8b09cd 68
b8432c6f
TB
69# Class: SystemValues
70# Description:
71# A global, single-instance container used to
72# store system values and test parameters
ee8b09cd 73class SystemValues:
af1e45e6 74 ansi = False
03bc39be 75 version = '4.5'
b8432c6f 76 verbose = False
af1e45e6 77 addlogs = False
03bc39be
TB
78 mindevlen = 0.0
79 mincglen = 0.0
80 cgphase = ''
81 cgtest = -1
1ea39643
TB
82 callloopmaxgap = 0.0001
83 callloopmaxlen = 0.005
af1e45e6
TB
84 srgap = 0
85 cgexp = False
86 outdir = ''
b8432c6f
TB
87 testdir = '.'
88 tpath = '/sys/kernel/debug/tracing/'
89 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
90 epath = '/sys/kernel/debug/tracing/events/power/'
91 traceevents = [
92 'suspend_resume',
93 'device_pm_callback_end',
94 'device_pm_callback_start'
95 ]
03bc39be 96 logmsg = ''
af1e45e6 97 testcommand = ''
b8432c6f
TB
98 mempath = '/dev/mem'
99 powerfile = '/sys/power/state'
100 suspendmode = 'mem'
101 hostname = 'localhost'
102 prefix = 'test'
103 teststamp = ''
af1e45e6 104 dmesgstart = 0.0
b8432c6f
TB
105 dmesgfile = ''
106 ftracefile = ''
107 htmlfile = ''
af1e45e6 108 embedded = False
ee8b09cd 109 rtcwake = False
b8432c6f
TB
110 rtcwaketime = 10
111 rtcpath = ''
b8432c6f
TB
112 devicefilter = []
113 stamp = 0
114 execcount = 1
115 x2delay = 0
116 usecallgraph = False
117 usetraceevents = False
118 usetraceeventsonly = False
af1e45e6
TB
119 usetracemarkers = True
120 usekprobes = True
121 usedevsrc = False
203f1f98 122 useprocmon = False
b8432c6f 123 notestrun = False
203f1f98 124 mixedphaseheight = True
af1e45e6 125 devprops = dict()
203f1f98
TB
126 predelay = 0
127 postdelay = 0
128 procexecfmt = 'ps - (?P<ps>.*)$'
af1e45e6 129 devpropfmt = '# Device Properties: .*'
b8432c6f
TB
130 tracertypefmt = '# tracer: (?P<t>.*)'
131 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
b8432c6f
TB
132 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
133 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
134 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
af1e45e6
TB
135 tracefuncs = {
136 'sys_sync': dict(),
137 'pm_prepare_console': dict(),
138 'pm_notifier_call_chain': dict(),
139 'freeze_processes': dict(),
140 'freeze_kernel_threads': dict(),
141 'pm_restrict_gfp_mask': dict(),
142 'acpi_suspend_begin': dict(),
143 'suspend_console': dict(),
144 'acpi_pm_prepare': dict(),
145 'syscore_suspend': dict(),
146 'arch_enable_nonboot_cpus_end': dict(),
147 'syscore_resume': dict(),
148 'acpi_pm_finish': dict(),
149 'resume_console': dict(),
150 'acpi_pm_end': dict(),
151 'pm_restore_gfp_mask': dict(),
152 'thaw_processes': dict(),
153 'pm_restore_console': dict(),
154 'CPU_OFF': {
155 'func':'_cpu_down',
156 'args_x86_64': {'cpu':'%di:s32'},
203f1f98 157 'format': 'CPU_OFF[{cpu}]'
af1e45e6
TB
158 },
159 'CPU_ON': {
160 'func':'_cpu_up',
161 'args_x86_64': {'cpu':'%di:s32'},
203f1f98 162 'format': 'CPU_ON[{cpu}]'
af1e45e6
TB
163 },
164 }
165 dev_tracefuncs = {
166 # general wait/delay/sleep
03bc39be
TB
167 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
168 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
169 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
170 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
171 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
172 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
173 'acpi_os_stall': {'ub': 1},
af1e45e6
TB
174 # ACPI
175 'acpi_resume_power_resources': dict(),
176 'acpi_ps_parse_aml': dict(),
177 # filesystem
178 'ext4_sync_fs': dict(),
03bc39be
TB
179 # 80211
180 'iwlagn_mac_start': dict(),
181 'iwlagn_alloc_bcast_station': dict(),
182 'iwl_trans_pcie_start_hw': dict(),
183 'iwl_trans_pcie_start_fw': dict(),
184 'iwl_run_init_ucode': dict(),
185 'iwl_load_ucode_wait_alive': dict(),
186 'iwl_alive_start': dict(),
187 'iwlagn_mac_stop': dict(),
188 'iwlagn_mac_suspend': dict(),
189 'iwlagn_mac_resume': dict(),
190 'iwlagn_mac_add_interface': dict(),
191 'iwlagn_mac_remove_interface': dict(),
192 'iwlagn_mac_change_interface': dict(),
193 'iwlagn_mac_config': dict(),
194 'iwlagn_configure_filter': dict(),
195 'iwlagn_mac_hw_scan': dict(),
196 'iwlagn_bss_info_changed': dict(),
197 'iwlagn_mac_channel_switch': dict(),
198 'iwlagn_mac_flush': dict(),
af1e45e6
TB
199 # ATA
200 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
201 # i915
203f1f98
TB
202 'i915_gem_resume': dict(),
203 'i915_restore_state': dict(),
af1e45e6 204 'intel_opregion_setup': dict(),
203f1f98
TB
205 'g4x_pre_enable_dp': dict(),
206 'vlv_pre_enable_dp': dict(),
207 'chv_pre_enable_dp': dict(),
208 'g4x_enable_dp': dict(),
209 'vlv_enable_dp': dict(),
210 'intel_hpd_init': dict(),
211 'intel_opregion_register': dict(),
af1e45e6
TB
212 'intel_dp_detect': dict(),
213 'intel_hdmi_detect': dict(),
214 'intel_opregion_init': dict(),
203f1f98 215 'intel_fbdev_set_suspend': dict(),
af1e45e6 216 }
af1e45e6
TB
217 kprobes = dict()
218 timeformat = '%.3f'
b8432c6f 219 def __init__(self):
af1e45e6
TB
220 # if this is a phoronix test run, set some default options
221 if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
222 self.embedded = True
223 self.addlogs = True
224 self.htmlfile = os.environ['LOG_FILE']
1ea39643 225 self.archargs = 'args_'+platform.machine()
b8432c6f
TB
226 self.hostname = platform.node()
227 if(self.hostname == ''):
228 self.hostname = 'localhost'
229 rtc = "rtc0"
230 if os.path.exists('/dev/rtc'):
231 rtc = os.readlink('/dev/rtc')
232 rtc = '/sys/class/rtc/'+rtc
233 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
234 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
235 self.rtcpath = rtc
af1e45e6
TB
236 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
237 self.ansi = True
238 def setPrecision(self, num):
239 if num < 0 or num > 6:
240 return
241 self.timeformat = '%.{0}f'.format(num)
203f1f98
TB
242 def setOutputFolder(self, value):
243 args = dict()
244 n = datetime.now()
245 args['date'] = n.strftime('%y%m%d')
246 args['time'] = n.strftime('%H%M%S')
247 args['hostname'] = self.hostname
248 self.outdir = value.format(**args)
ee8b09cd 249 def setOutputFile(self):
b8432c6f
TB
250 if((self.htmlfile == '') and (self.dmesgfile != '')):
251 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
ee8b09cd 252 if(m):
b8432c6f
TB
253 self.htmlfile = m.group('name')+'.html'
254 if((self.htmlfile == '') and (self.ftracefile != '')):
255 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
ee8b09cd 256 if(m):
b8432c6f
TB
257 self.htmlfile = m.group('name')+'.html'
258 if(self.htmlfile == ''):
259 self.htmlfile = 'output.html'
af1e45e6
TB
260 def initTestOutput(self, subdir, testpath=''):
261 self.prefix = self.hostname
262 v = open('/proc/version', 'r').read().strip()
263 kver = string.split(v)[2]
264 n = datetime.now()
265 testtime = n.strftime('suspend-%m%d%y-%H%M%S')
266 if not testpath:
267 testpath = n.strftime('suspend-%y%m%d-%H%M%S')
b8432c6f 268 if(subdir != "."):
af1e45e6 269 self.testdir = subdir+"/"+testpath
b8432c6f 270 else:
af1e45e6 271 self.testdir = testpath
b8432c6f
TB
272 self.teststamp = \
273 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
af1e45e6
TB
274 if(self.embedded):
275 self.dmesgfile = \
276 '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'
277 self.ftracefile = \
278 '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
279 return
b8432c6f
TB
280 self.dmesgfile = \
281 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
282 self.ftracefile = \
283 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
284 self.htmlfile = \
285 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
af1e45e6
TB
286 if not os.path.isdir(self.testdir):
287 os.mkdir(self.testdir)
203f1f98
TB
288 def setDeviceFilter(self, value):
289 self.devicefilter = []
290 if value:
291 value = value.split(',')
292 for i in value:
293 self.devicefilter.append(i.strip())
af1e45e6 294 def rtcWakeAlarmOn(self):
1ea39643 295 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
b8432c6f
TB
296 outD = open(self.rtcpath+'/date', 'r').read().strip()
297 outT = open(self.rtcpath+'/time', 'r').read().strip()
298 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
299 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
300 if(mD and mT):
301 # get the current time from hardware
302 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
303 dt = datetime(\
304 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
305 int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
306 nowtime = int(dt.strftime('%s')) + utcoffset
307 else:
308 # if hardware time fails, use the software time
309 nowtime = int(datetime.now().strftime('%s'))
310 alarm = nowtime + self.rtcwaketime
1ea39643 311 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
af1e45e6 312 def rtcWakeAlarmOff(self):
1ea39643 313 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
af1e45e6
TB
314 def initdmesg(self):
315 # get the latest time stamp from the dmesg log
1ea39643 316 fp = Popen('dmesg', stdout=PIPE).stdout
af1e45e6
TB
317 ktime = '0'
318 for line in fp:
319 line = line.replace('\r\n', '')
320 idx = line.find('[')
321 if idx > 1:
322 line = line[idx:]
323 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
324 if(m):
325 ktime = m.group('ktime')
326 fp.close()
327 self.dmesgstart = float(ktime)
328 def getdmesg(self):
329 # store all new dmesg lines since initdmesg was called
1ea39643 330 fp = Popen('dmesg', stdout=PIPE).stdout
af1e45e6
TB
331 op = open(self.dmesgfile, 'a')
332 for line in fp:
333 line = line.replace('\r\n', '')
334 idx = line.find('[')
335 if idx > 1:
336 line = line[idx:]
337 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
338 if(not m):
339 continue
340 ktime = float(m.group('ktime'))
341 if ktime > self.dmesgstart:
342 op.write(line)
343 fp.close()
344 op.close()
345 def addFtraceFilterFunctions(self, file):
346 fp = open(file)
347 list = fp.read().split('\n')
348 fp.close()
349 for i in list:
350 if len(i) < 2:
351 continue
352 self.tracefuncs[i] = dict()
353 def getFtraceFilterFunctions(self, current):
354 rootCheck(True)
355 if not current:
1ea39643 356 call('cat '+self.tpath+'available_filter_functions', shell=True)
af1e45e6
TB
357 return
358 fp = open(self.tpath+'available_filter_functions')
359 master = fp.read().split('\n')
360 fp.close()
1ea39643
TB
361 for i in self.tracefuncs:
362 if 'func' in self.tracefuncs[i]:
363 i = self.tracefuncs[i]['func']
364 if i in master:
365 print i
366 else:
367 print self.colorText(i)
af1e45e6
TB
368 def setFtraceFilterFunctions(self, list):
369 fp = open(self.tpath+'available_filter_functions')
370 master = fp.read().split('\n')
371 fp.close()
372 flist = ''
373 for i in list:
374 if i not in master:
375 continue
376 if ' [' in i:
377 flist += i.split(' ')[0]+'\n'
378 else:
379 flist += i+'\n'
380 fp = open(self.tpath+'set_graph_function', 'w')
381 fp.write(flist)
382 fp.close()
af1e45e6 383 def basicKprobe(self, name):
203f1f98 384 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
af1e45e6
TB
385 def defaultKprobe(self, name, kdata):
386 k = kdata
203f1f98 387 for field in ['name', 'format', 'func']:
af1e45e6
TB
388 if field not in k:
389 k[field] = name
1ea39643
TB
390 if self.archargs in k:
391 k['args'] = k[self.archargs]
af1e45e6
TB
392 else:
393 k['args'] = dict()
394 k['format'] = name
395 self.kprobes[name] = k
396 def kprobeColor(self, name):
397 if name not in self.kprobes or 'color' not in self.kprobes[name]:
398 return ''
399 return self.kprobes[name]['color']
400 def kprobeDisplayName(self, name, dataraw):
401 if name not in self.kprobes:
402 self.basicKprobe(name)
403 data = ''
404 quote=0
405 # first remvoe any spaces inside quotes, and the quotes
406 for c in dataraw:
407 if c == '"':
408 quote = (quote + 1) % 2
409 if quote and c == ' ':
410 data += '_'
411 elif c != '"':
412 data += c
413 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
414 arglist = dict()
415 # now process the args
416 for arg in sorted(args):
417 arglist[arg] = ''
418 m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
419 if m:
420 arglist[arg] = m.group('arg')
421 else:
422 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
423 if m:
424 arglist[arg] = m.group('arg')
425 out = fmt.format(**arglist)
426 out = out.replace(' ', '_').replace('"', '')
427 return out
1ea39643
TB
428 def kprobeText(self, kname, kprobe):
429 name = fmt = func = kname
430 args = dict()
431 if 'name' in kprobe:
432 name = kprobe['name']
433 if 'format' in kprobe:
434 fmt = kprobe['format']
435 if 'func' in kprobe:
436 func = kprobe['func']
437 if self.archargs in kprobe:
438 args = kprobe[self.archargs]
439 if 'args' in kprobe:
440 args = kprobe['args']
af1e45e6 441 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
03bc39be 442 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
af1e45e6
TB
443 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
444 if arg not in args:
03bc39be 445 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
af1e45e6
TB
446 val = 'p:%s_cal %s' % (name, func)
447 for i in sorted(args):
448 val += ' %s=%s' % (i, args[i])
449 val += '\nr:%s_ret %s $retval\n' % (name, func)
450 return val
03bc39be
TB
451 def addKprobes(self, output=False):
452 if len(sysvals.kprobes) < 1:
453 return
454 if output:
455 print(' kprobe functions in this kernel:')
af1e45e6 456 # first test each kprobe
af1e45e6 457 rejects = []
03bc39be
TB
458 # sort kprobes: trace, ub-dev, custom, dev
459 kpl = [[], [], [], []]
af1e45e6 460 for name in sorted(self.kprobes):
03bc39be 461 res = self.colorText('YES', 32)
1ea39643 462 if not self.testKprobe(name, self.kprobes[name]):
03bc39be 463 res = self.colorText('NO')
af1e45e6 464 rejects.append(name)
03bc39be
TB
465 else:
466 if name in self.tracefuncs:
467 kpl[0].append(name)
468 elif name in self.dev_tracefuncs:
469 if 'ub' in self.dev_tracefuncs[name]:
470 kpl[1].append(name)
471 else:
472 kpl[3].append(name)
473 else:
474 kpl[2].append(name)
475 if output:
476 print(' %s: %s' % (name, res))
477 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
af1e45e6
TB
478 # remove all failed ones from the list
479 for name in rejects:
af1e45e6 480 self.kprobes.pop(name)
03bc39be 481 # set the kprobes all at once
af1e45e6
TB
482 self.fsetVal('', 'kprobe_events')
483 kprobeevents = ''
03bc39be 484 for kp in kplist:
1ea39643 485 kprobeevents += self.kprobeText(kp, self.kprobes[kp])
af1e45e6
TB
486 self.fsetVal(kprobeevents, 'kprobe_events')
487 # verify that the kprobes were set as ordered
488 check = self.fgetVal('kprobe_events')
03bc39be
TB
489 linesout = len(kprobeevents.split('\n')) - 1
490 linesack = len(check.split('\n')) - 1
491 if output:
492 res = '%d/%d' % (linesack, linesout)
493 if linesack < linesout:
494 res = self.colorText(res, 31)
495 else:
496 res = self.colorText(res, 32)
497 print(' working kprobe functions enabled: %s' % res)
af1e45e6 498 self.fsetVal('1', 'events/kprobes/enable')
1ea39643 499 def testKprobe(self, kname, kprobe):
03bc39be 500 self.fsetVal('0', 'events/kprobes/enable')
1ea39643 501 kprobeevents = self.kprobeText(kname, kprobe)
af1e45e6
TB
502 if not kprobeevents:
503 return False
504 try:
505 self.fsetVal(kprobeevents, 'kprobe_events')
506 check = self.fgetVal('kprobe_events')
507 except:
508 return False
509 linesout = len(kprobeevents.split('\n'))
510 linesack = len(check.split('\n'))
511 if linesack < linesout:
512 return False
513 return True
514 def fsetVal(self, val, path, mode='w'):
515 file = self.tpath+path
516 if not os.path.exists(file):
517 return False
518 try:
03bc39be 519 fp = open(file, mode, 0)
af1e45e6 520 fp.write(val)
03bc39be 521 fp.flush()
af1e45e6
TB
522 fp.close()
523 except:
524 pass
525 return True
526 def fgetVal(self, path):
527 file = self.tpath+path
528 res = ''
529 if not os.path.exists(file):
530 return res
531 try:
532 fp = open(file, 'r')
533 res = fp.read()
534 fp.close()
535 except:
536 pass
537 return res
538 def cleanupFtrace(self):
539 if(self.usecallgraph or self.usetraceevents):
540 self.fsetVal('0', 'events/kprobes/enable')
541 self.fsetVal('', 'kprobe_events')
542 def setupAllKprobes(self):
543 for name in self.tracefuncs:
544 self.defaultKprobe(name, self.tracefuncs[name])
545 for name in self.dev_tracefuncs:
546 self.defaultKprobe(name, self.dev_tracefuncs[name])
547 def isCallgraphFunc(self, name):
1ea39643 548 if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
af1e45e6 549 return True
af1e45e6
TB
550 for i in self.tracefuncs:
551 if 'func' in self.tracefuncs[i]:
1ea39643 552 f = self.tracefuncs[i]['func']
af1e45e6 553 else:
1ea39643
TB
554 f = i
555 if name == f:
556 return True
af1e45e6
TB
557 return False
558 def initFtrace(self, testing=False):
af1e45e6
TB
559 print('INITIALIZING FTRACE...')
560 # turn trace off
561 self.fsetVal('0', 'tracing_on')
562 self.cleanupFtrace()
563 # set the trace clock to global
564 self.fsetVal('global', 'trace_clock')
565 # set trace buffer to a huge value
566 self.fsetVal('nop', 'current_tracer')
567 self.fsetVal('100000', 'buffer_size_kb')
568 # go no further if this is just a status check
569 if testing:
570 return
1ea39643 571 # initialize the callgraph trace
af1e45e6
TB
572 if(self.usecallgraph):
573 # set trace type
574 self.fsetVal('function_graph', 'current_tracer')
575 self.fsetVal('', 'set_ftrace_filter')
576 # set trace format options
577 self.fsetVal('print-parent', 'trace_options')
578 self.fsetVal('funcgraph-abstime', 'trace_options')
579 self.fsetVal('funcgraph-cpu', 'trace_options')
580 self.fsetVal('funcgraph-duration', 'trace_options')
581 self.fsetVal('funcgraph-proc', 'trace_options')
582 self.fsetVal('funcgraph-tail', 'trace_options')
583 self.fsetVal('nofuncgraph-overhead', 'trace_options')
584 self.fsetVal('context-info', 'trace_options')
585 self.fsetVal('graph-time', 'trace_options')
586 self.fsetVal('0', 'max_graph_depth')
1ea39643
TB
587 cf = ['dpm_run_callback']
588 if(self.usetraceeventsonly):
589 cf += ['dpm_prepare', 'dpm_complete']
590 for fn in self.tracefuncs:
591 if 'func' in self.tracefuncs[fn]:
592 cf.append(self.tracefuncs[fn]['func'])
593 else:
594 cf.append(fn)
595 self.setFtraceFilterFunctions(cf)
596 # initialize the kprobe trace
597 elif self.usekprobes:
598 for name in self.tracefuncs:
599 self.defaultKprobe(name, self.tracefuncs[name])
600 if self.usedevsrc:
601 for name in self.dev_tracefuncs:
602 self.defaultKprobe(name, self.dev_tracefuncs[name])
03bc39be
TB
603 print('INITIALIZING KPROBES...')
604 self.addKprobes(self.verbose)
af1e45e6
TB
605 if(self.usetraceevents):
606 # turn trace events on
607 events = iter(self.traceevents)
608 for e in events:
609 self.fsetVal('1', 'events/power/'+e+'/enable')
610 # clear the trace buffer
611 self.fsetVal('', 'trace')
612 def verifyFtrace(self):
613 # files needed for any trace data
614 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
615 'trace_marker', 'trace_options', 'tracing_on']
616 # files needed for callgraph trace data
617 tp = self.tpath
618 if(self.usecallgraph):
619 files += [
620 'available_filter_functions',
621 'set_ftrace_filter',
622 'set_graph_function'
623 ]
624 for f in files:
625 if(os.path.exists(tp+f) == False):
626 return False
627 return True
628 def verifyKprobes(self):
629 # files needed for kprobes to work
630 files = ['kprobe_events', 'events']
631 tp = self.tpath
632 for f in files:
633 if(os.path.exists(tp+f) == False):
634 return False
635 return True
03bc39be 636 def colorText(self, str, color=31):
af1e45e6
TB
637 if not self.ansi:
638 return str
03bc39be 639 return '\x1B[%d;40m%s\x1B[m' % (color, str)
ee8b09cd 640
b8432c6f
TB
641sysvals = SystemValues()
642
af1e45e6
TB
643# Class: DevProps
644# Description:
645# Simple class which holds property values collected
646# for all the devices used in the timeline.
647class DevProps:
648 syspath = ''
649 altname = ''
650 async = True
651 xtraclass = ''
652 xtrainfo = ''
653 def out(self, dev):
654 return '%s,%s,%d;' % (dev, self.altname, self.async)
655 def debug(self, dev):
656 print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)
657 def altName(self, dev):
658 if not self.altname or self.altname == dev:
659 return dev
660 return '%s [%s]' % (self.altname, dev)
661 def xtraClass(self):
662 if self.xtraclass:
663 return ' '+self.xtraclass
664 if not self.async:
665 return ' sync'
666 return ''
667 def xtraInfo(self):
668 if self.xtraclass:
669 return ' '+self.xtraclass
670 if self.async:
203f1f98
TB
671 return ' async_device'
672 return ' sync_device'
af1e45e6 673
b8432c6f
TB
674# Class: DeviceNode
675# Description:
676# A container used to create a device hierachy, with a single root node
677# and a tree of child nodes. Used by Data.deviceTopology()
678class DeviceNode:
679 name = ''
680 children = 0
681 depth = 0
682 def __init__(self, nodename, nodedepth):
683 self.name = nodename
684 self.children = []
685 self.depth = nodedepth
686
687# Class: Data
688# Description:
689# The primary container for suspend/resume test data. There is one for
690# each test run. The data is organized into a cronological hierarchy:
691# Data.dmesg {
b8432c6f
TB
692# phases {
693# 10 sequential, non-overlapping phases of S/R
694# contents: times for phase start/end, order/color data for html
695# devlist {
696# device callback or action list for this phase
697# device {
698# a single device callback or generic action
699# contents: start/stop times, pid/cpu/driver info
700# parents/children, html id for timeline/callgraph
701# optionally includes an ftrace callgraph
03bc39be 702# optionally includes dev/ps data
b8432c6f
TB
703# }
704# }
705# }
706# }
707#
ee8b09cd 708class Data:
b8432c6f
TB
709 dmesg = {} # root data structure
710 phases = [] # ordered list of phases
711 start = 0.0 # test start
712 end = 0.0 # test end
713 tSuspended = 0.0 # low-level suspend start
714 tResumed = 0.0 # low-level resume start
203f1f98
TB
715 tKernSus = 0.0 # kernel level suspend start
716 tKernRes = 0.0 # kernel level resume end
b8432c6f
TB
717 tLow = 0.0 # time spent in low-level suspend (standby/freeze)
718 fwValid = False # is firmware data available
719 fwSuspend = 0 # time spent in firmware suspend
720 fwResume = 0 # time spent in firmware resume
721 dmesgtext = [] # dmesg text file in memory
203f1f98 722 pstl = 0 # process timeline
b8432c6f
TB
723 testnumber = 0
724 idstr = ''
725 html_device_id = 0
726 stamp = 0
727 outfile = ''
203f1f98 728 devpids = []
03bc39be 729 kerror = False
b8432c6f 730 def __init__(self, num):
03bc39be 731 idchar = 'abcdefghij'
203f1f98 732 self.pstl = dict()
b8432c6f
TB
733 self.testnumber = num
734 self.idstr = idchar[num]
735 self.dmesgtext = []
736 self.phases = []
737 self.dmesg = { # fixed list of 10 phases
738 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
739 'row': 0, 'color': '#CCFFCC', 'order': 0},
740 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
741 'row': 0, 'color': '#88FF88', 'order': 1},
742 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
743 'row': 0, 'color': '#00AA00', 'order': 2},
ee8b09cd 744 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
b8432c6f
TB
745 'row': 0, 'color': '#008888', 'order': 3},
746 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
747 'row': 0, 'color': '#0000FF', 'order': 4},
748 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
749 'row': 0, 'color': '#FF0000', 'order': 5},
ee8b09cd 750 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
b8432c6f 751 'row': 0, 'color': '#FF9900', 'order': 6},
ee8b09cd 752 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
b8432c6f
TB
753 'row': 0, 'color': '#FFCC00', 'order': 7},
754 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
755 'row': 0, 'color': '#FFFF88', 'order': 8},
756 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
757 'row': 0, 'color': '#FFFFCC', 'order': 9}
ee8b09cd
TB
758 }
759 self.phases = self.sortedPhases()
af1e45e6
TB
760 self.devicegroups = []
761 for phase in self.phases:
762 self.devicegroups.append([phase])
03bc39be
TB
763 self.errorinfo = {'suspend':[],'resume':[]}
764 def extractErrorInfo(self, dmesg):
765 error = ''
766 tm = 0.0
767 for i in range(len(dmesg)):
768 if 'Call Trace:' in dmesg[i]:
769 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i])
770 if not m:
771 continue
772 tm = float(m.group('ktime'))
773 if tm < self.start or tm > self.end:
774 continue
775 for j in range(i-10, i+1):
776 error += dmesg[j]
777 continue
778 if error:
779 m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
780 if m:
781 error += dmesg[i]
782 else:
783 if tm < self.tSuspended:
784 dir = 'suspend'
785 else:
786 dir = 'resume'
787 error = error.replace('<', '&lt').replace('>', '&gt')
788 vprint('kernel error found in %s at %f' % (dir, tm))
789 self.errorinfo[dir].append((tm, error))
790 self.kerror = True
791 error = ''
b8432c6f
TB
792 def setStart(self, time):
793 self.start = time
b8432c6f
TB
794 def setEnd(self, time):
795 self.end = time
b8432c6f
TB
796 def isTraceEventOutsideDeviceCalls(self, pid, time):
797 for phase in self.phases:
798 list = self.dmesg[phase]['list']
799 for dev in list:
800 d = list[dev]
801 if(d['pid'] == pid and time >= d['start'] and
af1e45e6 802 time < d['end']):
b8432c6f
TB
803 return False
804 return True
03bc39be 805 def sourcePhase(self, start):
203f1f98 806 for phase in self.phases:
203f1f98
TB
807 pend = self.dmesg[phase]['end']
808 if start <= pend:
809 return phase
810 return 'resume_complete'
811 def sourceDevice(self, phaselist, start, end, pid, type):
af1e45e6
TB
812 tgtdev = ''
813 for phase in phaselist:
b8432c6f 814 list = self.dmesg[phase]['list']
af1e45e6
TB
815 for devname in list:
816 dev = list[devname]
203f1f98
TB
817 # pid must match
818 if dev['pid'] != pid:
af1e45e6
TB
819 continue
820 devS = dev['start']
821 devE = dev['end']
203f1f98
TB
822 if type == 'device':
823 # device target event is entirely inside the source boundary
824 if(start < devS or start >= devE or end <= devS or end > devE):
825 continue
826 elif type == 'thread':
827 # thread target event will expand the source boundary
828 if start < devS:
829 dev['start'] = start
830 if end > devE:
831 dev['end'] = end
af1e45e6
TB
832 tgtdev = dev
833 break
834 return tgtdev
835 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
203f1f98
TB
836 # try to place the call in a device
837 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device')
1ea39643
TB
838 # calls with device pids that occur outside device bounds are dropped
839 # TODO: include these somehow
203f1f98
TB
840 if not tgtdev and pid in self.devpids:
841 return False
842 # try to place the call in a thread
843 if not tgtdev:
1ea39643 844 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread')
203f1f98 845 # create new thread blocks, expand as new calls are found
af1e45e6 846 if not tgtdev:
203f1f98
TB
847 if proc == '<...>':
848 threadname = 'kthread-%d' % (pid)
af1e45e6 849 else:
203f1f98 850 threadname = '%s-%d' % (proc, pid)
03bc39be 851 tgtphase = self.sourcePhase(start)
203f1f98
TB
852 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
853 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
854 # this should not happen
855 if not tgtdev:
856 vprint('[%f - %f] %s-%d %s %s %s' % \
857 (start, end, proc, pid, kprobename, cdata, rdata))
af1e45e6 858 return False
203f1f98 859 # place the call data inside the src element of the tgtdev
af1e45e6
TB
860 if('src' not in tgtdev):
861 tgtdev['src'] = []
03bc39be 862 dtf = sysvals.dev_tracefuncs
203f1f98 863 ubiquitous = False
03bc39be 864 if kprobename in dtf and 'ub' in dtf[kprobename]:
203f1f98 865 ubiquitous = True
af1e45e6
TB
866 title = cdata+' '+rdata
867 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
868 m = re.match(mstr, title)
869 if m:
870 c = m.group('caller')
871 a = m.group('args').strip()
872 r = m.group('ret')
873 if len(r) > 6:
874 r = ''
875 else:
876 r = 'ret=%s ' % r
03bc39be 877 if ubiquitous and c in dtf and 'ub' in dtf[c]:
203f1f98 878 return False
1ea39643
TB
879 color = sysvals.kprobeColor(kprobename)
880 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
af1e45e6
TB
881 tgtdev['src'].append(e)
882 return True
203f1f98
TB
883 def overflowDevices(self):
884 # get a list of devices that extend beyond the end of this test run
885 devlist = []
886 for phase in self.phases:
887 list = self.dmesg[phase]['list']
888 for devname in list:
889 dev = list[devname]
890 if dev['end'] > self.end:
891 devlist.append(dev)
892 return devlist
893 def mergeOverlapDevices(self, devlist):
894 # merge any devices that overlap devlist
895 for dev in devlist:
896 devname = dev['name']
897 for phase in self.phases:
898 list = self.dmesg[phase]['list']
899 if devname not in list:
900 continue
901 tdev = list[devname]
902 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
903 if o <= 0:
904 continue
905 dev['end'] = tdev['end']
906 if 'src' not in dev or 'src' not in tdev:
907 continue
908 dev['src'] += tdev['src']
909 del list[devname]
1ea39643
TB
910 def usurpTouchingThread(self, name, dev):
911 # the caller test has priority of this thread, give it to him
912 for phase in self.phases:
913 list = self.dmesg[phase]['list']
914 if name in list:
915 tdev = list[name]
916 if tdev['start'] - dev['end'] < 0.1:
917 dev['end'] = tdev['end']
918 if 'src' not in dev:
919 dev['src'] = []
920 if 'src' in tdev:
921 dev['src'] += tdev['src']
922 del list[name]
923 break
924 def stitchTouchingThreads(self, testlist):
925 # merge any threads between tests that touch
926 for phase in self.phases:
927 list = self.dmesg[phase]['list']
928 for devname in list:
929 dev = list[devname]
930 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
931 continue
932 for data in testlist:
933 data.usurpTouchingThread(devname, dev)
203f1f98
TB
934 def optimizeDevSrc(self):
935 # merge any src call loops to reduce timeline size
936 for phase in self.phases:
937 list = self.dmesg[phase]['list']
938 for dev in list:
939 if 'src' not in list[dev]:
940 continue
941 src = list[dev]['src']
942 p = 0
943 for e in sorted(src, key=lambda event: event.time):
944 if not p or not e.repeat(p):
945 p = e
946 continue
947 # e is another iteration of p, move it into p
948 p.end = e.end
949 p.length = p.end - p.time
950 p.count += 1
951 src.remove(e)
b8432c6f
TB
952 def trimTimeVal(self, t, t0, dT, left):
953 if left:
954 if(t > t0):
955 if(t - dT < t0):
956 return t0
957 return t - dT
958 else:
959 return t
960 else:
961 if(t < t0 + dT):
962 if(t > t0):
963 return t0 + dT
964 return t + dT
965 else:
966 return t
967 def trimTime(self, t0, dT, left):
968 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
969 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
970 self.start = self.trimTimeVal(self.start, t0, dT, left)
03bc39be
TB
971 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
972 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
b8432c6f 973 self.end = self.trimTimeVal(self.end, t0, dT, left)
ee8b09cd 974 for phase in self.phases:
ee8b09cd 975 p = self.dmesg[phase]
b8432c6f
TB
976 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
977 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
ee8b09cd
TB
978 list = p['list']
979 for name in list:
980 d = list[name]
b8432c6f
TB
981 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
982 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
ee8b09cd
TB
983 if('ftrace' in d):
984 cg = d['ftrace']
b8432c6f
TB
985 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
986 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
ee8b09cd 987 for line in cg.list:
b8432c6f 988 line.time = self.trimTimeVal(line.time, t0, dT, left)
af1e45e6
TB
989 if('src' in d):
990 for e in d['src']:
b8432c6f
TB
991 e.time = self.trimTimeVal(e.time, t0, dT, left)
992 def normalizeTime(self, tZero):
af1e45e6 993 # trim out any standby or freeze clock time
b8432c6f
TB
994 if(self.tSuspended != self.tResumed):
995 if(self.tResumed > tZero):
996 self.trimTime(self.tSuspended, \
997 self.tResumed-self.tSuspended, True)
998 else:
999 self.trimTime(self.tSuspended, \
1000 self.tResumed-self.tSuspended, False)
b8432c6f
TB
1001 def setPhase(self, phase, ktime, isbegin):
1002 if(isbegin):
1003 self.dmesg[phase]['start'] = ktime
1004 else:
1005 self.dmesg[phase]['end'] = ktime
ee8b09cd
TB
1006 def dmesgSortVal(self, phase):
1007 return self.dmesg[phase]['order']
1008 def sortedPhases(self):
1009 return sorted(self.dmesg, key=self.dmesgSortVal)
1010 def sortedDevices(self, phase):
1011 list = self.dmesg[phase]['list']
1012 slist = []
1013 tmp = dict()
1014 for devname in list:
1015 dev = list[devname]
1016 tmp[dev['start']] = devname
1017 for t in sorted(tmp):
1018 slist.append(tmp[t])
1019 return slist
03bc39be 1020 def fixupInitcalls(self, phase):
ee8b09cd
TB
1021 # if any calls never returned, clip them at system resume end
1022 phaselist = self.dmesg[phase]['list']
1023 for devname in phaselist:
1024 dev = phaselist[devname]
1025 if(dev['end'] < 0):
af1e45e6
TB
1026 for p in self.phases:
1027 if self.dmesg[p]['end'] > dev['start']:
1028 dev['end'] = self.dmesg[p]['end']
1029 break
b8432c6f
TB
1030 vprint('%s (%s): callback didnt return' % (devname, phase))
1031 def deviceFilter(self, devicefilter):
b8432c6f
TB
1032 for phase in self.phases:
1033 list = self.dmesg[phase]['list']
1034 rmlist = []
1035 for name in list:
1ea39643
TB
1036 keep = False
1037 for filter in devicefilter:
1038 if filter in name or \
1039 ('drv' in list[name] and filter in list[name]['drv']):
1040 keep = True
1041 if not keep:
b8432c6f
TB
1042 rmlist.append(name)
1043 for name in rmlist:
1044 del list[name]
ee8b09cd
TB
1045 def fixupInitcallsThatDidntReturn(self):
1046 # if any calls never returned, clip them at system resume end
1047 for phase in self.phases:
03bc39be 1048 self.fixupInitcalls(phase)
af1e45e6
TB
1049 def phaseOverlap(self, phases):
1050 rmgroups = []
1051 newgroup = []
1052 for group in self.devicegroups:
1053 for phase in phases:
1054 if phase not in group:
1055 continue
1056 for p in group:
1057 if p not in newgroup:
1058 newgroup.append(p)
1059 if group not in rmgroups:
1060 rmgroups.append(group)
1061 for group in rmgroups:
1062 self.devicegroups.remove(group)
1063 self.devicegroups.append(newgroup)
1064 def newActionGlobal(self, name, start, end, pid=-1, color=''):
203f1f98
TB
1065 # which phase is this device callback or action in
1066 targetphase = 'none'
af1e45e6 1067 htmlclass = ''
b8432c6f 1068 overlap = 0.0
af1e45e6 1069 phases = []
b8432c6f
TB
1070 for phase in self.phases:
1071 pstart = self.dmesg[phase]['start']
1072 pend = self.dmesg[phase]['end']
203f1f98 1073 # see if the action overlaps this phase
b8432c6f 1074 o = max(0, min(end, pend) - max(start, pstart))
af1e45e6
TB
1075 if o > 0:
1076 phases.append(phase)
203f1f98 1077 # set the target phase to the one that overlaps most
af1e45e6
TB
1078 if o > overlap:
1079 if overlap > 0 and phase == 'post_resume':
1080 continue
b8432c6f
TB
1081 targetphase = phase
1082 overlap = o
1ea39643 1083 # if no target phase was found, pin it to the edge
203f1f98 1084 if targetphase == 'none':
1ea39643
TB
1085 p0start = self.dmesg[self.phases[0]]['start']
1086 if start <= p0start:
203f1f98 1087 targetphase = self.phases[0]
1ea39643 1088 else:
203f1f98 1089 targetphase = self.phases[-1]
af1e45e6
TB
1090 if pid == -2:
1091 htmlclass = ' bg'
203f1f98
TB
1092 elif pid == -3:
1093 htmlclass = ' ps'
af1e45e6
TB
1094 if len(phases) > 1:
1095 htmlclass = ' bg'
1096 self.phaseOverlap(phases)
b8432c6f 1097 if targetphase in self.phases:
af1e45e6
TB
1098 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1099 return (targetphase, newname)
b8432c6f 1100 return False
af1e45e6 1101 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
b8432c6f
TB
1102 # new device callback for a specific phase
1103 self.html_device_id += 1
1104 devid = '%s%d' % (self.idstr, self.html_device_id)
ee8b09cd
TB
1105 list = self.dmesg[phase]['list']
1106 length = -1.0
1107 if(start >= 0 and end >= 0):
1108 length = end - start
af1e45e6
TB
1109 if pid == -2:
1110 i = 2
1111 origname = name
1112 while(name in list):
1113 name = '%s[%d]' % (origname, i)
1114 i += 1
203f1f98
TB
1115 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,
1116 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }
af1e45e6
TB
1117 if htmlclass:
1118 list[name]['htmlclass'] = htmlclass
1119 if color:
1120 list[name]['color'] = color
1121 return name
b8432c6f 1122 def deviceChildren(self, devname, phase):
ee8b09cd 1123 devlist = []
b8432c6f
TB
1124 list = self.dmesg[phase]['list']
1125 for child in list:
1126 if(list[child]['par'] == devname):
1127 devlist.append(child)
1128 return devlist
b8432c6f 1129 def printDetails(self):
203f1f98 1130 vprint('Timeline Details:')
b8432c6f 1131 vprint(' test start: %f' % self.start)
203f1f98 1132 vprint('kernel suspend start: %f' % self.tKernSus)
b8432c6f
TB
1133 for phase in self.phases:
1134 dc = len(self.dmesg[phase]['list'])
1135 vprint(' %16s: %f - %f (%d devices)' % (phase, \
1136 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
203f1f98 1137 vprint(' kernel resume end: %f' % self.tKernRes)
b8432c6f 1138 vprint(' test end: %f' % self.end)
af1e45e6
TB
1139 def deviceChildrenAllPhases(self, devname):
1140 devlist = []
1141 for phase in self.phases:
1142 list = self.deviceChildren(devname, phase)
1143 for dev in list:
1144 if dev not in devlist:
1145 devlist.append(dev)
1146 return devlist
b8432c6f
TB
1147 def masterTopology(self, name, list, depth):
1148 node = DeviceNode(name, depth)
1149 for cname in list:
af1e45e6
TB
1150 # avoid recursions
1151 if name == cname:
1152 continue
1153 clist = self.deviceChildrenAllPhases(cname)
b8432c6f
TB
1154 cnode = self.masterTopology(cname, clist, depth+1)
1155 node.children.append(cnode)
1156 return node
1157 def printTopology(self, node):
1158 html = ''
1159 if node.name:
1160 info = ''
1161 drv = ''
1162 for phase in self.phases:
1163 list = self.dmesg[phase]['list']
1164 if node.name in list:
1165 s = list[node.name]['start']
1166 e = list[node.name]['end']
1167 if list[node.name]['drv']:
1168 drv = ' {'+list[node.name]['drv']+'}'
1169 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
1170 html += '<li><b>'+node.name+drv+'</b>'
1171 if info:
1172 html += '<ul>'+info+'</ul>'
1173 html += '</li>'
1174 if len(node.children) > 0:
1175 html += '<ul>'
1176 for cnode in node.children:
1177 html += self.printTopology(cnode)
1178 html += '</ul>'
1179 return html
1180 def rootDeviceList(self):
1181 # list of devices graphed
1182 real = []
1183 for phase in self.dmesg:
1184 list = self.dmesg[phase]['list']
1185 for dev in list:
1186 if list[dev]['pid'] >= 0 and dev not in real:
1187 real.append(dev)
1188 # list of top-most root devices
1189 rootlist = []
1190 for phase in self.dmesg:
1191 list = self.dmesg[phase]['list']
1192 for dev in list:
1193 pdev = list[dev]['par']
af1e45e6
TB
1194 pid = list[dev]['pid']
1195 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
b8432c6f
TB
1196 continue
1197 if pdev and pdev not in real and pdev not in rootlist:
1198 rootlist.append(pdev)
1199 return rootlist
1200 def deviceTopology(self):
1201 rootlist = self.rootDeviceList()
1202 master = self.masterTopology('', rootlist, 0)
1203 return self.printTopology(master)
af1e45e6
TB
1204 def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
1205 # only select devices that will actually show up in html
1206 self.tdevlist = dict()
1207 for phase in self.dmesg:
1208 devlist = []
1209 list = self.dmesg[phase]['list']
1210 for dev in list:
1211 length = (list[dev]['end'] - list[dev]['start']) * 1000
1212 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
1213 if width != '0.000000' and length >= mindevlen:
1214 devlist.append(dev)
1215 self.tdevlist[phase] = devlist
1ea39643
TB
1216 def addHorizontalDivider(self, devname, devend):
1217 phase = 'suspend_prepare'
1218 self.newAction(phase, devname, -2, '', \
1219 self.start, devend, '', ' sec', '')
1220 if phase not in self.tdevlist:
1221 self.tdevlist[phase] = []
1222 self.tdevlist[phase].append(devname)
1223 d = DevItem(0, phase, self.dmesg[phase]['list'][devname])
1224 return d
203f1f98
TB
1225 def addProcessUsageEvent(self, name, times):
1226 # get the start and end times for this process
1227 maxC = 0
1228 tlast = 0
1229 start = -1
1230 end = -1
1231 for t in sorted(times):
1232 if tlast == 0:
1233 tlast = t
1234 continue
1235 if name in self.pstl[t]:
1236 if start == -1 or tlast < start:
1237 start = tlast
1238 if end == -1 or t > end:
1239 end = t
1240 tlast = t
1241 if start == -1 or end == -1:
1242 return 0
1243 # add a new action for this process and get the object
1244 out = self.newActionGlobal(name, start, end, -3)
1245 if not out:
1246 return 0
1247 phase, devname = out
1248 dev = self.dmesg[phase]['list'][devname]
1249 # get the cpu exec data
1250 tlast = 0
1251 clast = 0
1252 cpuexec = dict()
1253 for t in sorted(times):
1254 if tlast == 0 or t <= start or t > end:
1255 tlast = t
1256 continue
1257 list = self.pstl[t]
1258 c = 0
1259 if name in list:
1260 c = list[name]
1261 if c > maxC:
1262 maxC = c
1263 if c != clast:
1264 key = (tlast, t)
1265 cpuexec[key] = c
1266 tlast = t
1267 clast = c
1268 dev['cpuexec'] = cpuexec
1269 return maxC
1270 def createProcessUsageEvents(self):
1271 # get an array of process names
1272 proclist = []
1273 for t in self.pstl:
1274 pslist = self.pstl[t]
1275 for ps in pslist:
1276 if ps not in proclist:
1277 proclist.append(ps)
1278 # get a list of data points for suspend and resume
1279 tsus = []
1280 tres = []
1281 for t in sorted(self.pstl):
1282 if t < self.tSuspended:
1283 tsus.append(t)
1284 else:
1285 tres.append(t)
1286 # process the events for suspend and resume
1287 if len(proclist) > 0:
1288 vprint('Process Execution:')
1289 for ps in proclist:
1290 c = self.addProcessUsageEvent(ps, tsus)
1291 if c > 0:
1292 vprint('%25s (sus): %d' % (ps, c))
1293 c = self.addProcessUsageEvent(ps, tres)
1294 if c > 0:
1295 vprint('%25s (res): %d' % (ps, c))
1296
1297# Class: DevFunction
b8432c6f 1298# Description:
203f1f98
TB
1299# A container for kprobe function data we want in the dev timeline
1300class DevFunction:
af1e45e6 1301 row = 0
203f1f98 1302 count = 1
1ea39643 1303 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
203f1f98
TB
1304 self.name = name
1305 self.args = args
1306 self.caller = caller
1307 self.ret = ret
1308 self.time = start
1309 self.length = end - start
1310 self.end = end
1311 self.ubiquitous = u
1312 self.proc = proc
1313 self.pid = pid
1ea39643 1314 self.color = color
203f1f98
TB
1315 def title(self):
1316 cnt = ''
1317 if self.count > 1:
1318 cnt = '(x%d)' % self.count
1319 l = '%0.3fms' % (self.length * 1000)
1320 if self.ubiquitous:
1ea39643
TB
1321 title = '%s(%s)%s <- %s, %s(%s)' % \
1322 (self.name, self.args, cnt, self.caller, self.ret, l)
203f1f98
TB
1323 else:
1324 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
1ea39643 1325 return title.replace('"', '')
203f1f98
TB
1326 def text(self):
1327 if self.count > 1:
1328 text = '%s(x%d)' % (self.name, self.count)
1329 else:
1330 text = self.name
1331 return text
1332 def repeat(self, tgt):
1ea39643 1333 # is the tgt call just a repeat of this call (e.g. are we in a loop)
203f1f98 1334 dt = self.time - tgt.end
1ea39643 1335 # only combine calls if -all- attributes are identical
203f1f98
TB
1336 if tgt.caller == self.caller and \
1337 tgt.name == self.name and tgt.args == self.args and \
1338 tgt.proc == self.proc and tgt.pid == self.pid and \
1ea39643
TB
1339 tgt.ret == self.ret and dt >= 0 and \
1340 dt <= sysvals.callloopmaxgap and \
1341 self.length < sysvals.callloopmaxlen:
203f1f98
TB
1342 return True
1343 return False
b8432c6f
TB
1344
1345# Class: FTraceLine
1346# Description:
1347# A container for a single line of ftrace data. There are six basic types:
1348# callgraph line:
1349# call: " dpm_run_callback() {"
1350# return: " }"
1351# leaf: " dpm_run_callback();"
1352# trace event:
1353# tracing_mark_write: SUSPEND START or RESUME COMPLETE
1354# suspend_resume: phase or custom exec block data
1355# device_pm_callback: device callback info
ee8b09cd
TB
1356class FTraceLine:
1357 time = 0.0
1358 length = 0.0
1359 fcall = False
1360 freturn = False
1361 fevent = False
af1e45e6 1362 fkprobe = False
ee8b09cd 1363 depth = 0
b8432c6f
TB
1364 name = ''
1365 type = ''
af1e45e6 1366 def __init__(self, t, m='', d=''):
ee8b09cd 1367 self.time = float(t)
af1e45e6
TB
1368 if not m and not d:
1369 return
b8432c6f
TB
1370 # is this a trace event
1371 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
1372 if(d == 'traceevent'):
1373 # nop format trace event
1374 msg = m
1375 else:
1376 # function_graph format trace event
1377 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
1378 msg = em.group('msg')
1379
1380 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
1381 if(emm):
1382 self.name = emm.group('msg')
1383 self.type = emm.group('call')
1384 else:
1385 self.name = msg
af1e45e6
TB
1386 km = re.match('^(?P<n>.*)_cal$', self.type)
1387 if km:
1388 self.fcall = True
1389 self.fkprobe = True
1390 self.type = km.group('n')
1391 return
1392 km = re.match('^(?P<n>.*)_ret$', self.type)
1393 if km:
1394 self.freturn = True
1395 self.fkprobe = True
1396 self.type = km.group('n')
1397 return
ee8b09cd
TB
1398 self.fevent = True
1399 return
1400 # convert the duration to seconds
1401 if(d):
1402 self.length = float(d)/1000000
1403 # the indentation determines the depth
b8432c6f 1404 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
ee8b09cd
TB
1405 if(not match):
1406 return
1407 self.depth = self.getDepth(match.group('d'))
1408 m = match.group('o')
1409 # function return
1410 if(m[0] == '}'):
1411 self.freturn = True
1412 if(len(m) > 1):
1413 # includes comment with function name
b8432c6f 1414 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
ee8b09cd 1415 if(match):
af1e45e6 1416 self.name = match.group('n').strip()
ee8b09cd
TB
1417 # function call
1418 else:
1419 self.fcall = True
1420 # function call with children
1421 if(m[-1] == '{'):
b8432c6f 1422 match = re.match('^(?P<n>.*) *\(.*', m)
ee8b09cd 1423 if(match):
af1e45e6 1424 self.name = match.group('n').strip()
ee8b09cd
TB
1425 # function call with no children (leaf)
1426 elif(m[-1] == ';'):
1427 self.freturn = True
b8432c6f 1428 match = re.match('^(?P<n>.*) *\(.*', m)
ee8b09cd 1429 if(match):
af1e45e6 1430 self.name = match.group('n').strip()
ee8b09cd
TB
1431 # something else (possibly a trace marker)
1432 else:
1433 self.name = m
1434 def getDepth(self, str):
1435 return len(str)/2
af1e45e6 1436 def debugPrint(self, dev=''):
b8432c6f
TB
1437 if(self.freturn and self.fcall):
1438 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
1439 self.depth, self.name, self.length*1000000))
1440 elif(self.freturn):
1441 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
1442 self.depth, self.name, self.length*1000000))
1443 else:
1444 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
1445 self.depth, self.name, self.length*1000000))
af1e45e6 1446 def startMarker(self):
af1e45e6
TB
1447 # Is this the starting line of a suspend?
1448 if not self.fevent:
1449 return False
1450 if sysvals.usetracemarkers:
1451 if(self.name == 'SUSPEND START'):
1452 return True
1453 return False
1454 else:
1455 if(self.type == 'suspend_resume' and
1456 re.match('suspend_enter\[.*\] begin', self.name)):
1457 return True
1458 return False
1459 def endMarker(self):
1460 # Is this the ending line of a resume?
1461 if not self.fevent:
1462 return False
1463 if sysvals.usetracemarkers:
1464 if(self.name == 'RESUME COMPLETE'):
1465 return True
1466 return False
1467 else:
1468 if(self.type == 'suspend_resume' and
1469 re.match('thaw_processes\[.*\] end', self.name)):
1470 return True
1471 return False
ee8b09cd 1472
b8432c6f
TB
1473# Class: FTraceCallGraph
1474# Description:
1475# A container for the ftrace callgraph of a single recursive function.
1476# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
1477# Each instance is tied to a single device in a single phase, and is
1478# comprised of an ordered list of FTraceLine objects
ee8b09cd
TB
1479class FTraceCallGraph:
1480 start = -1.0
1481 end = -1.0
1482 list = []
1483 invalid = False
1484 depth = 0
af1e45e6
TB
1485 pid = 0
1486 def __init__(self, pid):
ee8b09cd
TB
1487 self.start = -1.0
1488 self.end = -1.0
1489 self.list = []
1490 self.depth = 0
af1e45e6
TB
1491 self.pid = pid
1492 def addLine(self, line, debug=False):
1493 # if this is already invalid, just leave
1494 if(self.invalid):
1495 return False
1496 # invalidate on too much data or bad depth
1497 if(len(self.list) >= 1000000 or self.depth < 0):
1498 self.invalidate(line)
1499 return False
1500 # compare current depth with this lines pre-call depth
1501 prelinedep = line.depth
1502 if(line.freturn and not line.fcall):
1503 prelinedep += 1
1504 last = 0
1505 lasttime = line.time
1506 virtualfname = 'execution_misalignment'
1507 if len(self.list) > 0:
1508 last = self.list[-1]
1509 lasttime = last.time
1510 # handle low misalignments by inserting returns
1511 if prelinedep < self.depth:
1512 if debug and last:
1513 print '-------- task %d --------' % self.pid
1514 last.debugPrint()
1515 idx = 0
1516 # add return calls to get the depth down
1517 while prelinedep < self.depth:
1518 if debug:
1519 print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
1520 self.depth -= 1
1521 if idx == 0 and last and last.fcall and not last.freturn:
1522 # special case, turn last call into a leaf
1523 last.depth = self.depth
1524 last.freturn = True
1525 last.length = line.time - last.time
1526 if debug:
1527 last.debugPrint()
1528 else:
1529 vline = FTraceLine(lasttime)
1530 vline.depth = self.depth
1531 vline.name = virtualfname
1532 vline.freturn = True
1533 self.list.append(vline)
1534 if debug:
1535 vline.debugPrint()
1536 idx += 1
1537 if debug:
1538 line.debugPrint()
1539 print ''
1540 # handle high misalignments by inserting calls
1541 elif prelinedep > self.depth:
1542 if debug and last:
1543 print '-------- task %d --------' % self.pid
1544 last.debugPrint()
1545 idx = 0
1546 # add calls to get the depth up
1547 while prelinedep > self.depth:
1548 if debug:
1549 print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
1550 if idx == 0 and line.freturn and not line.fcall:
1551 # special case, turn this return into a leaf
1552 line.fcall = True
1553 prelinedep -= 1
1554 else:
1555 vline = FTraceLine(lasttime)
1556 vline.depth = self.depth
1557 vline.name = virtualfname
1558 vline.fcall = True
1559 if debug:
1560 vline.debugPrint()
1561 self.list.append(vline)
1562 self.depth += 1
1563 if not last:
1564 self.start = vline.time
1565 idx += 1
1566 if debug:
1567 line.debugPrint()
1568 print ''
1569 # process the call and set the new depth
ee8b09cd 1570 if(line.fcall and not line.freturn):
ee8b09cd
TB
1571 self.depth += 1
1572 elif(line.freturn and not line.fcall):
1573 self.depth -= 1
af1e45e6
TB
1574 if len(self.list) < 1:
1575 self.start = line.time
1576 self.list.append(line)
ee8b09cd 1577 if(line.depth == 0 and line.freturn):
b8432c6f
TB
1578 if(self.start < 0):
1579 self.start = line.time
ee8b09cd 1580 self.end = line.time
af1e45e6
TB
1581 if line.fcall:
1582 self.end += line.length
1583 if self.list[0].name == virtualfname:
1584 self.invalid = True
ee8b09cd 1585 return True
ee8b09cd 1586 return False
af1e45e6
TB
1587 def invalidate(self, line):
1588 if(len(self.list) > 0):
1589 first = self.list[0]
1590 self.list = []
1591 self.list.append(first)
1592 self.invalid = True
1593 id = 'task %s' % (self.pid)
1594 window = '(%f - %f)' % (self.start, line.time)
1595 if(self.depth < 0):
1596 vprint('Too much data for '+id+\
1597 ' (buffer overflow), ignoring this callback')
1598 else:
1599 vprint('Too much data for '+id+\
1600 ' '+window+', ignoring this callback')
b8432c6f 1601 def slice(self, t0, tN):
af1e45e6 1602 minicg = FTraceCallGraph(0)
b8432c6f
TB
1603 count = -1
1604 firstdepth = 0
1605 for l in self.list:
1606 if(l.time < t0 or l.time > tN):
1607 continue
1608 if(count < 0):
1609 if(not l.fcall or l.name == 'dev_driver_string'):
1610 continue
1611 firstdepth = l.depth
1612 count = 0
1613 l.depth -= firstdepth
af1e45e6 1614 minicg.addLine(l)
b8432c6f
TB
1615 if((count == 0 and l.freturn and l.fcall) or
1616 (count > 0 and l.depth <= 0)):
1617 break
1618 count += 1
1619 return minicg
af1e45e6
TB
1620 def repair(self, enddepth):
1621 # bring the depth back to 0 with additional returns
1622 fixed = False
1623 last = self.list[-1]
1624 for i in reversed(range(enddepth)):
1625 t = FTraceLine(last.time)
1626 t.depth = i
1627 t.freturn = True
1628 fixed = self.addLine(t)
1629 if fixed:
1630 self.end = last.time
1631 return True
1632 return False
1633 def postProcess(self, debug=False):
ee8b09cd
TB
1634 stack = dict()
1635 cnt = 0
1636 for l in self.list:
1637 if(l.fcall and not l.freturn):
1638 stack[l.depth] = l
1639 cnt += 1
1640 elif(l.freturn and not l.fcall):
b8432c6f 1641 if(l.depth not in stack):
af1e45e6
TB
1642 if debug:
1643 print 'Post Process Error: Depth missing'
1644 l.debugPrint()
ee8b09cd 1645 return False
af1e45e6 1646 # transfer total time from return line to call line
ee8b09cd 1647 stack[l.depth].length = l.length
af1e45e6 1648 stack.pop(l.depth)
ee8b09cd
TB
1649 l.length = 0
1650 cnt -= 1
1651 if(cnt == 0):
af1e45e6 1652 # trace caught the whole call tree
ee8b09cd 1653 return True
af1e45e6
TB
1654 elif(cnt < 0):
1655 if debug:
1656 print 'Post Process Error: Depth is less than 0'
1657 return False
1658 # trace ended before call tree finished
1659 return self.repair(cnt)
1660 def deviceMatch(self, pid, data):
1661 found = False
1662 # add the callgraph data to the device hierarchy
1663 borderphase = {
1664 'dpm_prepare': 'suspend_prepare',
1665 'dpm_complete': 'resume_complete'
1666 }
1667 if(self.list[0].name in borderphase):
1668 p = borderphase[self.list[0].name]
1669 list = data.dmesg[p]['list']
1670 for devname in list:
1671 dev = list[devname]
1672 if(pid == dev['pid'] and
1673 self.start <= dev['start'] and
1674 self.end >= dev['end']):
1675 dev['ftrace'] = self.slice(dev['start'], dev['end'])
1676 found = True
1677 return found
1678 for p in data.phases:
1679 if(data.dmesg[p]['start'] <= self.start and
1680 self.start <= data.dmesg[p]['end']):
1681 list = data.dmesg[p]['list']
1682 for devname in list:
1683 dev = list[devname]
1684 if(pid == dev['pid'] and
1685 self.start <= dev['start'] and
1686 self.end >= dev['end']):
1687 dev['ftrace'] = self
1688 found = True
1689 break
1690 break
1691 return found
1692 def newActionFromFunction(self, data):
1693 name = self.list[0].name
1694 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
1695 return
1696 fs = self.start
1697 fe = self.end
1698 if fs < data.start or fe > data.end:
1699 return
1700 phase = ''
1701 for p in data.phases:
1702 if(data.dmesg[p]['start'] <= self.start and
1703 self.start < data.dmesg[p]['end']):
1704 phase = p
1705 break
1706 if not phase:
1707 return
1708 out = data.newActionGlobal(name, fs, fe, -2)
1709 if out:
1710 phase, myname = out
1711 data.dmesg[phase]['list'][myname]['ftrace'] = self
1712 def debugPrint(self):
1713 print('[%f - %f] %s (%d)') % (self.start, self.end, self.list[0].name, self.pid)
1714 for l in self.list:
1715 if(l.freturn and l.fcall):
1716 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
1717 l.depth, l.name, l.length*1000000))
1718 elif(l.freturn):
1719 print('%f (%02d): %s} (%.3f us)' % (l.time, \
1720 l.depth, l.name, l.length*1000000))
1721 else:
1722 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
1723 l.depth, l.name, l.length*1000000))
1724 print(' ')
ee8b09cd 1725
203f1f98
TB
1726class DevItem:
1727 def __init__(self, test, phase, dev):
1728 self.test = test
1729 self.phase = phase
1730 self.dev = dev
1ea39643
TB
1731 def isa(self, cls):
1732 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:
1733 return True
1734 return False
203f1f98 1735
b8432c6f
TB
1736# Class: Timeline
1737# Description:
af1e45e6
TB
1738# A container for a device timeline which calculates
1739# all the html properties to display it correctly
ee8b09cd
TB
1740class Timeline:
1741 html = {}
af1e45e6
TB
1742 height = 0 # total timeline height
1743 scaleH = 20 # timescale (top) row height
1744 rowH = 30 # device row height
1745 bodyH = 0 # body height
1746 rows = 0 # total timeline rows
203f1f98 1747 rowlines = dict()
af1e45e6 1748 rowheight = dict()
03bc39be 1749 def __init__(self, rowheight, scaleheight):
af1e45e6 1750 self.rowH = rowheight
03bc39be 1751 self.scaleH = scaleheight
ee8b09cd 1752 self.html = {
af1e45e6 1753 'header': '',
b8432c6f
TB
1754 'timeline': '',
1755 'legend': '',
ee8b09cd 1756 }
af1e45e6
TB
1757 # Function: getDeviceRows
1758 # Description:
1759 # determine how may rows the device funcs will take
1760 # Arguments:
1761 # rawlist: the list of devices/actions for a single phase
1762 # Output:
1763 # The total number of rows needed to display this phase of the timeline
1764 def getDeviceRows(self, rawlist):
1765 # clear all rows and set them to undefined
203f1f98 1766 sortdict = dict()
af1e45e6
TB
1767 for item in rawlist:
1768 item.row = -1
203f1f98
TB
1769 sortdict[item] = item.length
1770 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
1771 remaining = len(sortlist)
af1e45e6
TB
1772 rowdata = dict()
1773 row = 1
1774 # try to pack each row with as many ranges as possible
1775 while(remaining > 0):
1776 if(row not in rowdata):
1777 rowdata[row] = []
203f1f98 1778 for i in sortlist:
af1e45e6
TB
1779 if(i.row >= 0):
1780 continue
1781 s = i.time
1782 e = i.time + i.length
1783 valid = True
1784 for ritem in rowdata[row]:
1785 rs = ritem.time
1786 re = ritem.time + ritem.length
1787 if(not (((s <= rs) and (e <= rs)) or
1788 ((s >= re) and (e >= re)))):
1789 valid = False
1790 break
1791 if(valid):
1792 rowdata[row].append(i)
1793 i.row = row
1794 remaining -= 1
1795 row += 1
1796 return row
1797 # Function: getPhaseRows
1798 # Description:
1799 # Organize the timeline entries into the smallest
1800 # number of rows possible, with no entry overlapping
1801 # Arguments:
203f1f98 1802 # devlist: the list of devices/actions in a group of contiguous phases
af1e45e6
TB
1803 # Output:
1804 # The total number of rows needed to display this phase of the timeline
1ea39643 1805 def getPhaseRows(self, devlist, row=0):
af1e45e6
TB
1806 # clear all rows and set them to undefined
1807 remaining = len(devlist)
1808 rowdata = dict()
203f1f98 1809 sortdict = dict()
af1e45e6 1810 myphases = []
203f1f98 1811 # initialize all device rows to -1 and calculate devrows
af1e45e6 1812 for item in devlist:
203f1f98
TB
1813 dev = item.dev
1814 tp = (item.test, item.phase)
1815 if tp not in myphases:
1816 myphases.append(tp)
af1e45e6 1817 dev['row'] = -1
203f1f98
TB
1818 # sort by length 1st, then name 2nd
1819 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])
af1e45e6
TB
1820 if 'src' in dev:
1821 dev['devrows'] = self.getDeviceRows(dev['src'])
203f1f98
TB
1822 # sort the devlist by length so that large items graph on top
1823 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
af1e45e6 1824 orderedlist = []
203f1f98
TB
1825 for item in sortlist:
1826 if item.dev['pid'] == -2:
af1e45e6 1827 orderedlist.append(item)
203f1f98 1828 for item in sortlist:
af1e45e6
TB
1829 if item not in orderedlist:
1830 orderedlist.append(item)
203f1f98 1831 # try to pack each row with as many devices as possible
af1e45e6
TB
1832 while(remaining > 0):
1833 rowheight = 1
1834 if(row not in rowdata):
1835 rowdata[row] = []
1836 for item in orderedlist:
203f1f98 1837 dev = item.dev
af1e45e6
TB
1838 if(dev['row'] < 0):
1839 s = dev['start']
1840 e = dev['end']
1841 valid = True
1842 for ritem in rowdata[row]:
203f1f98
TB
1843 rs = ritem.dev['start']
1844 re = ritem.dev['end']
af1e45e6
TB
1845 if(not (((s <= rs) and (e <= rs)) or
1846 ((s >= re) and (e >= re)))):
1847 valid = False
1848 break
1849 if(valid):
203f1f98 1850 rowdata[row].append(item)
af1e45e6
TB
1851 dev['row'] = row
1852 remaining -= 1
1853 if 'devrows' in dev and dev['devrows'] > rowheight:
1854 rowheight = dev['devrows']
203f1f98
TB
1855 for t, p in myphases:
1856 if t not in self.rowlines or t not in self.rowheight:
1857 self.rowlines[t] = dict()
1858 self.rowheight[t] = dict()
1859 if p not in self.rowlines[t] or p not in self.rowheight[t]:
1860 self.rowlines[t][p] = dict()
1861 self.rowheight[t][p] = dict()
1ea39643
TB
1862 rh = self.rowH
1863 # section headers should use a different row height
1864 if len(rowdata[row]) == 1 and \
1865 'htmlclass' in rowdata[row][0].dev and \
1866 'sec' in rowdata[row][0].dev['htmlclass']:
1867 rh = 15
203f1f98 1868 self.rowlines[t][p][row] = rowheight
1ea39643 1869 self.rowheight[t][p][row] = rowheight * rh
af1e45e6
TB
1870 row += 1
1871 if(row > self.rows):
1872 self.rows = int(row)
af1e45e6 1873 return row
203f1f98
TB
1874 def phaseRowHeight(self, test, phase, row):
1875 return self.rowheight[test][phase][row]
1876 def phaseRowTop(self, test, phase, row):
af1e45e6 1877 top = 0
203f1f98 1878 for i in sorted(self.rowheight[test][phase]):
af1e45e6
TB
1879 if i >= row:
1880 break
203f1f98 1881 top += self.rowheight[test][phase][i]
af1e45e6
TB
1882 return top
1883 # Function: calcTotalRows
1884 # Description:
1885 # Calculate the heights and offsets for the header and rows
1886 def calcTotalRows(self):
1887 maxrows = 0
1888 standardphases = []
203f1f98
TB
1889 for t in self.rowlines:
1890 for p in self.rowlines[t]:
1891 total = 0
1892 for i in sorted(self.rowlines[t][p]):
1893 total += self.rowlines[t][p][i]
1894 if total > maxrows:
1895 maxrows = total
1896 if total == len(self.rowlines[t][p]):
1897 standardphases.append((t, p))
af1e45e6
TB
1898 self.height = self.scaleH + (maxrows*self.rowH)
1899 self.bodyH = self.height - self.scaleH
203f1f98
TB
1900 # if there is 1 line per row, draw them the standard way
1901 for t, p in standardphases:
1902 for i in sorted(self.rowheight[t][p]):
1903 self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p])
af1e45e6
TB
1904 # Function: createTimeScale
1905 # Description:
1906 # Create the timescale for a timeline block
1907 # Arguments:
1908 # m0: start time (mode begin)
1909 # mMax: end time (mode end)
1910 # tTotal: total timeline time
1911 # mode: suspend or resume
1912 # Output:
1913 # The html code needed to display the time scale
1914 def createTimeScale(self, m0, mMax, tTotal, mode):
1915 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1916 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n'
1917 output = '<div class="timescale">\n'
1918 # set scale for timeline
1919 mTotal = mMax - m0
1920 tS = 0.1
1921 if(tTotal <= 0):
1922 return output+'</div>\n'
1923 if(tTotal > 4):
1924 tS = 1
1925 divTotal = int(mTotal/tS) + 1
1926 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
1927 for i in range(divTotal):
1928 htmlline = ''
1929 if(mode == 'resume'):
1930 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
1931 val = '%0.fms' % (float(i)*tS*1000)
1932 htmlline = timescale.format(pos, val)
1933 if(i == 0):
1934 htmlline = rline
1935 else:
1936 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
1937 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
1938 if(i == divTotal - 1):
1939 val = 'Suspend'
1940 htmlline = timescale.format(pos, val)
1941 output += htmlline
1942 output += '</div>\n'
1943 return output
ee8b09cd 1944
af1e45e6 1945# Class: TestProps
b8432c6f 1946# Description:
af1e45e6
TB
1947# A list of values describing the properties of these test runs
1948class TestProps:
1949 stamp = ''
af1e45e6
TB
1950 S0i3 = False
1951 fwdata = []
b8432c6f
TB
1952 ftrace_line_fmt_fg = \
1953 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
1954 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
af1e45e6 1955 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
b8432c6f
TB
1956 ftrace_line_fmt_nop = \
1957 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
1958 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
1959 '(?P<msg>.*)'
1960 ftrace_line_fmt = ftrace_line_fmt_nop
1961 cgformat = False
b8432c6f 1962 data = 0
af1e45e6
TB
1963 ktemp = dict()
1964 def __init__(self):
1965 self.ktemp = dict()
b8432c6f 1966 def setTracerType(self, tracer):
b8432c6f
TB
1967 if(tracer == 'function_graph'):
1968 self.cgformat = True
1969 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
1970 elif(tracer == 'nop'):
1971 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
1972 else:
03bc39be 1973 doError('Invalid tracer format: [%s]' % tracer)
ee8b09cd 1974
af1e45e6
TB
1975# Class: TestRun
1976# Description:
1977# A container for a suspend/resume test run. This is necessary as
1978# there could be more than one, and they need to be separate.
1979class TestRun:
1980 ftemp = dict()
1981 ttemp = dict()
1982 data = 0
1983 def __init__(self, dataobj):
1984 self.data = dataobj
1985 self.ftemp = dict()
1986 self.ttemp = dict()
1987
203f1f98
TB
1988class ProcessMonitor:
1989 proclist = dict()
1990 running = False
1991 def procstat(self):
1992 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
1ea39643 1993 process = Popen(c, shell=True, stdout=PIPE)
203f1f98
TB
1994 running = dict()
1995 for line in process.stdout:
1996 data = line.split()
1997 pid = data[0]
1998 name = re.sub('[()]', '', data[1])
1999 user = int(data[13])
2000 kern = int(data[14])
2001 kjiff = ujiff = 0
2002 if pid not in self.proclist:
2003 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern}
2004 else:
2005 val = self.proclist[pid]
2006 ujiff = user - val['user']
2007 kjiff = kern - val['kern']
2008 val['user'] = user
2009 val['kern'] = kern
2010 if ujiff > 0 or kjiff > 0:
2011 running[pid] = ujiff + kjiff
2012 result = process.wait()
2013 out = ''
2014 for pid in running:
2015 jiffies = running[pid]
2016 val = self.proclist[pid]
2017 if out:
2018 out += ','
2019 out += '%s-%s %d' % (val['name'], pid, jiffies)
2020 return 'ps - '+out
2021 def processMonitor(self, tid):
203f1f98
TB
2022 while self.running:
2023 out = self.procstat()
2024 if out:
2025 sysvals.fsetVal(out, 'trace_marker')
2026 def start(self):
2027 self.thread = Thread(target=self.processMonitor, args=(0,))
2028 self.running = True
2029 self.thread.start()
2030 def stop(self):
2031 self.running = False
2032
b8432c6f 2033# ----------------- FUNCTIONS --------------------
ee8b09cd 2034
b8432c6f
TB
2035# Function: vprint
2036# Description:
2037# verbose print (prints only with -verbose option)
2038# Arguments:
2039# msg: the debug/log message to print
2040def vprint(msg):
03bc39be 2041 sysvals.logmsg += msg+'\n'
b8432c6f
TB
2042 if(sysvals.verbose):
2043 print(msg)
ee8b09cd 2044
b8432c6f 2045# Function: parseStamp
ee8b09cd 2046# Description:
b8432c6f
TB
2047# Pull in the stamp comment line from the data file(s),
2048# create the stamp, and add it to the global sysvals object
2049# Arguments:
2050# m: the valid re.match output for the stamp line
af1e45e6 2051def parseStamp(line, data):
af1e45e6 2052 m = re.match(sysvals.stampfmt, line)
b8432c6f
TB
2053 data.stamp = {'time': '', 'host': '', 'mode': ''}
2054 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
2055 int(m.group('d')), int(m.group('H')), int(m.group('M')),
2056 int(m.group('S')))
2057 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
2058 data.stamp['host'] = m.group('host')
2059 data.stamp['mode'] = m.group('mode')
2060 data.stamp['kernel'] = m.group('kernel')
af1e45e6 2061 sysvals.hostname = data.stamp['host']
b8432c6f 2062 sysvals.suspendmode = data.stamp['mode']
203f1f98
TB
2063 if sysvals.suspendmode == 'command' and sysvals.ftracefile != '':
2064 modes = ['on', 'freeze', 'standby', 'mem']
1ea39643
TB
2065 out = Popen(['grep', 'suspend_enter', sysvals.ftracefile],
2066 stderr=PIPE, stdout=PIPE).stdout.read()
203f1f98
TB
2067 m = re.match('.* suspend_enter\[(?P<mode>.*)\]', out)
2068 if m and m.group('mode') in ['1', '2', '3']:
2069 sysvals.suspendmode = modes[int(m.group('mode'))]
2070 data.stamp['mode'] = sysvals.suspendmode
b8432c6f
TB
2071 if not sysvals.stamp:
2072 sysvals.stamp = data.stamp
2073
2074# Function: diffStamp
2075# Description:
2076# compare the host, kernel, and mode fields in 3 stamps
2077# Arguments:
2078# stamp1: string array with mode, kernel, and host
2079# stamp2: string array with mode, kernel, and host
2080# Return:
2081# True if stamps differ, False if they're the same
2082def diffStamp(stamp1, stamp2):
2083 if 'host' in stamp1 and 'host' in stamp2:
2084 if stamp1['host'] != stamp2['host']:
2085 return True
2086 if 'kernel' in stamp1 and 'kernel' in stamp2:
2087 if stamp1['kernel'] != stamp2['kernel']:
2088 return True
2089 if 'mode' in stamp1 and 'mode' in stamp2:
2090 if stamp1['mode'] != stamp2['mode']:
2091 return True
2092 return False
2093
2094# Function: doesTraceLogHaveTraceEvents
2095# Description:
2096# Quickly determine if the ftrace log has some or all of the trace events
2097# required for primary parsing. Set the usetraceevents and/or
2098# usetraceeventsonly flags in the global sysvals object
2099def doesTraceLogHaveTraceEvents():
af1e45e6
TB
2100 # check for kprobes
2101 sysvals.usekprobes = False
1ea39643 2102 out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True)
af1e45e6
TB
2103 if(out == 0):
2104 sysvals.usekprobes = True
2105 # check for callgraph data on trace event blocks
1ea39643 2106 out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True)
af1e45e6
TB
2107 if(out == 0):
2108 sysvals.usekprobes = True
1ea39643
TB
2109 out = Popen(['head', '-1', sysvals.ftracefile],
2110 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
af1e45e6
TB
2111 m = re.match(sysvals.stampfmt, out)
2112 if m and m.group('mode') == 'command':
2113 sysvals.usetraceeventsonly = True
2114 sysvals.usetraceevents = True
2115 return
2116 # figure out what level of trace events are supported
b8432c6f
TB
2117 sysvals.usetraceeventsonly = True
2118 sysvals.usetraceevents = False
2119 for e in sysvals.traceevents:
1ea39643 2120 out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True)
af1e45e6 2121 if(out != 0):
b8432c6f 2122 sysvals.usetraceeventsonly = False
af1e45e6 2123 if(e == 'suspend_resume' and out == 0):
b8432c6f 2124 sysvals.usetraceevents = True
af1e45e6
TB
2125 # determine is this log is properly formatted
2126 for e in ['SUSPEND START', 'RESUME COMPLETE']:
1ea39643 2127 out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True)
af1e45e6
TB
2128 if(out != 0):
2129 sysvals.usetracemarkers = False
b8432c6f
TB
2130
2131# Function: appendIncompleteTraceLog
2132# Description:
2133# [deprecated for kernel 3.15 or newer]
2134# Legacy support of ftrace outputs that lack the device_pm_callback
2135# and/or suspend_resume trace events. The primary data should be
2136# taken from dmesg, and this ftrace is used only for callgraph data
2137# or custom actions in the timeline. The data is appended to the Data
2138# objects provided.
2139# Arguments:
2140# testruns: the array of Data objects obtained from parseKernelLog
2141def appendIncompleteTraceLog(testruns):
b8432c6f
TB
2142 # create TestRun vessels for ftrace parsing
2143 testcnt = len(testruns)
af1e45e6 2144 testidx = 0
b8432c6f
TB
2145 testrun = []
2146 for data in testruns:
2147 testrun.append(TestRun(data))
2148
2149 # extract the callgraph and traceevent data
2150 vprint('Analyzing the ftrace data...')
af1e45e6 2151 tp = TestProps()
ee8b09cd 2152 tf = open(sysvals.ftracefile, 'r')
af1e45e6 2153 data = 0
ee8b09cd 2154 for line in tf:
b8432c6f
TB
2155 # remove any latent carriage returns
2156 line = line.replace('\r\n', '')
af1e45e6 2157 # grab the time stamp
b8432c6f
TB
2158 m = re.match(sysvals.stampfmt, line)
2159 if(m):
af1e45e6 2160 tp.stamp = line
b8432c6f
TB
2161 continue
2162 # determine the trace data type (required for further parsing)
2163 m = re.match(sysvals.tracertypefmt, line)
2164 if(m):
af1e45e6
TB
2165 tp.setTracerType(m.group('t'))
2166 continue
2167 # device properties line
2168 if(re.match(sysvals.devpropfmt, line)):
2169 devProps(line)
ee8b09cd 2170 continue
af1e45e6
TB
2171 # parse only valid lines, if this is not one move on
2172 m = re.match(tp.ftrace_line_fmt, line)
ee8b09cd
TB
2173 if(not m):
2174 continue
b8432c6f
TB
2175 # gather the basic message data from the line
2176 m_time = m.group('time')
2177 m_pid = m.group('pid')
2178 m_msg = m.group('msg')
af1e45e6 2179 if(tp.cgformat):
b8432c6f
TB
2180 m_param3 = m.group('dur')
2181 else:
2182 m_param3 = 'traceevent'
ee8b09cd 2183 if(m_time and m_pid and m_msg):
b8432c6f 2184 t = FTraceLine(m_time, m_msg, m_param3)
ee8b09cd
TB
2185 pid = int(m_pid)
2186 else:
2187 continue
2188 # the line should be a call, return, or event
2189 if(not t.fcall and not t.freturn and not t.fevent):
2190 continue
af1e45e6
TB
2191 # look for the suspend start marker
2192 if(t.startMarker()):
2193 data = testrun[testidx].data
2194 parseStamp(tp.stamp, data)
2195 data.setStart(t.time)
2196 continue
2197 if(not data):
2198 continue
2199 # find the end of resume
2200 if(t.endMarker()):
2201 data.setEnd(t.time)
2202 testidx += 1
2203 if(testidx >= testcnt):
2204 break
2205 continue
2206 # trace event processing
2207 if(t.fevent):
2208 # general trace events have two types, begin and end
2209 if(re.match('(?P<name>.*) begin$', t.name)):
2210 isbegin = True
2211 elif(re.match('(?P<name>.*) end$', t.name)):
2212 isbegin = False
2213 else:
ee8b09cd 2214 continue
af1e45e6
TB
2215 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2216 if(m):
2217 val = m.group('val')
2218 if val == '0':
2219 name = m.group('name')
b8432c6f 2220 else:
af1e45e6
TB
2221 name = m.group('name')+'['+val+']'
2222 else:
2223 m = re.match('(?P<name>.*) .*', t.name)
2224 name = m.group('name')
2225 # special processing for trace events
2226 if re.match('dpm_prepare\[.*', name):
2227 continue
2228 elif re.match('machine_suspend.*', name):
2229 continue
2230 elif re.match('suspend_enter\[.*', name):
2231 if(not isbegin):
2232 data.dmesg['suspend_prepare']['end'] = t.time
2233 continue
2234 elif re.match('dpm_suspend\[.*', name):
2235 if(not isbegin):
2236 data.dmesg['suspend']['end'] = t.time
2237 continue
2238 elif re.match('dpm_suspend_late\[.*', name):
2239 if(isbegin):
2240 data.dmesg['suspend_late']['start'] = t.time
b8432c6f 2241 else:
af1e45e6
TB
2242 data.dmesg['suspend_late']['end'] = t.time
2243 continue
2244 elif re.match('dpm_suspend_noirq\[.*', name):
2245 if(isbegin):
2246 data.dmesg['suspend_noirq']['start'] = t.time
b8432c6f 2247 else:
af1e45e6
TB
2248 data.dmesg['suspend_noirq']['end'] = t.time
2249 continue
2250 elif re.match('dpm_resume_noirq\[.*', name):
2251 if(isbegin):
2252 data.dmesg['resume_machine']['end'] = t.time
2253 data.dmesg['resume_noirq']['start'] = t.time
2254 else:
2255 data.dmesg['resume_noirq']['end'] = t.time
2256 continue
2257 elif re.match('dpm_resume_early\[.*', name):
2258 if(isbegin):
2259 data.dmesg['resume_early']['start'] = t.time
2260 else:
2261 data.dmesg['resume_early']['end'] = t.time
2262 continue
2263 elif re.match('dpm_resume\[.*', name):
2264 if(isbegin):
2265 data.dmesg['resume']['start'] = t.time
2266 else:
2267 data.dmesg['resume']['end'] = t.time
2268 continue
2269 elif re.match('dpm_complete\[.*', name):
2270 if(isbegin):
2271 data.dmesg['resume_complete']['start'] = t.time
2272 else:
2273 data.dmesg['resume_complete']['end'] = t.time
2274 continue
2275 # skip trace events inside devices calls
2276 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2277 continue
2278 # global events (outside device calls) are simply graphed
2279 if(isbegin):
2280 # store each trace event in ttemp
2281 if(name not in testrun[testidx].ttemp):
2282 testrun[testidx].ttemp[name] = []
2283 testrun[testidx].ttemp[name].append(\
2284 {'begin': t.time, 'end': t.time})
2285 else:
2286 # finish off matching trace event in ttemp
2287 if(name in testrun[testidx].ttemp):
2288 testrun[testidx].ttemp[name][-1]['end'] = t.time
2289 # call/return processing
2290 elif sysvals.usecallgraph:
2291 # create a callgraph object for the data
2292 if(pid not in testrun[testidx].ftemp):
2293 testrun[testidx].ftemp[pid] = []
2294 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
2295 # when the call is finished, see which device matches it
2296 cg = testrun[testidx].ftemp[pid][-1]
2297 if(cg.addLine(t)):
2298 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
b8432c6f
TB
2299 tf.close()
2300
2301 for test in testrun:
2302 # add the traceevent data to the device hierarchy
2303 if(sysvals.usetraceevents):
2304 for name in test.ttemp:
2305 for event in test.ttemp[name]:
af1e45e6 2306 test.data.newActionGlobal(name, event['begin'], event['end'])
b8432c6f
TB
2307
2308 # add the callgraph data to the device hierarchy
2309 for pid in test.ftemp:
2310 for cg in test.ftemp[pid]:
af1e45e6
TB
2311 if len(cg.list) < 1 or cg.invalid:
2312 continue
2313 if(not cg.postProcess()):
b8432c6f
TB
2314 id = 'task %s cpu %s' % (pid, m.group('cpu'))
2315 vprint('Sanity check failed for '+\
2316 id+', ignoring this callback')
2317 continue
2318 callstart = cg.start
2319 callend = cg.end
2320 for p in test.data.phases:
2321 if(test.data.dmesg[p]['start'] <= callstart and
2322 callstart <= test.data.dmesg[p]['end']):
2323 list = test.data.dmesg[p]['list']
2324 for devname in list:
2325 dev = list[devname]
2326 if(pid == dev['pid'] and
2327 callstart <= dev['start'] and
2328 callend >= dev['end']):
2329 dev['ftrace'] = cg
2330 break
2331
03bc39be 2332 test.data.printDetails()
b8432c6f 2333
b8432c6f
TB
2334# Function: parseTraceLog
2335# Description:
2336# Analyze an ftrace log output file generated from this app during
2337# the execution phase. Used when the ftrace log is the primary data source
2338# and includes the suspend_resume and device_pm_callback trace events
2339# The ftrace filename is taken from sysvals
2340# Output:
2341# An array of Data objects
2342def parseTraceLog():
b8432c6f
TB
2343 vprint('Analyzing the ftrace data...')
2344 if(os.path.exists(sysvals.ftracefile) == False):
03bc39be 2345 doError('%s does not exist' % sysvals.ftracefile)
af1e45e6
TB
2346
2347 sysvals.setupAllKprobes()
203f1f98 2348 tracewatch = []
af1e45e6
TB
2349 if sysvals.usekprobes:
2350 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2351 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
b8432c6f
TB
2352
2353 # extract the callgraph and traceevent data
af1e45e6 2354 tp = TestProps()
b8432c6f
TB
2355 testruns = []
2356 testdata = []
2357 testrun = 0
2358 data = 0
2359 tf = open(sysvals.ftracefile, 'r')
2360 phase = 'suspend_prepare'
2361 for line in tf:
2362 # remove any latent carriage returns
2363 line = line.replace('\r\n', '')
2364 # stamp line: each stamp means a new test run
2365 m = re.match(sysvals.stampfmt, line)
2366 if(m):
af1e45e6 2367 tp.stamp = line
b8432c6f
TB
2368 continue
2369 # firmware line: pull out any firmware data
2370 m = re.match(sysvals.firmwarefmt, line)
2371 if(m):
af1e45e6 2372 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
b8432c6f
TB
2373 continue
2374 # tracer type line: determine the trace data type
2375 m = re.match(sysvals.tracertypefmt, line)
2376 if(m):
af1e45e6 2377 tp.setTracerType(m.group('t'))
b8432c6f 2378 continue
af1e45e6
TB
2379 # device properties line
2380 if(re.match(sysvals.devpropfmt, line)):
2381 devProps(line)
2382 continue
203f1f98
TB
2383 # ignore all other commented lines
2384 if line[0] == '#':
2385 continue
b8432c6f 2386 # ftrace line: parse only valid lines
af1e45e6 2387 m = re.match(tp.ftrace_line_fmt, line)
b8432c6f
TB
2388 if(not m):
2389 continue
2390 # gather the basic message data from the line
2391 m_time = m.group('time')
af1e45e6 2392 m_proc = m.group('proc')
b8432c6f
TB
2393 m_pid = m.group('pid')
2394 m_msg = m.group('msg')
af1e45e6 2395 if(tp.cgformat):
b8432c6f
TB
2396 m_param3 = m.group('dur')
2397 else:
2398 m_param3 = 'traceevent'
2399 if(m_time and m_pid and m_msg):
2400 t = FTraceLine(m_time, m_msg, m_param3)
2401 pid = int(m_pid)
2402 else:
2403 continue
2404 # the line should be a call, return, or event
2405 if(not t.fcall and not t.freturn and not t.fevent):
2406 continue
af1e45e6
TB
2407 # find the start of suspend
2408 if(t.startMarker()):
2409 phase = 'suspend_prepare'
2410 data = Data(len(testdata))
2411 testdata.append(data)
2412 testrun = TestRun(data)
2413 testruns.append(testrun)
2414 parseStamp(tp.stamp, data)
af1e45e6 2415 data.setStart(t.time)
203f1f98 2416 data.tKernSus = t.time
af1e45e6
TB
2417 continue
2418 if(not data):
2419 continue
203f1f98
TB
2420 # process cpu exec line
2421 if t.type == 'tracing_mark_write':
2422 m = re.match(sysvals.procexecfmt, t.name)
2423 if(m):
2424 proclist = dict()
2425 for ps in m.group('ps').split(','):
2426 val = ps.split()
2427 if not val:
2428 continue
2429 name = val[0].replace('--', '-')
2430 proclist[name] = int(val[1])
2431 data.pstl[t.time] = proclist
2432 continue
af1e45e6
TB
2433 # find the end of resume
2434 if(t.endMarker()):
af1e45e6 2435 data.setEnd(t.time)
203f1f98
TB
2436 if data.tKernRes == 0.0:
2437 data.tKernRes = t.time
2438 if data.dmesg['resume_complete']['end'] < 0:
2439 data.dmesg['resume_complete']['end'] = t.time
03bc39be
TB
2440 if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
2441 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2442 if(data.tSuspended != 0 and data.tResumed != 0 and \
2443 (data.fwSuspend > 0 or data.fwResume > 0)):
2444 data.fwValid = True
af1e45e6
TB
2445 if(not sysvals.usetracemarkers):
2446 # no trace markers? then quit and be sure to finish recording
2447 # the event we used to trigger resume end
2448 if(len(testrun.ttemp['thaw_processes']) > 0):
2449 # if an entry exists, assume this is its end
2450 testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2451 break
b8432c6f
TB
2452 continue
2453 # trace event processing
2454 if(t.fevent):
b8432c6f
TB
2455 if(phase == 'post_resume'):
2456 data.setEnd(t.time)
2457 if(t.type == 'suspend_resume'):
2458 # suspend_resume trace events have two types, begin and end
2459 if(re.match('(?P<name>.*) begin$', t.name)):
2460 isbegin = True
2461 elif(re.match('(?P<name>.*) end$', t.name)):
2462 isbegin = False
2463 else:
2464 continue
2465 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2466 if(m):
2467 val = m.group('val')
2468 if val == '0':
2469 name = m.group('name')
2470 else:
2471 name = m.group('name')+'['+val+']'
2472 else:
2473 m = re.match('(?P<name>.*) .*', t.name)
2474 name = m.group('name')
2475 # ignore these events
af1e45e6 2476 if(name.split('[')[0] in tracewatch):
b8432c6f
TB
2477 continue
2478 # -- phase changes --
203f1f98
TB
2479 # start of kernel suspend
2480 if(re.match('suspend_enter\[.*', t.name)):
2481 if(isbegin):
2482 data.dmesg[phase]['start'] = t.time
2483 data.tKernSus = t.time
2484 continue
b8432c6f 2485 # suspend_prepare start
203f1f98 2486 elif(re.match('dpm_prepare\[.*', t.name)):
b8432c6f
TB
2487 phase = 'suspend_prepare'
2488 if(not isbegin):
2489 data.dmesg[phase]['end'] = t.time
2490 continue
2491 # suspend start
2492 elif(re.match('dpm_suspend\[.*', t.name)):
2493 phase = 'suspend'
2494 data.setPhase(phase, t.time, isbegin)
2495 continue
2496 # suspend_late start
2497 elif(re.match('dpm_suspend_late\[.*', t.name)):
2498 phase = 'suspend_late'
2499 data.setPhase(phase, t.time, isbegin)
2500 continue
2501 # suspend_noirq start
2502 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2503 phase = 'suspend_noirq'
2504 data.setPhase(phase, t.time, isbegin)
2505 if(not isbegin):
2506 phase = 'suspend_machine'
2507 data.dmesg[phase]['start'] = t.time
2508 continue
2509 # suspend_machine/resume_machine
2510 elif(re.match('machine_suspend\[.*', t.name)):
2511 if(isbegin):
2512 phase = 'suspend_machine'
2513 data.dmesg[phase]['end'] = t.time
2514 data.tSuspended = t.time
2515 else:
af1e45e6 2516 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
b8432c6f
TB
2517 data.dmesg['suspend_machine']['end'] = t.time
2518 data.tSuspended = t.time
2519 phase = 'resume_machine'
2520 data.dmesg[phase]['start'] = t.time
2521 data.tResumed = t.time
2522 data.tLow = data.tResumed - data.tSuspended
2523 continue
af1e45e6
TB
2524 # acpi_suspend
2525 elif(re.match('acpi_suspend\[.*', t.name)):
2526 # acpi_suspend[0] S0i3
2527 if(re.match('acpi_suspend\[0\] begin', t.name)):
2528 if(sysvals.suspendmode == 'mem'):
2529 tp.S0i3 = True
2530 data.dmesg['suspend_machine']['end'] = t.time
2531 data.tSuspended = t.time
2532 continue
b8432c6f
TB
2533 # resume_noirq start
2534 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2535 phase = 'resume_noirq'
2536 data.setPhase(phase, t.time, isbegin)
2537 if(isbegin):
2538 data.dmesg['resume_machine']['end'] = t.time
2539 continue
2540 # resume_early start
2541 elif(re.match('dpm_resume_early\[.*', t.name)):
2542 phase = 'resume_early'
2543 data.setPhase(phase, t.time, isbegin)
2544 continue
2545 # resume start
2546 elif(re.match('dpm_resume\[.*', t.name)):
2547 phase = 'resume'
2548 data.setPhase(phase, t.time, isbegin)
2549 continue
2550 # resume complete start
2551 elif(re.match('dpm_complete\[.*', t.name)):
2552 phase = 'resume_complete'
2553 if(isbegin):
2554 data.dmesg[phase]['start'] = t.time
2555 continue
af1e45e6
TB
2556 # skip trace events inside devices calls
2557 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2558 continue
2559 # global events (outside device calls) are graphed
2560 if(name not in testrun.ttemp):
2561 testrun.ttemp[name] = []
2562 if(isbegin):
2563 # create a new list entry
2564 testrun.ttemp[name].append(\
2565 {'begin': t.time, 'end': t.time, 'pid': pid})
b8432c6f 2566 else:
af1e45e6
TB
2567 if(len(testrun.ttemp[name]) > 0):
2568 # if an entry exists, assume this is its end
2569 testrun.ttemp[name][-1]['end'] = t.time
2570 elif(phase == 'post_resume'):
2571 # post resume events can just have ends
2572 testrun.ttemp[name].append({
2573 'begin': data.dmesg[phase]['start'],
2574 'end': t.time})
b8432c6f
TB
2575 # device callback start
2576 elif(t.type == 'device_pm_callback_start'):
2577 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2578 t.name);
2579 if(not m):
2580 continue
2581 drv = m.group('drv')
2582 n = m.group('d')
2583 p = m.group('p')
2584 if(n and p):
2585 data.newAction(phase, n, pid, p, t.time, -1, drv)
203f1f98
TB
2586 if pid not in data.devpids:
2587 data.devpids.append(pid)
b8432c6f
TB
2588 # device callback finish
2589 elif(t.type == 'device_pm_callback_end'):
2590 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2591 if(not m):
2592 continue
2593 n = m.group('d')
2594 list = data.dmesg[phase]['list']
2595 if(n in list):
2596 dev = list[n]
2597 dev['length'] = t.time - dev['start']
2598 dev['end'] = t.time
af1e45e6
TB
2599 # kprobe event processing
2600 elif(t.fkprobe):
2601 kprobename = t.type
2602 kprobedata = t.name
2603 key = (kprobename, pid)
2604 # displayname is generated from kprobe data
2605 displayname = ''
2606 if(t.fcall):
2607 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2608 if not displayname:
2609 continue
2610 if(key not in tp.ktemp):
2611 tp.ktemp[key] = []
2612 tp.ktemp[key].append({
2613 'pid': pid,
2614 'begin': t.time,
2615 'end': t.time,
2616 'name': displayname,
2617 'cdata': kprobedata,
2618 'proc': m_proc,
2619 })
2620 elif(t.freturn):
2621 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2622 continue
2623 e = tp.ktemp[key][-1]
2624 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2625 tp.ktemp[key].pop()
2626 else:
2627 e['end'] = t.time
2628 e['rdata'] = kprobedata
203f1f98
TB
2629 # end of kernel resume
2630 if(kprobename == 'pm_notifier_call_chain' or \
2631 kprobename == 'pm_restore_console'):
2632 data.dmesg[phase]['end'] = t.time
2633 data.tKernRes = t.time
2634
b8432c6f
TB
2635 # callgraph processing
2636 elif sysvals.usecallgraph:
ee8b09cd 2637 # create a callgraph object for the data
af1e45e6
TB
2638 key = (m_proc, pid)
2639 if(key not in testrun.ftemp):
2640 testrun.ftemp[key] = []
2641 testrun.ftemp[key].append(FTraceCallGraph(pid))
ee8b09cd 2642 # when the call is finished, see which device matches it
af1e45e6
TB
2643 cg = testrun.ftemp[key][-1]
2644 if(cg.addLine(t)):
2645 testrun.ftemp[key].append(FTraceCallGraph(pid))
b8432c6f
TB
2646 tf.close()
2647
af1e45e6
TB
2648 if sysvals.suspendmode == 'command':
2649 for test in testruns:
2650 for p in test.data.phases:
1ea39643 2651 if p == 'suspend_prepare':
af1e45e6
TB
2652 test.data.dmesg[p]['start'] = test.data.start
2653 test.data.dmesg[p]['end'] = test.data.end
2654 else:
1ea39643
TB
2655 test.data.dmesg[p]['start'] = test.data.end
2656 test.data.dmesg[p]['end'] = test.data.end
2657 test.data.tSuspended = test.data.end
2658 test.data.tResumed = test.data.end
af1e45e6
TB
2659 test.data.tLow = 0
2660 test.data.fwValid = False
2661
203f1f98
TB
2662 # dev source and procmon events can be unreadable with mixed phase height
2663 if sysvals.usedevsrc or sysvals.useprocmon:
2664 sysvals.mixedphaseheight = False
2665
1ea39643
TB
2666 for i in range(len(testruns)):
2667 test = testruns[i]
2668 data = test.data
2669 # find the total time range for this test (begin, end)
2670 tlb, tle = data.start, data.end
2671 if i < len(testruns) - 1:
2672 tle = testruns[i+1].data.start
203f1f98
TB
2673 # add the process usage data to the timeline
2674 if sysvals.useprocmon:
1ea39643 2675 data.createProcessUsageEvents()
b8432c6f
TB
2676 # add the traceevent data to the device hierarchy
2677 if(sysvals.usetraceevents):
af1e45e6 2678 # add actual trace funcs
b8432c6f
TB
2679 for name in test.ttemp:
2680 for event in test.ttemp[name]:
1ea39643 2681 data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
af1e45e6
TB
2682 # add the kprobe based virtual tracefuncs as actual devices
2683 for key in tp.ktemp:
2684 name, pid = key
2685 if name not in sysvals.tracefuncs:
b8432c6f 2686 continue
af1e45e6
TB
2687 for e in tp.ktemp[key]:
2688 kb, ke = e['begin'], e['end']
1ea39643 2689 if kb == ke or tlb > kb or tle <= kb:
af1e45e6 2690 continue
1ea39643
TB
2691 color = sysvals.kprobeColor(name)
2692 data.newActionGlobal(e['name'], kb, ke, pid, color)
af1e45e6 2693 # add config base kprobes and dev kprobes
1ea39643
TB
2694 if sysvals.usedevsrc:
2695 for key in tp.ktemp:
2696 name, pid = key
2697 if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs:
af1e45e6 2698 continue
1ea39643
TB
2699 for e in tp.ktemp[key]:
2700 kb, ke = e['begin'], e['end']
2701 if kb == ke or tlb > kb or tle <= kb:
2702 continue
2703 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
af1e45e6
TB
2704 ke, e['cdata'], e['rdata'])
2705 if sysvals.usecallgraph:
2706 # add the callgraph data to the device hierarchy
2707 sortlist = dict()
2708 for key in test.ftemp:
2709 proc, pid = key
2710 for cg in test.ftemp[key]:
2711 if len(cg.list) < 1 or cg.invalid:
2712 continue
2713 if(not cg.postProcess()):
2714 id = 'task %s' % (pid)
2715 vprint('Sanity check failed for '+\
2716 id+', ignoring this callback')
2717 continue
2718 # match cg data to devices
1ea39643 2719 if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, data):
af1e45e6
TB
2720 sortkey = '%f%f%d' % (cg.start, cg.end, pid)
2721 sortlist[sortkey] = cg
2722 # create blocks for orphan cg data
2723 for sortkey in sorted(sortlist):
2724 cg = sortlist[sortkey]
2725 name = cg.list[0].name
2726 if sysvals.isCallgraphFunc(name):
2727 vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
1ea39643 2728 cg.newActionFromFunction(data)
af1e45e6
TB
2729
2730 if sysvals.suspendmode == 'command':
03bc39be
TB
2731 for data in testdata:
2732 data.printDetails()
af1e45e6 2733 return testdata
ee8b09cd 2734
b8432c6f
TB
2735 # fill in any missing phases
2736 for data in testdata:
2737 lp = data.phases[0]
2738 for p in data.phases:
2739 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
03bc39be 2740 vprint('WARNING: phase "%s" is missing!' % p)
b8432c6f
TB
2741 if(data.dmesg[p]['start'] < 0):
2742 data.dmesg[p]['start'] = data.dmesg[lp]['end']
2743 if(p == 'resume_machine'):
2744 data.tSuspended = data.dmesg[lp]['end']
2745 data.tResumed = data.dmesg[lp]['end']
2746 data.tLow = 0
2747 if(data.dmesg[p]['end'] < 0):
2748 data.dmesg[p]['end'] = data.dmesg[p]['start']
03bc39be
TB
2749 if(p != lp and not ('machine' in p and 'machine' in lp)):
2750 data.dmesg[lp]['end'] = data.dmesg[p]['start']
b8432c6f
TB
2751 lp = p
2752
2753 if(len(sysvals.devicefilter) > 0):
2754 data.deviceFilter(sysvals.devicefilter)
2755 data.fixupInitcallsThatDidntReturn()
203f1f98
TB
2756 if sysvals.usedevsrc:
2757 data.optimizeDevSrc()
03bc39be 2758 data.printDetails()
b8432c6f 2759
1ea39643 2760 # x2: merge any overlapping devices between test runs
203f1f98
TB
2761 if sysvals.usedevsrc and len(testdata) > 1:
2762 tc = len(testdata)
2763 for i in range(tc - 1):
2764 devlist = testdata[i].overflowDevices()
2765 for j in range(i + 1, tc):
2766 testdata[j].mergeOverlapDevices(devlist)
1ea39643 2767 testdata[0].stitchTouchingThreads(testdata[1:])
b8432c6f
TB
2768 return testdata
2769
2770# Function: loadKernelLog
ee8b09cd 2771# Description:
b8432c6f
TB
2772# [deprecated for kernel 3.15.0 or newer]
2773# load the dmesg file into memory and fix up any ordering issues
2774# The dmesg filename is taken from sysvals
2775# Output:
2776# An array of empty Data objects with only their dmesgtext attributes set
03bc39be 2777def loadKernelLog(justtext=False):
b8432c6f
TB
2778 vprint('Analyzing the dmesg data...')
2779 if(os.path.exists(sysvals.dmesgfile) == False):
03bc39be 2780 doError('%s does not exist' % sysvals.dmesgfile)
b8432c6f 2781
03bc39be
TB
2782 if justtext:
2783 dmesgtext = []
af1e45e6
TB
2784 # there can be multiple test runs in a single file
2785 tp = TestProps()
03bc39be 2786 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
b8432c6f
TB
2787 testruns = []
2788 data = 0
ee8b09cd 2789 lf = open(sysvals.dmesgfile, 'r')
ee8b09cd 2790 for line in lf:
b8432c6f
TB
2791 line = line.replace('\r\n', '')
2792 idx = line.find('[')
2793 if idx > 1:
2794 line = line[idx:]
2795 m = re.match(sysvals.stampfmt, line)
2796 if(m):
af1e45e6 2797 tp.stamp = line
b8432c6f
TB
2798 continue
2799 m = re.match(sysvals.firmwarefmt, line)
2800 if(m):
af1e45e6 2801 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
b8432c6f
TB
2802 continue
2803 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
af1e45e6
TB
2804 if(not m):
2805 continue
2806 msg = m.group("msg")
03bc39be
TB
2807 if justtext:
2808 dmesgtext.append(line)
2809 continue
af1e45e6
TB
2810 if(re.match('PM: Syncing filesystems.*', msg)):
2811 if(data):
2812 testruns.append(data)
2813 data = Data(len(testruns))
2814 parseStamp(tp.stamp, data)
2815 if len(tp.fwdata) > data.testnumber:
2816 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2817 if(data.fwSuspend > 0 or data.fwResume > 0):
2818 data.fwValid = True
af1e45e6
TB
2819 if(not data):
2820 continue
03bc39be
TB
2821 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
2822 if(m):
2823 sysvals.stamp['kernel'] = m.group('k')
2824 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
2825 if(m):
2826 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')
af1e45e6 2827 data.dmesgtext.append(line)
ee8b09cd 2828 lf.close()
b8432c6f 2829
03bc39be
TB
2830 if justtext:
2831 return dmesgtext
2832 if data:
2833 testruns.append(data)
2834 if len(testruns) < 1:
2835 doError(' dmesg log has no suspend/resume data: %s' \
2836 % sysvals.dmesgfile)
b8432c6f
TB
2837
2838 # fix lines with same timestamp/function with the call and return swapped
2839 for data in testruns:
2840 last = ''
2841 for line in data.dmesgtext:
2842 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
2843 '(?P<f>.*)\+ @ .*, parent: .*', line)
2844 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
2845 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
2846 if(mc and mr and (mc.group('t') == mr.group('t')) and
2847 (mc.group('f') == mr.group('f'))):
2848 i = data.dmesgtext.index(last)
2849 j = data.dmesgtext.index(line)
2850 data.dmesgtext[i] = line
2851 data.dmesgtext[j] = last
2852 last = line
2853 return testruns
2854
2855# Function: parseKernelLog
ee8b09cd 2856# Description:
b8432c6f 2857# [deprecated for kernel 3.15.0 or newer]
ee8b09cd
TB
2858# Analyse a dmesg log output file generated from this app during
2859# the execution phase. Create a set of device structures in memory
2860# for subsequent formatting in the html output file
b8432c6f
TB
2861# This call is only for legacy support on kernels where the ftrace
2862# data lacks the suspend_resume or device_pm_callbacks trace events.
2863# Arguments:
2864# data: an empty Data object (with dmesgtext) obtained from loadKernelLog
2865# Output:
2866# The filled Data object
2867def parseKernelLog(data):
b8432c6f 2868 phase = 'suspend_runtime'
ee8b09cd 2869
b8432c6f
TB
2870 if(data.fwValid):
2871 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
2872 (data.fwSuspend, data.fwResume))
ee8b09cd 2873
b8432c6f 2874 # dmesg phase match table
ee8b09cd 2875 dm = {
b8432c6f
TB
2876 'suspend_prepare': 'PM: Syncing filesystems.*',
2877 'suspend': 'PM: Entering [a-z]* sleep.*',
2878 'suspend_late': 'PM: suspend of devices complete after.*',
2879 'suspend_noirq': 'PM: late suspend of devices complete after.*',
2880 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
2881 'resume_machine': 'ACPI: Low-level resume complete.*',
2882 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
2883 'resume_early': 'PM: noirq resume of devices complete after.*',
2884 'resume': 'PM: early resume of devices complete after.*',
2885 'resume_complete': 'PM: resume of devices complete after.*',
2886 'post_resume': '.*Restarting tasks \.\.\..*',
ee8b09cd 2887 }
b8432c6f
TB
2888 if(sysvals.suspendmode == 'standby'):
2889 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
2890 elif(sysvals.suspendmode == 'disk'):
2891 dm['suspend_late'] = 'PM: freeze of devices complete after.*'
2892 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
2893 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
2894 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
2895 dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
2896 dm['resume'] = 'PM: early restore of devices complete after.*'
2897 dm['resume_complete'] = 'PM: restore of devices complete after.*'
2898 elif(sysvals.suspendmode == 'freeze'):
2899 dm['resume_machine'] = 'ACPI: resume from mwait'
2900
2901 # action table (expected events that occur and show up in dmesg)
2902 at = {
2903 'sync_filesystems': {
2904 'smsg': 'PM: Syncing filesystems.*',
2905 'emsg': 'PM: Preparing system for mem sleep.*' },
2906 'freeze_user_processes': {
2907 'smsg': 'Freezing user space processes .*',
2908 'emsg': 'Freezing remaining freezable tasks.*' },
2909 'freeze_tasks': {
2910 'smsg': 'Freezing remaining freezable tasks.*',
2911 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
2912 'ACPI prepare': {
2913 'smsg': 'ACPI: Preparing to enter system sleep state.*',
2914 'emsg': 'PM: Saving platform NVS memory.*' },
2915 'PM vns': {
2916 'smsg': 'PM: Saving platform NVS memory.*',
2917 'emsg': 'Disabling non-boot CPUs .*' },
2918 }
2919
2920 t0 = -1.0
2921 cpu_start = -1.0
2922 prevktime = -1.0
2923 actions = dict()
2924 for line in data.dmesgtext:
ee8b09cd 2925 # parse each dmesg line into the time and message
b8432c6f 2926 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
ee8b09cd 2927 if(m):
b8432c6f
TB
2928 val = m.group('ktime')
2929 try:
2930 ktime = float(val)
2931 except:
b8432c6f
TB
2932 continue
2933 msg = m.group('msg')
2934 # initialize data start to first line time
2935 if t0 < 0:
2936 data.setStart(ktime)
2937 t0 = ktime
ee8b09cd 2938 else:
ee8b09cd
TB
2939 continue
2940
b8432c6f
TB
2941 # hack for determining resume_machine end for freeze
2942 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
2943 and phase == 'resume_machine' and \
2944 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
2945 data.dmesg['resume_machine']['end'] = ktime
2946 phase = 'resume_noirq'
2947 data.dmesg[phase]['start'] = ktime
2948
b8432c6f
TB
2949 # suspend start
2950 if(re.match(dm['suspend_prepare'], msg)):
2951 phase = 'suspend_prepare'
2952 data.dmesg[phase]['start'] = ktime
2953 data.setStart(ktime)
03bc39be 2954 data.tKernSus = ktime
b8432c6f
TB
2955 # suspend start
2956 elif(re.match(dm['suspend'], msg)):
2957 data.dmesg['suspend_prepare']['end'] = ktime
2958 phase = 'suspend'
ee8b09cd 2959 data.dmesg[phase]['start'] = ktime
b8432c6f
TB
2960 # suspend_late start
2961 elif(re.match(dm['suspend_late'], msg)):
2962 data.dmesg['suspend']['end'] = ktime
2963 phase = 'suspend_late'
ee8b09cd
TB
2964 data.dmesg[phase]['start'] = ktime
2965 # suspend_noirq start
2966 elif(re.match(dm['suspend_noirq'], msg)):
b8432c6f
TB
2967 data.dmesg['suspend_late']['end'] = ktime
2968 phase = 'suspend_noirq'
ee8b09cd 2969 data.dmesg[phase]['start'] = ktime
b8432c6f
TB
2970 # suspend_machine start
2971 elif(re.match(dm['suspend_machine'], msg)):
2972 data.dmesg['suspend_noirq']['end'] = ktime
2973 phase = 'suspend_machine'
ee8b09cd 2974 data.dmesg[phase]['start'] = ktime
b8432c6f
TB
2975 # resume_machine start
2976 elif(re.match(dm['resume_machine'], msg)):
2977 if(sysvals.suspendmode in ['freeze', 'standby']):
2978 data.tSuspended = prevktime
2979 data.dmesg['suspend_machine']['end'] = prevktime
2980 else:
2981 data.tSuspended = ktime
2982 data.dmesg['suspend_machine']['end'] = ktime
2983 phase = 'resume_machine'
2984 data.tResumed = ktime
2985 data.tLow = data.tResumed - data.tSuspended
ee8b09cd
TB
2986 data.dmesg[phase]['start'] = ktime
2987 # resume_noirq start
2988 elif(re.match(dm['resume_noirq'], msg)):
b8432c6f
TB
2989 data.dmesg['resume_machine']['end'] = ktime
2990 phase = 'resume_noirq'
ee8b09cd 2991 data.dmesg[phase]['start'] = ktime
ee8b09cd
TB
2992 # resume_early start
2993 elif(re.match(dm['resume_early'], msg)):
b8432c6f
TB
2994 data.dmesg['resume_noirq']['end'] = ktime
2995 phase = 'resume_early'
ee8b09cd 2996 data.dmesg[phase]['start'] = ktime
b8432c6f
TB
2997 # resume start
2998 elif(re.match(dm['resume'], msg)):
2999 data.dmesg['resume_early']['end'] = ktime
3000 phase = 'resume'
ee8b09cd
TB
3001 data.dmesg[phase]['start'] = ktime
3002 # resume complete start
3003 elif(re.match(dm['resume_complete'], msg)):
b8432c6f
TB
3004 data.dmesg['resume']['end'] = ktime
3005 phase = 'resume_complete'
3006 data.dmesg[phase]['start'] = ktime
3007 # post resume start
3008 elif(re.match(dm['post_resume'], msg)):
3009 data.dmesg['resume_complete']['end'] = ktime
3010 data.setEnd(ktime)
03bc39be 3011 data.tKernRes = ktime
ee8b09cd
TB
3012 break
3013
3014 # -- device callbacks --
3015 if(phase in data.phases):
3016 # device init call
b8432c6f
TB
3017 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3018 sm = re.match('calling (?P<f>.*)\+ @ '+\
3019 '(?P<n>.*), parent: (?P<p>.*)', msg);
3020 f = sm.group('f')
3021 n = sm.group('n')
3022 p = sm.group('p')
ee8b09cd 3023 if(f and n and p):
b8432c6f 3024 data.newAction(phase, f, int(n), p, ktime, -1, '')
ee8b09cd 3025 # device init return
b8432c6f
TB
3026 elif(re.match('call (?P<f>.*)\+ returned .* after '+\
3027 '(?P<t>.*) usecs', msg)):
3028 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
3029 '(?P<t>.*) usecs(?P<a>.*)', msg);
3030 f = sm.group('f')
3031 t = sm.group('t')
ee8b09cd
TB
3032 list = data.dmesg[phase]['list']
3033 if(f in list):
3034 dev = list[f]
3035 dev['length'] = int(t)
3036 dev['end'] = ktime
b8432c6f 3037
b8432c6f
TB
3038 # if trace events are not available, these are better than nothing
3039 if(not sysvals.usetraceevents):
3040 # look for known actions
3041 for a in at:
3042 if(re.match(at[a]['smsg'], msg)):
3043 if(a not in actions):
3044 actions[a] = []
3045 actions[a].append({'begin': ktime, 'end': ktime})
3046 if(re.match(at[a]['emsg'], msg)):
af1e45e6
TB
3047 if(a in actions):
3048 actions[a][-1]['end'] = ktime
b8432c6f
TB
3049 # now look for CPU on/off events
3050 if(re.match('Disabling non-boot CPUs .*', msg)):
3051 # start of first cpu suspend
3052 cpu_start = ktime
3053 elif(re.match('Enabling non-boot CPUs .*', msg)):
3054 # start of first cpu resume
3055 cpu_start = ktime
3056 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
3057 # end of a cpu suspend, start of the next
3058 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
3059 cpu = 'CPU'+m.group('cpu')
3060 if(cpu not in actions):
3061 actions[cpu] = []
3062 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3063 cpu_start = ktime
3064 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
3065 # end of a cpu resume, start of the next
3066 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
3067 cpu = 'CPU'+m.group('cpu')
3068 if(cpu not in actions):
3069 actions[cpu] = []
3070 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3071 cpu_start = ktime
3072 prevktime = ktime
ee8b09cd
TB
3073
3074 # fill in any missing phases
b8432c6f 3075 lp = data.phases[0]
ee8b09cd 3076 for p in data.phases:
b8432c6f
TB
3077 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
3078 print('WARNING: phase "%s" is missing, something went wrong!' % p)
3079 print(' In %s, this dmesg line denotes the start of %s:' % \
3080 (sysvals.suspendmode, p))
3081 print(' "%s"' % dm[p])
ee8b09cd
TB
3082 if(data.dmesg[p]['start'] < 0):
3083 data.dmesg[p]['start'] = data.dmesg[lp]['end']
b8432c6f 3084 if(p == 'resume_machine'):
ee8b09cd 3085 data.tSuspended = data.dmesg[lp]['end']
b8432c6f
TB
3086 data.tResumed = data.dmesg[lp]['end']
3087 data.tLow = 0
ee8b09cd
TB
3088 if(data.dmesg[p]['end'] < 0):
3089 data.dmesg[p]['end'] = data.dmesg[p]['start']
3090 lp = p
3091
b8432c6f
TB
3092 # fill in any actions we've found
3093 for name in actions:
3094 for event in actions[name]:
af1e45e6 3095 data.newActionGlobal(name, event['begin'], event['end'])
b8432c6f 3096
03bc39be 3097 data.printDetails()
b8432c6f
TB
3098 if(len(sysvals.devicefilter) > 0):
3099 data.deviceFilter(sysvals.devicefilter)
ee8b09cd
TB
3100 data.fixupInitcallsThatDidntReturn()
3101 return True
3102
b8432c6f
TB
3103# Function: createHTMLSummarySimple
3104# Description:
3105# Create summary html file for a series of tests
3106# Arguments:
3107# testruns: array of Data objects from parseTraceLog
3108def createHTMLSummarySimple(testruns, htmlfile):
b8432c6f
TB
3109 # print out the basic summary of all the tests
3110 hf = open(htmlfile, 'w')
3111
3112 # write the html header first (html head, css code, up to body start)
3113 html = '<!DOCTYPE html>\n<html>\n<head>\n\
3114 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3115 <title>AnalyzeSuspend Summary</title>\n\
3116 <style type=\'text/css\'>\n\
3117 body {overflow-y: scroll;}\n\
3118 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\
3119 table {width:100%;border-collapse: collapse;}\n\
3120 .summary {font: 22px Arial;border:1px solid;}\n\
3121 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\
3122 td {text-align: center;}\n\
3123 tr.alt td {background-color:#EAF2D3;}\n\
3124 tr.avg td {background-color:#BDE34C;}\n\
3125 a:link {color: #90B521;}\n\
3126 a:visited {color: #495E09;}\n\
3127 a:hover {color: #B1DF28;}\n\
3128 a:active {color: #FFFFFF;}\n\
3129 </style>\n</head>\n<body>\n'
3130
3131 # group test header
3132 count = len(testruns)
3133 headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n'
3134 html += headline_stamp.format(sysvals.stamp['host'],
3135 sysvals.stamp['kernel'], sysvals.stamp['mode'],
3136 sysvals.stamp['time'], count)
3137
3138 # check to see if all the tests have the same value
3139 stampcolumns = False
3140 for data in testruns:
3141 if diffStamp(sysvals.stamp, data.stamp):
3142 stampcolumns = True
3143 break
3144
3145 th = '\t<th>{0}</th>\n'
3146 td = '\t<td>{0}</td>\n'
3147 tdlink = '\t<td><a href="{0}">Click Here</a></td>\n'
3148
3149 # table header
3150 html += '<table class="summary">\n<tr>\n'
3151 html += th.format("Test #")
3152 if stampcolumns:
3153 html += th.format("Hostname")
3154 html += th.format("Kernel Version")
3155 html += th.format("Suspend Mode")
3156 html += th.format("Test Time")
3157 html += th.format("Suspend Time")
3158 html += th.format("Resume Time")
3159 html += th.format("Detail")
3160 html += '</tr>\n'
3161
3162 # test data, 1 row per test
3163 sTimeAvg = 0.0
3164 rTimeAvg = 0.0
3165 num = 1
3166 for data in testruns:
3167 # data.end is the end of post_resume
3168 resumeEnd = data.dmesg['resume_complete']['end']
3169 if num % 2 == 1:
3170 html += '<tr class="alt">\n'
3171 else:
3172 html += '<tr>\n'
3173
3174 # test num
3175 html += td.format("test %d" % num)
3176 num += 1
3177 if stampcolumns:
3178 # host name
3179 val = "unknown"
3180 if('host' in data.stamp):
3181 val = data.stamp['host']
3182 html += td.format(val)
3183 # host kernel
3184 val = "unknown"
3185 if('kernel' in data.stamp):
3186 val = data.stamp['kernel']
3187 html += td.format(val)
3188 # suspend mode
3189 val = "unknown"
3190 if('mode' in data.stamp):
3191 val = data.stamp['mode']
3192 html += td.format(val)
3193 # test time
3194 val = "unknown"
3195 if('time' in data.stamp):
3196 val = data.stamp['time']
3197 html += td.format(val)
3198 # suspend time
3199 sTime = (data.tSuspended - data.start)*1000
3200 sTimeAvg += sTime
3201 html += td.format("%3.3f ms" % sTime)
3202 # resume time
3203 rTime = (resumeEnd - data.tResumed)*1000
3204 rTimeAvg += rTime
3205 html += td.format("%3.3f ms" % rTime)
3206 # link to the output html
3207 html += tdlink.format(data.outfile)
3208
3209 html += '</tr>\n'
3210
3211 # last line: test average
3212 if(count > 0):
3213 sTimeAvg /= count
3214 rTimeAvg /= count
3215 html += '<tr class="avg">\n'
3216 html += td.format('Average') # name
3217 if stampcolumns:
3218 html += td.format('') # host
3219 html += td.format('') # kernel
3220 html += td.format('') # mode
3221 html += td.format('') # time
3222 html += td.format("%3.3f ms" % sTimeAvg) # suspend time
3223 html += td.format("%3.3f ms" % rTimeAvg) # resume time
3224 html += td.format('') # output link
3225 html += '</tr>\n'
3226
3227 # flush the data to file
3228 hf.write(html+'</table>\n')
3229 hf.write('</body>\n</html>\n')
3230 hf.close()
3231
af1e45e6 3232def htmlTitle():
af1e45e6
TB
3233 modename = {
3234 'freeze': 'Freeze (S0)',
3235 'standby': 'Standby (S1)',
3236 'mem': 'Suspend (S3)',
3237 'disk': 'Hibernate (S4)'
3238 }
3239 kernel = sysvals.stamp['kernel']
3240 host = sysvals.hostname[0].upper()+sysvals.hostname[1:]
3241 mode = sysvals.suspendmode
3242 if sysvals.suspendmode in modename:
3243 mode = modename[sysvals.suspendmode]
3244 return host+' '+mode+' '+kernel
3245
3246def ordinal(value):
3247 suffix = 'th'
3248 if value < 10 or value > 19:
3249 if value % 10 == 1:
3250 suffix = 'st'
3251 elif value % 10 == 2:
3252 suffix = 'nd'
3253 elif value % 10 == 3:
3254 suffix = 'rd'
3255 return '%d%s' % (value, suffix)
3256
ee8b09cd
TB
3257# Function: createHTML
3258# Description:
b8432c6f
TB
3259# Create the output html file from the resident test data
3260# Arguments:
3261# testruns: array of Data objects from parseKernelLog or parseTraceLog
3262# Output:
3263# True if the html file was created, false if it failed
3264def createHTML(testruns):
af1e45e6
TB
3265 if len(testruns) < 1:
3266 print('ERROR: Not enough test data to build a timeline')
3267 return
3268
03bc39be 3269 kerror = False
b8432c6f 3270 for data in testruns:
03bc39be
TB
3271 if data.kerror:
3272 kerror = True
b8432c6f 3273 data.normalizeTime(testruns[-1].tSuspended)
ee8b09cd 3274
b8432c6f
TB
3275 x2changes = ['', 'absolute']
3276 if len(testruns) > 1:
3277 x2changes = ['1', 'relative']
ee8b09cd 3278 # html function templates
af1e45e6 3279 headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version
ee8b09cd 3280 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
b8432c6f 3281 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
203f1f98 3282 html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
b8432c6f
TB
3283 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
3284 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
203f1f98 3285 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
af1e45e6 3286 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'
03bc39be 3287 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR&rarr;</div>\n'
1ea39643 3288 html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n'
203f1f98 3289 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
af1e45e6 3290 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
203f1f98 3291 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
af1e45e6 3292 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
ee8b09cd 3293 html_timetotal = '<table class="time1">\n<tr>'\
1ea39643
TB
3294 '<td class="green" title="{3}">{2} Suspend Time: <b>{0} ms</b></td>'\
3295 '<td class="yellow" title="{4}">{2} Resume Time: <b>{1} ms</b></td>'\
b8432c6f
TB
3296 '</tr>\n</table>\n'
3297 html_timetotal2 = '<table class="time1">\n<tr>'\
1ea39643
TB
3298 '<td class="green" title="{4}">{3} Suspend Time: <b>{0} ms</b></td>'\
3299 '<td class="gray" title="time spent in low-power mode with clock running">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
3300 '<td class="yellow" title="{5}">{3} Resume Time: <b>{2} ms</b></td>'\
ee8b09cd 3301 '</tr>\n</table>\n'
af1e45e6
TB
3302 html_timetotal3 = '<table class="time1">\n<tr>'\
3303 '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3304 '<td class="yellow">Command: <b>{1}</b></td>'\
3305 '</tr>\n</table>\n'
ee8b09cd 3306 html_timegroups = '<table class="time2">\n<tr>'\
1ea39643 3307 '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\
b8432c6f
TB
3308 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3309 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
1ea39643 3310 '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\
ee8b09cd
TB
3311 '</tr>\n</table>\n'
3312
af1e45e6 3313 # html format variables
203f1f98 3314 hoverZ = 'z-index:8;'
af1e45e6
TB
3315 if sysvals.usedevsrc:
3316 hoverZ = ''
03bc39be
TB
3317 scaleH = 20
3318 scaleTH = 20
3319 if kerror:
3320 scaleH = 40
3321 scaleTH = 60
af1e45e6 3322
b8432c6f
TB
3323 # device timeline
3324 vprint('Creating Device Timeline...')
af1e45e6 3325
03bc39be 3326 devtl = Timeline(30, scaleH)
ee8b09cd 3327
b8432c6f 3328 # Generate the header for this timeline
b8432c6f
TB
3329 for data in testruns:
3330 tTotal = data.end - data.start
1ea39643
TB
3331 sktime = (data.dmesg['suspend_machine']['end'] - \
3332 data.tKernSus) * 1000
3333 rktime = (data.dmesg['resume_complete']['end'] - \
3334 data.dmesg['resume_machine']['start']) * 1000
ee8b09cd 3335 if(tTotal == 0):
b8432c6f 3336 print('ERROR: No timeline data')
ee8b09cd 3337 sys.exit()
b8432c6f
TB
3338 if(data.tLow > 0):
3339 low_time = '%.0f'%(data.tLow*1000)
af1e45e6
TB
3340 if sysvals.suspendmode == 'command':
3341 run_time = '%.0f'%((data.end-data.start)*1000)
3342 if sysvals.testcommand:
3343 testdesc = sysvals.testcommand
3344 else:
3345 testdesc = 'unknown'
3346 if(len(testruns) > 1):
3347 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3348 thtml = html_timetotal3.format(run_time, testdesc)
3349 devtl.html['header'] += thtml
3350 elif data.fwValid:
1ea39643
TB
3351 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3352 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
b8432c6f
TB
3353 testdesc1 = 'Total'
3354 testdesc2 = ''
1ea39643
TB
3355 stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode
3356 rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode
b8432c6f 3357 if(len(testruns) > 1):
af1e45e6 3358 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
b8432c6f
TB
3359 testdesc2 += ' '
3360 if(data.tLow == 0):
3361 thtml = html_timetotal.format(suspend_time, \
1ea39643 3362 resume_time, testdesc1, stitle, rtitle)
b8432c6f
TB
3363 else:
3364 thtml = html_timetotal2.format(suspend_time, low_time, \
1ea39643 3365 resume_time, testdesc1, stitle, rtitle)
af1e45e6 3366 devtl.html['header'] += thtml
b8432c6f
TB
3367 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3368 rftime = '%.3f'%(data.fwResume / 1000000.0)
1ea39643
TB
3369 devtl.html['header'] += html_timegroups.format('%.3f'%sktime, \
3370 sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode)
ee8b09cd 3371 else:
1ea39643
TB
3372 suspend_time = '%.3f' % sktime
3373 resume_time = '%.3f' % rktime
b8432c6f 3374 testdesc = 'Kernel'
1ea39643
TB
3375 stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode
3376 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode
b8432c6f 3377 if(len(testruns) > 1):
af1e45e6 3378 testdesc = ordinal(data.testnumber+1)+' '+testdesc
b8432c6f
TB
3379 if(data.tLow == 0):
3380 thtml = html_timetotal.format(suspend_time, \
1ea39643 3381 resume_time, testdesc, stitle, rtitle)
b8432c6f
TB
3382 else:
3383 thtml = html_timetotal2.format(suspend_time, low_time, \
1ea39643 3384 resume_time, testdesc, stitle, rtitle)
af1e45e6 3385 devtl.html['header'] += thtml
b8432c6f
TB
3386
3387 # time scale for potentially multiple datasets
3388 t0 = testruns[0].start
3389 tMax = testruns[-1].end
b8432c6f 3390 tTotal = tMax - t0
ee8b09cd 3391
b8432c6f 3392 # determine the maximum number of rows we need to draw
203f1f98 3393 fulllist = []
1ea39643
TB
3394 threadlist = []
3395 pscnt = 0
3396 devcnt = 0
b8432c6f 3397 for data in testruns:
af1e45e6
TB
3398 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
3399 for group in data.devicegroups:
3400 devlist = []
3401 for phase in group:
3402 for devname in data.tdevlist[phase]:
203f1f98
TB
3403 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3404 devlist.append(d)
1ea39643
TB
3405 if d.isa('kth'):
3406 threadlist.append(d)
3407 else:
3408 if d.isa('ps'):
3409 pscnt += 1
3410 else:
3411 devcnt += 1
3412 fulllist.append(d)
203f1f98
TB
3413 if sysvals.mixedphaseheight:
3414 devtl.getPhaseRows(devlist)
3415 if not sysvals.mixedphaseheight:
1ea39643
TB
3416 if len(threadlist) > 0 and len(fulllist) > 0:
3417 if pscnt > 0 and devcnt > 0:
3418 msg = 'user processes & device pm callbacks'
3419 elif pscnt > 0:
3420 msg = 'user processes'
3421 else:
3422 msg = 'device pm callbacks'
3423 d = testruns[0].addHorizontalDivider(msg, testruns[-1].end)
3424 fulllist.insert(0, d)
203f1f98 3425 devtl.getPhaseRows(fulllist)
1ea39643
TB
3426 if len(threadlist) > 0:
3427 d = testruns[0].addHorizontalDivider('asynchronous kernel threads', testruns[-1].end)
3428 threadlist.insert(0, d)
3429 devtl.getPhaseRows(threadlist, devtl.rows)
af1e45e6
TB
3430 devtl.calcTotalRows()
3431
3432 # create bounding box, add buttons
3433 if sysvals.suspendmode != 'command':
3434 devtl.html['timeline'] += html_devlist1
3435 if len(testruns) > 1:
3436 devtl.html['timeline'] += html_devlist2
b8432c6f
TB
3437 devtl.html['timeline'] += html_zoombox
3438 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
ee8b09cd 3439
af1e45e6
TB
3440 # draw the full timeline
3441 phases = {'suspend':[],'resume':[]}
3442 for phase in data.dmesg:
3443 if 'resume' in phase:
3444 phases['resume'].append(phase)
3445 else:
3446 phases['suspend'].append(phase)
b8432c6f 3447
af1e45e6 3448 # draw each test run chronologically
b8432c6f 3449 for data in testruns:
af1e45e6
TB
3450 # now draw the actual timeline blocks
3451 for dir in phases:
3452 # draw suspend and resume blocks separately
3453 bname = '%s%d' % (dir[0], data.testnumber)
3454 if dir == 'suspend':
3455 m0 = testruns[data.testnumber].start
3456 mMax = testruns[data.testnumber].tSuspended
3457 mTotal = mMax - m0
3458 left = '%f' % (((m0-t0)*100.0)/tTotal)
3459 else:
3460 m0 = testruns[data.testnumber].tSuspended
3461 mMax = testruns[data.testnumber].end
203f1f98
TB
3462 # in an x2 run, remove any gap between blocks
3463 if len(testruns) > 1 and data.testnumber == 0:
3464 mMax = testruns[1].start
af1e45e6
TB
3465 mTotal = mMax - m0
3466 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
3467 # if a timeline block is 0 length, skip altogether
3468 if mTotal == 0:
3469 continue
3470 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
203f1f98 3471 devtl.html['timeline'] += html_tblock.format(bname, left, width, devtl.scaleH)
af1e45e6
TB
3472 for b in sorted(phases[dir]):
3473 # draw the phase color background
3474 phase = data.dmesg[b]
3475 length = phase['end']-phase['start']
3476 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
3477 width = '%f' % ((length*100.0)/mTotal)
3478 devtl.html['timeline'] += html_phase.format(left, width, \
3479 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
3480 data.dmesg[b]['color'], '')
03bc39be
TB
3481 for e in data.errorinfo[dir]:
3482 # draw red lines for any kernel errors found
3483 t, err = e
3484 right = '%f' % (((mMax-t)*100.0)/mTotal)
3485 devtl.html['timeline'] += html_error.format(right, err)
203f1f98 3486 for b in sorted(phases[dir]):
af1e45e6
TB
3487 # draw the devices for this phase
3488 phaselist = data.dmesg[b]['list']
3489 for d in data.tdevlist[b]:
3490 name = d
3491 drv = ''
3492 dev = phaselist[d]
3493 xtraclass = ''
3494 xtrainfo = ''
3495 xtrastyle = ''
3496 if 'htmlclass' in dev:
3497 xtraclass = dev['htmlclass']
af1e45e6
TB
3498 if 'color' in dev:
3499 xtrastyle = 'background-color:%s;' % dev['color']
3500 if(d in sysvals.devprops):
3501 name = sysvals.devprops[d].altName(d)
3502 xtraclass = sysvals.devprops[d].xtraClass()
3503 xtrainfo = sysvals.devprops[d].xtraInfo()
203f1f98
TB
3504 elif xtraclass == ' kth':
3505 xtrainfo = ' kernel_thread'
af1e45e6
TB
3506 if('drv' in dev and dev['drv']):
3507 drv = ' {%s}' % dev['drv']
203f1f98
TB
3508 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row'])
3509 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row'])
af1e45e6
TB
3510 top = '%.3f' % (rowtop + devtl.scaleH)
3511 left = '%f' % (((dev['start']-m0)*100)/mTotal)
3512 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
3513 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
203f1f98 3514 title = name+drv+xtrainfo+length
af1e45e6 3515 if sysvals.suspendmode == 'command':
1ea39643 3516 title += sysvals.testcommand
203f1f98
TB
3517 elif xtraclass == ' ps':
3518 if 'suspend' in b:
3519 title += 'pre_suspend_process'
3520 else:
3521 title += 'post_resume_process'
af1e45e6 3522 else:
203f1f98 3523 title += b
af1e45e6
TB
3524 devtl.html['timeline'] += html_device.format(dev['id'], \
3525 title, left, top, '%.3f'%rowheight, width, \
3526 d+drv, xtraclass, xtrastyle)
203f1f98
TB
3527 if('cpuexec' in dev):
3528 for t in sorted(dev['cpuexec']):
3529 start, end = t
3530 j = float(dev['cpuexec'][t]) / 5
3531 if j > 1.0:
3532 j = 1.0
3533 height = '%.3f' % (rowheight/3)
3534 top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3)
3535 left = '%f' % (((start-m0)*100)/mTotal)
3536 width = '%f' % ((end-start)*100/mTotal)
3537 color = 'rgba(255, 0, 0, %f)' % j
3538 devtl.html['timeline'] += \
3539 html_cpuexec.format(left, top, height, width, color)
af1e45e6
TB
3540 if('src' not in dev):
3541 continue
3542 # draw any trace events for this device
af1e45e6 3543 for e in dev['src']:
203f1f98 3544 height = '%.3f' % devtl.rowH
af1e45e6
TB
3545 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
3546 left = '%f' % (((e.time-m0)*100)/mTotal)
3547 width = '%f' % (e.length*100/mTotal)
1ea39643
TB
3548 xtrastyle = ''
3549 if e.color:
3550 xtrastyle = 'background:%s;' % e.color
b8432c6f 3551 devtl.html['timeline'] += \
203f1f98 3552 html_traceevent.format(e.title(), \
1ea39643 3553 left, top, height, width, e.text(), '', xtrastyle)
af1e45e6
TB
3554 # draw the time scale, try to make the number of labels readable
3555 devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir)
3556 devtl.html['timeline'] += '</div>\n'
b8432c6f
TB
3557
3558 # timeline is finished
3559 devtl.html['timeline'] += '</div>\n</div>\n'
3560
3561 # draw a legend which describes the phases by color
af1e45e6
TB
3562 if sysvals.suspendmode != 'command':
3563 data = testruns[-1]
3564 devtl.html['legend'] = '<div class="legend">\n'
3565 pdelta = 100.0/len(data.phases)
3566 pmargin = pdelta / 4.0
3567 for phase in data.phases:
3568 tmp = phase.split('_')
3569 id = tmp[0][0]
3570 if(len(tmp) > 1):
3571 id += tmp[1][0]
3572 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3573 name = string.replace(phase, '_', ' &nbsp;')
3574 devtl.html['legend'] += html_legend.format(order, \
3575 data.dmesg[phase]['color'], name, id)
3576 devtl.html['legend'] += '</div>\n'
ee8b09cd
TB
3577
3578 hf = open(sysvals.htmlfile, 'w')
af1e45e6
TB
3579
3580 if not sysvals.cgexp:
3581 cgchk = 'checked'
3582 cgnchk = 'not(:checked)'
3583 else:
3584 cgchk = 'not(:checked)'
3585 cgnchk = 'checked'
ee8b09cd 3586
b8432c6f
TB
3587 # write the html header first (html head, css code, up to body start)
3588 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
3589 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
af1e45e6 3590 <title>'+htmlTitle()+'</title>\n\
b8432c6f 3591 <style type=\'text/css\'>\n\
af1e45e6
TB
3592 body {overflow-y:scroll;}\n\
3593 .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\
3594 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
3595 .callgraph article * {padding-left:28px;}\n\
3596 h1 {color:black;font:bold 30px Times;}\n\
3597 t0 {color:black;font:bold 30px Times;}\n\
3598 t1 {color:black;font:30px Times;}\n\
3599 t2 {color:black;font:25px Times;}\n\
3600 t3 {color:black;font:20px Times;white-space:nowrap;}\n\
3601 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
03bc39be 3602 cS {font:bold 13px Times;}\n\
ee8b09cd
TB
3603 table {width:100%;}\n\
3604 .gray {background-color:rgba(80,80,80,0.1);}\n\
3605 .green {background-color:rgba(204,255,204,0.4);}\n\
3606 .purple {background-color:rgba(128,0,128,0.2);}\n\
3607 .yellow {background-color:rgba(255,255,204,0.4);}\n\
af1e45e6
TB
3608 .time1 {font:22px Arial;border:1px solid;}\n\
3609 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
3610 td {text-align:center;}\n\
b8432c6f
TB
3611 r {color:#500000;font:15px Tahoma;}\n\
3612 n {color:#505050;font:15px Tahoma;}\n\
af1e45e6
TB
3613 .tdhl {color:red;}\n\
3614 .hide {display:none;}\n\
3615 .pf {display:none;}\n\
3616 .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\
3617 .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\
3618 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
203f1f98 3619 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\
af1e45e6 3620 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
203f1f98 3621 .thread {position:absolute;height:0%;overflow:hidden;z-index:7;line-height:30px;font-size:14px;border:1px solid;text-align:center;white-space:nowrap;}\n\
203f1f98 3622 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\
af1e45e6 3623 .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
1ea39643 3624 .thread.sec,.thread.sec:hover {background-color:black;border:0;color:white;line-height:15px;font-size:10px;}\n\
af1e45e6
TB
3625 .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
3626 .hover.sync {background-color:white;}\n\
203f1f98
TB
3627 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background-color:white;}\n\
3628 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\
1ea39643
TB
3629 .traceevent {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
3630 .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\
af1e45e6 3631 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
b8432c6f 3632 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
03bc39be
TB
3633 .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\
3634 .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\
af1e45e6
TB
3635 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
3636 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
ee8b09cd 3637 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
af1e45e6 3638 .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
b8432c6f 3639 .devlist {position:'+x2changes[1]+';width:190px;}\n\
af1e45e6
TB
3640 a:link {color:white;text-decoration:none;}\n\
3641 a:visited {color:white;}\n\
3642 a:hover {color:white;}\n\
3643 a:active {color:white;}\n\
3644 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
3645 #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\
203f1f98
TB
3646 .tblock {position:absolute;height:100%;background-color:#ddd;}\n\
3647 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\
af1e45e6 3648 .bg {z-index:1;}\n\
b8432c6f 3649 </style>\n</head>\n<body>\n'
af1e45e6
TB
3650
3651 # no header or css if its embedded
3652 if(sysvals.embedded):
3653 hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
3654 (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \
3655 data.fwSuspend/1000000, data.fwResume/1000000))
3656 else:
3657 hf.write(html_header)
ee8b09cd
TB
3658
3659 # write the test title and general info header
b8432c6f 3660 if(sysvals.stamp['time'] != ""):
af1e45e6 3661 hf.write(headline_version)
03bc39be
TB
3662 if sysvals.logmsg:
3663 hf.write('<button id="showtest" class="logbtn">log</button>')
af1e45e6
TB
3664 if sysvals.addlogs and sysvals.dmesgfile:
3665 hf.write('<button id="showdmesg" class="logbtn">dmesg</button>')
3666 if sysvals.addlogs and sysvals.ftracefile:
3667 hf.write('<button id="showftrace" class="logbtn">ftrace</button>')
b8432c6f
TB
3668 hf.write(headline_stamp.format(sysvals.stamp['host'],
3669 sysvals.stamp['kernel'], sysvals.stamp['mode'], \
3670 sysvals.stamp['time']))
3671
3672 # write the device timeline
af1e45e6 3673 hf.write(devtl.html['header'])
b8432c6f
TB
3674 hf.write(devtl.html['timeline'])
3675 hf.write(devtl.html['legend'])
3676 hf.write('<div id="devicedetailtitle"></div>\n')
3677 hf.write('<div id="devicedetail" style="display:none;">\n')
3678 # draw the colored boxes for the device detail section
3679 for data in testruns:
3680 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
203f1f98
TB
3681 pscolor = 'linear-gradient(to top left, #ccc, #eee)'
3682 hf.write(html_phaselet.format('pre_suspend_process', \
3683 '0', '0', pscolor))
b8432c6f
TB
3684 for b in data.phases:
3685 phase = data.dmesg[b]
3686 length = phase['end']-phase['start']
3687 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
3688 width = '%.3f' % ((length*100.0)/tTotal)
3689 hf.write(html_phaselet.format(b, left, width, \
3690 data.dmesg[b]['color']))
203f1f98
TB
3691 hf.write(html_phaselet.format('post_resume_process', \
3692 '0', '0', pscolor))
af1e45e6 3693 if sysvals.suspendmode == 'command':
203f1f98 3694 hf.write(html_phaselet.format('cmdexec', '0', '0', pscolor))
b8432c6f
TB
3695 hf.write('</div>\n')
3696 hf.write('</div>\n')
ee8b09cd
TB
3697
3698 # write the ftrace data (callgraph)
03bc39be
TB
3699 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
3700 data = testruns[sysvals.cgtest]
3701 else:
3702 data = testruns[-1]
af1e45e6 3703 if(sysvals.usecallgraph and not sysvals.embedded):
ee8b09cd
TB
3704 hf.write('<section id="callgraphs" class="callgraph">\n')
3705 # write out the ftrace data converted to html
3706 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'
3707 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
3708 html_func_end = '</article>\n'
3709 html_func_leaf = '<article>{0} {1}</article>\n'
3710 num = 0
3711 for p in data.phases:
03bc39be
TB
3712 if sysvals.cgphase and p != sysvals.cgphase:
3713 continue
ee8b09cd
TB
3714 list = data.dmesg[p]['list']
3715 for devname in data.sortedDevices(p):
3716 if('ftrace' not in list[devname]):
3717 continue
ee8b09cd
TB
3718 devid = list[devname]['id']
3719 cg = list[devname]['ftrace']
af1e45e6
TB
3720 clen = (cg.end - cg.start) * 1000
3721 if clen < sysvals.mincglen:
3722 continue
3723 fmt = '<r>(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')</r>'
3724 flen = fmt % (clen, cg.start, cg.end)
3725 name = devname
3726 if(devname in sysvals.devprops):
3727 name = sysvals.devprops[devname].altName(devname)
3728 if sysvals.suspendmode == 'command':
3729 ftitle = name
3730 else:
3731 ftitle = name+' '+p
b8432c6f 3732 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
af1e45e6 3733 num, ftitle, flen))
ee8b09cd
TB
3734 num += 1
3735 for line in cg.list:
3736 if(line.length < 0.000000001):
b8432c6f 3737 flen = ''
ee8b09cd 3738 else:
af1e45e6
TB
3739 fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>'
3740 flen = fmt % (line.length*1000, line.time)
ee8b09cd
TB
3741 if(line.freturn and line.fcall):
3742 hf.write(html_func_leaf.format(line.name, flen))
3743 elif(line.freturn):
3744 hf.write(html_func_end)
3745 else:
3746 hf.write(html_func_start.format(num, line.name, flen))
3747 num += 1
3748 hf.write(html_func_end)
b8432c6f 3749 hf.write('\n\n </section>\n')
af1e45e6 3750
03bc39be
TB
3751 # add the test log as a hidden div
3752 if sysvals.logmsg:
3753 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
af1e45e6
TB
3754 # add the dmesg log as a hidden div
3755 if sysvals.addlogs and sysvals.dmesgfile:
3756 hf.write('<div id="dmesglog" style="display:none;">\n')
3757 lf = open(sysvals.dmesgfile, 'r')
3758 for line in lf:
03bc39be 3759 line = line.replace('<', '&lt').replace('>', '&gt')
af1e45e6
TB
3760 hf.write(line)
3761 lf.close()
3762 hf.write('</div>\n')
3763 # add the ftrace log as a hidden div
3764 if sysvals.addlogs and sysvals.ftracefile:
3765 hf.write('<div id="ftracelog" style="display:none;">\n')
3766 lf = open(sysvals.ftracefile, 'r')
3767 for line in lf:
3768 hf.write(line)
3769 lf.close()
3770 hf.write('</div>\n')
3771
3772 if(not sysvals.embedded):
3773 # write the footer and close
3774 addScriptCode(hf, testruns)
3775 hf.write('</body>\n</html>\n')
3776 else:
3777 # embedded out will be loaded in a page, skip the js
3778 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
3779 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
3780 # add js code in a div entry for later evaluation
3781 detail = 'var bounds = [%f,%f];\n' % (t0, tMax)
3782 detail += 'var devtable = [\n'
3783 for data in testruns:
3784 topo = data.deviceTopology()
3785 detail += '\t"%s",\n' % (topo)
3786 detail += '];\n'
3787 hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n')
ee8b09cd
TB
3788 hf.close()
3789 return True
3790
b8432c6f
TB
3791# Function: addScriptCode
3792# Description:
3793# Adds the javascript code to the output html
3794# Arguments:
3795# hf: the open html file pointer
3796# testruns: array of Data objects from parseKernelLog or parseTraceLog
3797def addScriptCode(hf, testruns):
af1e45e6
TB
3798 t0 = testruns[0].start * 1000
3799 tMax = testruns[-1].end * 1000
ee8b09cd 3800 # create an array in javascript memory with the device details
b8432c6f
TB
3801 detail = ' var devtable = [];\n'
3802 for data in testruns:
3803 topo = data.deviceTopology()
3804 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
3805 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
ee8b09cd
TB
3806 # add the code which will manipulate the data in the browser
3807 script_code = \
3808 '<script type="text/javascript">\n'+detail+\
af1e45e6 3809 ' var resolution = -1;\n'\
203f1f98 3810 ' var dragval = [0, 0];\n'\
af1e45e6 3811 ' function redrawTimescale(t0, tMax, tS) {\n'\
03bc39be 3812 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cS>&larr;R</cS></div>\';\n'\
af1e45e6
TB
3813 ' var tTotal = tMax - t0;\n'\
3814 ' var list = document.getElementsByClassName("tblock");\n'\
3815 ' for (var i = 0; i < list.length; i++) {\n'\
3816 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
3817 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
3818 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
3819 ' var mMax = m0 + mTotal;\n'\
3820 ' var html = "";\n'\
3821 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
3822 ' if(divTotal > 1000) continue;\n'\
3823 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
3824 ' var pos = 0.0, val = 0.0;\n'\
3825 ' for (var j = 0; j < divTotal; j++) {\n'\
3826 ' var htmlline = "";\n'\
3827 ' if(list[i].id[5] == "r") {\n'\
3828 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
3829 ' val = (j)*tS;\n'\
3830 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3831 ' if(j == 0)\n'\
3832 ' htmlline = rline;\n'\
3833 ' } else {\n'\
3834 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
3835 ' val = (j-divTotal+1)*tS;\n'\
3836 ' if(j == divTotal - 1)\n'\
03bc39be 3837 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S&rarr;</cS></div>\';\n'\
af1e45e6
TB
3838 ' else\n'\
3839 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3840 ' }\n'\
3841 ' html += htmlline;\n'\
3842 ' }\n'\
3843 ' timescale.innerHTML = html;\n'\
3844 ' }\n'\
3845 ' }\n'\
ee8b09cd 3846 ' function zoomTimeline() {\n'\
ee8b09cd
TB
3847 ' var dmesg = document.getElementById("dmesg");\n'\
3848 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
b3fc275d 3849 ' var left = zoombox.scrollLeft;\n'\
ee8b09cd
TB
3850 ' var val = parseFloat(dmesg.style.width);\n'\
3851 ' var newval = 100;\n'\
3852 ' var sh = window.outerWidth / 2;\n'\
3853 ' if(this.id == "zoomin") {\n'\
3854 ' newval = val * 1.2;\n'\
af1e45e6 3855 ' if(newval > 910034) newval = 910034;\n'\
ee8b09cd 3856 ' dmesg.style.width = newval+"%";\n'\
b3fc275d 3857 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
ee8b09cd
TB
3858 ' } else if (this.id == "zoomout") {\n'\
3859 ' newval = val / 1.2;\n'\
3860 ' if(newval < 100) newval = 100;\n'\
3861 ' dmesg.style.width = newval+"%";\n'\
b3fc275d 3862 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
ee8b09cd
TB
3863 ' } else {\n'\
3864 ' zoombox.scrollLeft = 0;\n'\
3865 ' dmesg.style.width = "100%";\n'\
3866 ' }\n'\
af1e45e6 3867 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
ee8b09cd
TB
3868 ' var t0 = bounds[0];\n'\
3869 ' var tMax = bounds[1];\n'\
3870 ' var tTotal = tMax - t0;\n'\
3871 ' var wTotal = tTotal * 100.0 / newval;\n'\
af1e45e6
TB
3872 ' var idx = 7*window.innerWidth/1100;\n'\
3873 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
3874 ' if(i >= tS.length) i = tS.length - 1;\n'\
3875 ' if(tS[i] == resolution) return;\n'\
3876 ' resolution = tS[i];\n'\
3877 ' redrawTimescale(t0, tMax, tS[i]);\n'\
ee8b09cd 3878 ' }\n'\
203f1f98
TB
3879 ' function deviceName(title) {\n'\
3880 ' var name = title.slice(0, title.indexOf(" ("));\n'\
3881 ' return name;\n'\
3882 ' }\n'\
b8432c6f 3883 ' function deviceHover() {\n'\
203f1f98 3884 ' var name = deviceName(this.title);\n'\
b8432c6f
TB
3885 ' var dmesg = document.getElementById("dmesg");\n'\
3886 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3887 ' var cpu = -1;\n'\
3888 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3889 ' cpu = parseInt(name.slice(7));\n'\
3890 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3891 ' cpu = parseInt(name.slice(8));\n'\
3892 ' for (var i = 0; i < dev.length; i++) {\n'\
203f1f98 3893 ' dname = deviceName(dev[i].title);\n'\
af1e45e6 3894 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
b8432c6f
TB
3895 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3896 ' (name == dname))\n'\
3897 ' {\n'\
af1e45e6 3898 ' dev[i].className = "hover "+cname;\n'\
b8432c6f 3899 ' } else {\n'\
af1e45e6 3900 ' dev[i].className = cname;\n'\
b8432c6f
TB
3901 ' }\n'\
3902 ' }\n'\
3903 ' }\n'\
3904 ' function deviceUnhover() {\n'\
3905 ' var dmesg = document.getElementById("dmesg");\n'\
3906 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3907 ' for (var i = 0; i < dev.length; i++) {\n'\
af1e45e6 3908 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
b8432c6f
TB
3909 ' }\n'\
3910 ' }\n'\
3911 ' function deviceTitle(title, total, cpu) {\n'\
3912 ' var prefix = "Total";\n'\
3913 ' if(total.length > 3) {\n'\
3914 ' prefix = "Average";\n'\
3915 ' total[1] = (total[1]+total[3])/2;\n'\
3916 ' total[2] = (total[2]+total[4])/2;\n'\
3917 ' }\n'\
3918 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
203f1f98 3919 ' var name = deviceName(title);\n'\
b8432c6f
TB
3920 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
3921 ' var driver = "";\n'\
3922 ' var tS = "<t2>(</t2>";\n'\
3923 ' var tR = "<t2>)</t2>";\n'\
3924 ' if(total[1] > 0)\n'\
3925 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
3926 ' if(total[2] > 0)\n'\
3927 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
3928 ' var s = title.indexOf("{");\n'\
3929 ' var e = title.indexOf("}");\n'\
3930 ' if((s >= 0) && (e >= 0))\n'\
3931 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
3932 ' if(total[1] > 0 && total[2] > 0)\n'\
3933 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
3934 ' else\n'\
3935 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
3936 ' return name;\n'\
3937 ' }\n'\
ee8b09cd 3938 ' function deviceDetail() {\n'\
b8432c6f
TB
3939 ' var devinfo = document.getElementById("devicedetail");\n'\
3940 ' devinfo.style.display = "block";\n'\
203f1f98 3941 ' var name = deviceName(this.title);\n'\
b8432c6f
TB
3942 ' var cpu = -1;\n'\
3943 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3944 ' cpu = parseInt(name.slice(7));\n'\
3945 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3946 ' cpu = parseInt(name.slice(8));\n'\
3947 ' var dmesg = document.getElementById("dmesg");\n'\
3948 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3949 ' var idlist = [];\n'\
3950 ' var pdata = [[]];\n'\
af1e45e6
TB
3951 ' if(document.getElementById("devicedetail1"))\n'\
3952 ' pdata = [[], []];\n'\
b8432c6f
TB
3953 ' var pd = pdata[0];\n'\
3954 ' var total = [0.0, 0.0, 0.0];\n'\
3955 ' for (var i = 0; i < dev.length; i++) {\n'\
203f1f98 3956 ' dname = deviceName(dev[i].title);\n'\
b8432c6f
TB
3957 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3958 ' (name == dname))\n'\
3959 ' {\n'\
3960 ' idlist[idlist.length] = dev[i].id;\n'\
3961 ' var tidx = 1;\n'\
3962 ' if(dev[i].id[0] == "a") {\n'\
3963 ' pd = pdata[0];\n'\
3964 ' } else {\n'\
3965 ' if(pdata.length == 1) pdata[1] = [];\n'\
3966 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
3967 ' pd = pdata[1];\n'\
3968 ' tidx = 3;\n'\
3969 ' }\n'\
3970 ' var info = dev[i].title.split(" ");\n'\
3971 ' var pname = info[info.length-1];\n'\
3972 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
3973 ' total[0] += pd[pname];\n'\
3974 ' if(pname.indexOf("suspend") >= 0)\n'\
3975 ' total[tidx] += pd[pname];\n'\
3976 ' else\n'\
3977 ' total[tidx+1] += pd[pname];\n'\
3978 ' }\n'\
3979 ' }\n'\
3980 ' var devname = deviceTitle(this.title, total, cpu);\n'\
3981 ' var left = 0.0;\n'\
3982 ' for (var t = 0; t < pdata.length; t++) {\n'\
3983 ' pd = pdata[t];\n'\
3984 ' devinfo = document.getElementById("devicedetail"+t);\n'\
3985 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
3986 ' for (var i = 0; i < phases.length; i++) {\n'\
3987 ' if(phases[i].id in pd) {\n'\
3988 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
3989 ' var fs = 32;\n'\
3990 ' if(w < 8) fs = 4*w | 0;\n'\
3991 ' var fs2 = fs*3/4;\n'\
3992 ' phases[i].style.width = w+"%";\n'\
3993 ' phases[i].style.left = left+"%";\n'\
3994 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
3995 ' left += w;\n'\
3996 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
203f1f98 3997 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\
b8432c6f
TB
3998 ' phases[i].innerHTML = time+pname;\n'\
3999 ' } else {\n'\
4000 ' phases[i].style.width = "0%";\n'\
4001 ' phases[i].style.left = left+"%";\n'\
4002 ' }\n'\
4003 ' }\n'\
4004 ' }\n'\
ee8b09cd
TB
4005 ' var cglist = document.getElementById("callgraphs");\n'\
4006 ' if(!cglist) return;\n'\
4007 ' var cg = cglist.getElementsByClassName("atop");\n'\
af1e45e6 4008 ' if(cg.length < 10) return;\n'\
ee8b09cd 4009 ' for (var i = 0; i < cg.length; i++) {\n'\
b8432c6f 4010 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
ee8b09cd
TB
4011 ' cg[i].style.display = "block";\n'\
4012 ' } else {\n'\
4013 ' cg[i].style.display = "none";\n'\
4014 ' }\n'\
4015 ' }\n'\
4016 ' }\n'\
b8432c6f 4017 ' function devListWindow(e) {\n'\
03bc39be 4018 ' var win = window.open();\n'\
b8432c6f
TB
4019 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
4020 ' "<style type=\\"text/css\\">"+\n'\
4021 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
4022 ' "</style>"\n'\
4023 ' var dt = devtable[0];\n'\
4024 ' if(e.target.id != "devlist1")\n'\
4025 ' dt = devtable[1];\n'\
4026 ' win.document.write(html+dt);\n'\
4027 ' }\n'\
03bc39be
TB
4028 ' function errWindow() {\n'\
4029 ' var text = this.id;\n'\
4030 ' var win = window.open();\n'\
4031 ' win.document.write("<pre>"+text+"</pre>");\n'\
4032 ' win.document.close();\n'\
4033 ' }\n'\
af1e45e6
TB
4034 ' function logWindow(e) {\n'\
4035 ' var name = e.target.id.slice(4);\n'\
4036 ' var win = window.open();\n'\
4037 ' var log = document.getElementById(name+"log");\n'\
4038 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
4039 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
4040 ' win.document.close();\n'\
4041 ' }\n'\
4042 ' function onClickPhase(e) {\n'\
4043 ' }\n'\
203f1f98
TB
4044 ' function onMouseDown(e) {\n'\
4045 ' dragval[0] = e.clientX;\n'\
4046 ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\
4047 ' document.onmousemove = onMouseMove;\n'\
4048 ' }\n'\
4049 ' function onMouseMove(e) {\n'\
4050 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4051 ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\
4052 ' }\n'\
4053 ' function onMouseUp(e) {\n'\
4054 ' document.onmousemove = null;\n'\
4055 ' }\n'\
4056 ' function onKeyPress(e) {\n'\
4057 ' var c = e.charCode;\n'\
4058 ' if(c != 42 && c != 43 && c != 45) return;\n'\
4059 ' var click = document.createEvent("Events");\n'\
4060 ' click.initEvent("click", true, false);\n'\
4061 ' if(c == 43) \n'\
4062 ' document.getElementById("zoomin").dispatchEvent(click);\n'\
4063 ' else if(c == 45)\n'\
4064 ' document.getElementById("zoomout").dispatchEvent(click);\n'\
4065 ' else if(c == 42)\n'\
4066 ' document.getElementById("zoomdef").dispatchEvent(click);\n'\
4067 ' }\n'\
af1e45e6 4068 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
ee8b09cd
TB
4069 ' window.addEventListener("load", function () {\n'\
4070 ' var dmesg = document.getElementById("dmesg");\n'\
4071 ' dmesg.style.width = "100%"\n'\
b3fc275d 4072 ' dmesg.onmousedown = onMouseDown;\n'\
203f1f98
TB
4073 ' document.onmouseup = onMouseUp;\n'\
4074 ' document.onkeypress = onKeyPress;\n'\
ee8b09cd
TB
4075 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
4076 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
4077 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
af1e45e6
TB
4078 ' var list = document.getElementsByClassName("square");\n'\
4079 ' for (var i = 0; i < list.length; i++)\n'\
4080 ' list[i].onclick = onClickPhase;\n'\
03bc39be
TB
4081 ' var list = document.getElementsByClassName("err");\n'\
4082 ' for (var i = 0; i < list.length; i++)\n'\
4083 ' list[i].onclick = errWindow;\n'\
af1e45e6
TB
4084 ' var list = document.getElementsByClassName("logbtn");\n'\
4085 ' for (var i = 0; i < list.length; i++)\n'\
4086 ' list[i].onclick = logWindow;\n'\
4087 ' list = document.getElementsByClassName("devlist");\n'\
4088 ' for (var i = 0; i < list.length; i++)\n'\
4089 ' list[i].onclick = devListWindow;\n'\
ee8b09cd
TB
4090 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4091 ' for (var i = 0; i < dev.length; i++) {\n'\
4092 ' dev[i].onclick = deviceDetail;\n'\
b8432c6f
TB
4093 ' dev[i].onmouseover = deviceHover;\n'\
4094 ' dev[i].onmouseout = deviceUnhover;\n'\
ee8b09cd
TB
4095 ' }\n'\
4096 ' zoomTimeline();\n'\
4097 ' });\n'\
4098 '</script>\n'
4099 hf.write(script_code);
4100
4101# Function: executeSuspend
4102# Description:
b8432c6f
TB
4103# Execute system suspend through the sysfs interface, then copy the output
4104# dmesg and ftrace files to the test output directory.
ee8b09cd 4105def executeSuspend():
203f1f98 4106 pm = ProcessMonitor()
b8432c6f 4107 tp = sysvals.tpath
af1e45e6
TB
4108 fwdata = []
4109 # mark the start point in the kernel ring buffer just as we start
4110 sysvals.initdmesg()
4111 # start ftrace
4112 if(sysvals.usecallgraph or sysvals.usetraceevents):
4113 print('START TRACING')
4114 sysvals.fsetVal('1', 'tracing_on')
203f1f98
TB
4115 if sysvals.useprocmon:
4116 pm.start()
b8432c6f
TB
4117 # execute however many s/r runs requested
4118 for count in range(1,sysvals.execcount+1):
203f1f98 4119 # x2delay in between test runs
b8432c6f 4120 if(count > 1 and sysvals.x2delay > 0):
03bc39be 4121 sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
203f1f98 4122 time.sleep(sysvals.x2delay/1000.0)
03bc39be 4123 sysvals.fsetVal('WAIT END', 'trace_marker')
203f1f98
TB
4124 # start message
4125 if sysvals.testcommand != '':
af1e45e6 4126 print('COMMAND START')
b8432c6f 4127 else:
af1e45e6
TB
4128 if(sysvals.rtcwake):
4129 print('SUSPEND START')
af1e45e6
TB
4130 else:
4131 print('SUSPEND START (press a key to resume)')
203f1f98
TB
4132 # set rtcwake
4133 if(sysvals.rtcwake):
4134 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
4135 sysvals.rtcWakeAlarmOn()
4136 # start of suspend trace marker
4137 if(sysvals.usecallgraph or sysvals.usetraceevents):
4138 sysvals.fsetVal('SUSPEND START', 'trace_marker')
4139 # predelay delay
4140 if(count == 1 and sysvals.predelay > 0):
03bc39be 4141 sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
203f1f98 4142 time.sleep(sysvals.predelay/1000.0)
03bc39be 4143 sysvals.fsetVal('WAIT END', 'trace_marker')
203f1f98
TB
4144 # initiate suspend or command
4145 if sysvals.testcommand != '':
1ea39643 4146 call(sysvals.testcommand+' 2>&1', shell=True);
203f1f98 4147 else:
af1e45e6
TB
4148 pf = open(sysvals.powerfile, 'w')
4149 pf.write(sysvals.suspendmode)
4150 # execution will pause here
4151 try:
4152 pf.close()
4153 except:
4154 pass
af1e45e6
TB
4155 if(sysvals.rtcwake):
4156 sysvals.rtcWakeAlarmOff()
203f1f98
TB
4157 # postdelay delay
4158 if(count == sysvals.execcount and sysvals.postdelay > 0):
03bc39be 4159 sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
203f1f98 4160 time.sleep(sysvals.postdelay/1000.0)
03bc39be 4161 sysvals.fsetVal('WAIT END', 'trace_marker')
b8432c6f
TB
4162 # return from suspend
4163 print('RESUME COMPLETE')
4164 if(sysvals.usecallgraph or sysvals.usetraceevents):
af1e45e6 4165 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
203f1f98 4166 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
af1e45e6 4167 fwdata.append(getFPDT(False))
af1e45e6
TB
4168 # stop ftrace
4169 if(sysvals.usecallgraph or sysvals.usetraceevents):
203f1f98
TB
4170 if sysvals.useprocmon:
4171 pm.stop()
af1e45e6
TB
4172 sysvals.fsetVal('0', 'tracing_on')
4173 print('CAPTURING TRACE')
4174 writeDatafileHeader(sysvals.ftracefile, fwdata)
1ea39643 4175 call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True)
af1e45e6
TB
4176 sysvals.fsetVal('', 'trace')
4177 devProps()
4178 # grab a copy of the dmesg output
4179 print('CAPTURING DMESG')
4180 writeDatafileHeader(sysvals.dmesgfile, fwdata)
4181 sysvals.getdmesg()
4182
4183def writeDatafileHeader(filename, fwdata):
b8432c6f
TB
4184 fp = open(filename, 'a')
4185 fp.write(sysvals.teststamp+'\n')
203f1f98 4186 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
af1e45e6
TB
4187 for fw in fwdata:
4188 if(fw):
4189 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
b8432c6f
TB
4190 fp.close()
4191
b8432c6f
TB
4192# Function: setUSBDevicesAuto
4193# Description:
4194# Set the autosuspend control parameter of all USB devices to auto
4195# This can be dangerous, so use at your own risk, most devices are set
4196# to always-on since the kernel cant determine if the device can
4197# properly autosuspend
4198def setUSBDevicesAuto():
af1e45e6 4199 rootCheck(True)
b8432c6f
TB
4200 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4201 if(re.match('.*/usb[0-9]*.*', dirname) and
4202 'idVendor' in filenames and 'idProduct' in filenames):
1ea39643 4203 call('echo auto > %s/power/control' % dirname, shell=True)
b8432c6f 4204 name = dirname.split('/')[-1]
1ea39643
TB
4205 desc = Popen(['cat', '%s/product' % dirname],
4206 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4207 ctrl = Popen(['cat', '%s/power/control' % dirname],
4208 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
b8432c6f
TB
4209 print('control is %s for %6s: %s' % (ctrl, name, desc))
4210
4211# Function: yesno
4212# Description:
4213# Print out an equivalent Y or N for a set of known parameter values
4214# Output:
4215# 'Y', 'N', or ' ' if the value is unknown
4216def yesno(val):
4217 yesvals = ['auto', 'enabled', 'active', '1']
4218 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
4219 if val in yesvals:
4220 return 'Y'
4221 elif val in novals:
4222 return 'N'
4223 return ' '
4224
4225# Function: ms2nice
4226# Description:
4227# Print out a very concise time string in minutes and seconds
4228# Output:
4229# The time string, e.g. "1901m16s"
4230def ms2nice(val):
4231 ms = 0
4232 try:
4233 ms = int(val)
4234 except:
4235 return 0.0
4236 m = ms / 60000
4237 s = (ms / 1000) - (m * 60)
4238 return '%3dm%2ds' % (m, s)
ee8b09cd
TB
4239
4240# Function: detectUSB
4241# Description:
b8432c6f
TB
4242# Detect all the USB hosts and devices currently connected and add
4243# a list of USB device names to sysvals for better timeline readability
af1e45e6 4244def detectUSB():
b8432c6f
TB
4245 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
4246 power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
4247 'control':'', 'persist':'', 'runtime_enabled':'',
4248 'runtime_status':'', 'runtime_usage':'',
4249 'runtime_active_time':'',
4250 'runtime_suspended_time':'',
4251 'active_duration':'',
4252 'connected_duration':''}
af1e45e6
TB
4253
4254 print('LEGEND')
4255 print('---------------------------------------------------------------------------------------------')
4256 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
4257 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
4258 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
4259 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
4260 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
4261 print(' U = runtime usage count')
4262 print('---------------------------------------------------------------------------------------------')
4263 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
4264 print('---------------------------------------------------------------------------------------------')
b8432c6f
TB
4265
4266 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4267 if(re.match('.*/usb[0-9]*.*', dirname) and
4268 'idVendor' in filenames and 'idProduct' in filenames):
4269 for i in field:
1ea39643
TB
4270 field[i] = Popen(['cat', '%s/%s' % (dirname, i)],
4271 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
ee8b09cd 4272 name = dirname.split('/')[-1]
af1e45e6 4273 for i in power:
1ea39643
TB
4274 power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)],
4275 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
af1e45e6
TB
4276 if(re.match('usb[0-9]*', name)):
4277 first = '%-8s' % name
ee8b09cd 4278 else:
af1e45e6
TB
4279 first = '%8s' % name
4280 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
4281 (first, field['idVendor'], field['idProduct'], \
4282 field['product'][0:20], field['speed'], \
4283 yesno(power['async']), \
4284 yesno(power['control']), \
4285 yesno(power['persist']), \
4286 yesno(power['runtime_enabled']), \
4287 yesno(power['runtime_status']), \
4288 power['runtime_usage'], \
4289 power['autosuspend'], \
4290 ms2nice(power['runtime_active_time']), \
4291 ms2nice(power['runtime_suspended_time']), \
4292 ms2nice(power['active_duration']), \
4293 ms2nice(power['connected_duration'])))
4294
4295# Function: devProps
4296# Description:
4297# Retrieve a list of properties for all devices in the trace log
4298def devProps(data=0):
af1e45e6
TB
4299 props = dict()
4300
4301 if data:
4302 idx = data.index(': ') + 2
4303 if idx >= len(data):
4304 return
4305 devlist = data[idx:].split(';')
4306 for dev in devlist:
4307 f = dev.split(',')
4308 if len(f) < 3:
4309 continue
4310 dev = f[0]
4311 props[dev] = DevProps()
4312 props[dev].altname = f[1]
4313 if int(f[2]):
4314 props[dev].async = True
4315 else:
4316 props[dev].async = False
4317 sysvals.devprops = props
4318 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4319 sysvals.testcommand = props['testcommandstring'].altname
4320 return
4321
4322 if(os.path.exists(sysvals.ftracefile) == False):
03bc39be 4323 doError('%s does not exist' % sysvals.ftracefile)
af1e45e6
TB
4324
4325 # first get the list of devices we need properties for
4326 msghead = 'Additional data added by AnalyzeSuspend'
4327 alreadystamped = False
4328 tp = TestProps()
4329 tf = open(sysvals.ftracefile, 'r')
4330 for line in tf:
4331 if msghead in line:
4332 alreadystamped = True
4333 continue
4334 # determine the trace data type (required for further parsing)
4335 m = re.match(sysvals.tracertypefmt, line)
4336 if(m):
4337 tp.setTracerType(m.group('t'))
4338 continue
4339 # parse only valid lines, if this is not one move on
4340 m = re.match(tp.ftrace_line_fmt, line)
4341 if(not m or 'device_pm_callback_start' not in line):
4342 continue
4343 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
4344 if(not m):
4345 continue
03bc39be 4346 dev = m.group('d')
af1e45e6
TB
4347 if dev not in props:
4348 props[dev] = DevProps()
4349 tf.close()
4350
4351 if not alreadystamped and sysvals.suspendmode == 'command':
4352 out = '#\n# '+msghead+'\n# Device Properties: '
4353 out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
4354 with open(sysvals.ftracefile, 'a') as fp:
4355 fp.write(out+'\n')
4356 sysvals.devprops = props
4357 return
4358
4359 # now get the syspath for each of our target devices
4360 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4361 if(re.match('.*/power', dirname) and 'async' in filenames):
4362 dev = dirname.split('/')[-2]
4363 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
4364 props[dev].syspath = dirname[:-6]
4365
4366 # now fill in the properties for our target devices
4367 for dev in props:
4368 dirname = props[dev].syspath
4369 if not dirname or not os.path.exists(dirname):
4370 continue
4371 with open(dirname+'/power/async') as fp:
4372 text = fp.read()
4373 props[dev].async = False
4374 if 'enabled' in text:
4375 props[dev].async = True
4376 fields = os.listdir(dirname)
4377 if 'product' in fields:
4378 with open(dirname+'/product') as fp:
4379 props[dev].altname = fp.read()
4380 elif 'name' in fields:
4381 with open(dirname+'/name') as fp:
4382 props[dev].altname = fp.read()
4383 elif 'model' in fields:
4384 with open(dirname+'/model') as fp:
4385 props[dev].altname = fp.read()
4386 elif 'description' in fields:
4387 with open(dirname+'/description') as fp:
4388 props[dev].altname = fp.read()
4389 elif 'id' in fields:
4390 with open(dirname+'/id') as fp:
4391 props[dev].altname = fp.read()
4392 elif 'idVendor' in fields and 'idProduct' in fields:
4393 idv, idp = '', ''
4394 with open(dirname+'/idVendor') as fp:
4395 idv = fp.read().strip()
4396 with open(dirname+'/idProduct') as fp:
4397 idp = fp.read().strip()
4398 props[dev].altname = '%s:%s' % (idv, idp)
4399
4400 if props[dev].altname:
4401 out = props[dev].altname.strip().replace('\n', ' ')
4402 out = out.replace(',', ' ')
4403 out = out.replace(';', ' ')
4404 props[dev].altname = out
4405
4406 # and now write the data to the ftrace file
4407 if not alreadystamped:
4408 out = '#\n# '+msghead+'\n# Device Properties: '
4409 for dev in sorted(props):
4410 out += props[dev].out(dev)
4411 with open(sysvals.ftracefile, 'a') as fp:
4412 fp.write(out+'\n')
4413
4414 sysvals.devprops = props
b8432c6f
TB
4415
4416# Function: getModes
4417# Description:
4418# Determine the supported power modes on this system
4419# Output:
4420# A string list of the available modes
ee8b09cd 4421def getModes():
b8432c6f 4422 modes = ''
af1e45e6
TB
4423 if(os.path.exists(sysvals.powerfile)):
4424 fp = open(sysvals.powerfile, 'r')
4425 modes = string.split(fp.read())
4426 fp.close()
ee8b09cd
TB
4427 return modes
4428
b8432c6f
TB
4429# Function: getFPDT
4430# Description:
4431# Read the acpi bios tables and pull out FPDT, the firmware data
4432# Arguments:
4433# output: True to output the info to stdout, False otherwise
4434def getFPDT(output):
b8432c6f
TB
4435 rectype = {}
4436 rectype[0] = 'Firmware Basic Boot Performance Record'
4437 rectype[1] = 'S3 Performance Table Record'
4438 prectype = {}
4439 prectype[0] = 'Basic S3 Resume Performance Record'
4440 prectype[1] = 'Basic S3 Suspend Performance Record'
4441
af1e45e6 4442 rootCheck(True)
b8432c6f
TB
4443 if(not os.path.exists(sysvals.fpdtpath)):
4444 if(output):
03bc39be 4445 doError('file does not exist: %s' % sysvals.fpdtpath)
b8432c6f
TB
4446 return False
4447 if(not os.access(sysvals.fpdtpath, os.R_OK)):
4448 if(output):
03bc39be 4449 doError('file is not readable: %s' % sysvals.fpdtpath)
b8432c6f
TB
4450 return False
4451 if(not os.path.exists(sysvals.mempath)):
4452 if(output):
03bc39be 4453 doError('file does not exist: %s' % sysvals.mempath)
b8432c6f
TB
4454 return False
4455 if(not os.access(sysvals.mempath, os.R_OK)):
4456 if(output):
03bc39be 4457 doError('file is not readable: %s' % sysvals.mempath)
b8432c6f
TB
4458 return False
4459
4460 fp = open(sysvals.fpdtpath, 'rb')
4461 buf = fp.read()
4462 fp.close()
4463
4464 if(len(buf) < 36):
4465 if(output):
4466 doError('Invalid FPDT table data, should '+\
03bc39be 4467 'be at least 36 bytes')
b8432c6f
TB
4468 return False
4469
4470 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
4471 if(output):
4472 print('')
4473 print('Firmware Performance Data Table (%s)' % table[0])
4474 print(' Signature : %s' % table[0])
4475 print(' Table Length : %u' % table[1])
4476 print(' Revision : %u' % table[2])
4477 print(' Checksum : 0x%x' % table[3])
4478 print(' OEM ID : %s' % table[4])
4479 print(' OEM Table ID : %s' % table[5])
4480 print(' OEM Revision : %u' % table[6])
4481 print(' Creator ID : %s' % table[7])
4482 print(' Creator Revision : 0x%x' % table[8])
4483 print('')
4484
4485 if(table[0] != 'FPDT'):
4486 if(output):
4487 doError('Invalid FPDT table')
4488 return False
4489 if(len(buf) <= 36):
4490 return False
4491 i = 0
4492 fwData = [0, 0]
4493 records = buf[36:]
4494 fp = open(sysvals.mempath, 'rb')
4495 while(i < len(records)):
4496 header = struct.unpack('HBB', records[i:i+4])
4497 if(header[0] not in rectype):
af1e45e6 4498 i += header[1]
b8432c6f
TB
4499 continue
4500 if(header[1] != 16):
af1e45e6 4501 i += header[1]
b8432c6f
TB
4502 continue
4503 addr = struct.unpack('Q', records[i+8:i+16])[0]
4504 try:
4505 fp.seek(addr)
4506 first = fp.read(8)
4507 except:
af1e45e6
TB
4508 if(output):
4509 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
4510 return [0, 0]
b8432c6f
TB
4511 rechead = struct.unpack('4sI', first)
4512 recdata = fp.read(rechead[1]-8)
4513 if(rechead[0] == 'FBPT'):
4514 record = struct.unpack('HBBIQQQQQ', recdata)
4515 if(output):
4516 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4517 print(' Reset END : %u ns' % record[4])
4518 print(' OS Loader LoadImage Start : %u ns' % record[5])
4519 print(' OS Loader StartImage Start : %u ns' % record[6])
4520 print(' ExitBootServices Entry : %u ns' % record[7])
4521 print(' ExitBootServices Exit : %u ns' % record[8])
4522 elif(rechead[0] == 'S3PT'):
4523 if(output):
4524 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4525 j = 0
4526 while(j < len(recdata)):
4527 prechead = struct.unpack('HBB', recdata[j:j+4])
4528 if(prechead[0] not in prectype):
4529 continue
4530 if(prechead[0] == 0):
4531 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
4532 fwData[1] = record[2]
4533 if(output):
4534 print(' %s' % prectype[prechead[0]])
4535 print(' Resume Count : %u' % \
4536 record[1])
4537 print(' FullResume : %u ns' % \
4538 record[2])
4539 print(' AverageResume : %u ns' % \
4540 record[3])
4541 elif(prechead[0] == 1):
4542 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
4543 fwData[0] = record[1] - record[0]
4544 if(output):
4545 print(' %s' % prectype[prechead[0]])
4546 print(' SuspendStart : %u ns' % \
4547 record[0])
4548 print(' SuspendEnd : %u ns' % \
4549 record[1])
4550 print(' SuspendTime : %u ns' % \
4551 fwData[0])
4552 j += prechead[1]
4553 if(output):
4554 print('')
4555 i += header[1]
4556 fp.close()
4557 return fwData
4558
ee8b09cd
TB
4559# Function: statusCheck
4560# Description:
b8432c6f
TB
4561# Verify that the requested command and options will work, and
4562# print the results to the terminal
4563# Output:
4564# True if the test will work, False if not
af1e45e6 4565def statusCheck(probecheck=False):
b8432c6f 4566 status = True
ee8b09cd 4567
af1e45e6 4568 print('Checking this system (%s)...' % platform.node())
ee8b09cd
TB
4569
4570 # check we have root access
af1e45e6
TB
4571 res = sysvals.colorText('NO (No features of this tool will work!)')
4572 if(rootCheck(False)):
4573 res = 'YES'
b8432c6f
TB
4574 print(' have root access: %s' % res)
4575 if(res != 'YES'):
af1e45e6 4576 print(' Try running this script with sudo')
b8432c6f 4577 return False
ee8b09cd
TB
4578
4579 # check sysfs is mounted
af1e45e6
TB
4580 res = sysvals.colorText('NO (No features of this tool will work!)')
4581 if(os.path.exists(sysvals.powerfile)):
4582 res = 'YES'
b8432c6f
TB
4583 print(' is sysfs mounted: %s' % res)
4584 if(res != 'YES'):
4585 return False
ee8b09cd
TB
4586
4587 # check target mode is a valid mode
af1e45e6
TB
4588 if sysvals.suspendmode != 'command':
4589 res = sysvals.colorText('NO')
4590 modes = getModes()
4591 if(sysvals.suspendmode in modes):
4592 res = 'YES'
4593 else:
4594 status = False
4595 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
4596 if(res == 'NO'):
4597 print(' valid power modes are: %s' % modes)
4598 print(' please choose one with -m')
ee8b09cd
TB
4599
4600 # check if ftrace is available
af1e45e6
TB
4601 res = sysvals.colorText('NO')
4602 ftgood = sysvals.verifyFtrace()
b8432c6f
TB
4603 if(ftgood):
4604 res = 'YES'
4605 elif(sysvals.usecallgraph):
4606 status = False
4607 print(' is ftrace supported: %s' % res)
4608
af1e45e6
TB
4609 # check if kprobes are available
4610 res = sysvals.colorText('NO')
4611 sysvals.usekprobes = sysvals.verifyKprobes()
4612 if(sysvals.usekprobes):
4613 res = 'YES'
4614 else:
4615 sysvals.usedevsrc = False
4616 print(' are kprobes supported: %s' % res)
4617
b8432c6f
TB
4618 # what data source are we using
4619 res = 'DMESG'
4620 if(ftgood):
4621 sysvals.usetraceeventsonly = True
4622 sysvals.usetraceevents = False
4623 for e in sysvals.traceevents:
4624 check = False
af1e45e6
TB
4625 if(os.path.exists(sysvals.epath+e)):
4626 check = True
b8432c6f
TB
4627 if(not check):
4628 sysvals.usetraceeventsonly = False
4629 if(e == 'suspend_resume' and check):
4630 sysvals.usetraceevents = True
4631 if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
4632 res = 'FTRACE (all trace events found)'
4633 elif(sysvals.usetraceevents):
4634 res = 'DMESG and FTRACE (suspend_resume trace event found)'
4635 print(' timeline data source: %s' % res)
ee8b09cd
TB
4636
4637 # check if rtcwake
af1e45e6 4638 res = sysvals.colorText('NO')
b8432c6f
TB
4639 if(sysvals.rtcpath != ''):
4640 res = 'YES'
4641 elif(sysvals.rtcwake):
4642 status = False
4643 print(' is rtcwake supported: %s' % res)
ee8b09cd 4644
af1e45e6
TB
4645 if not probecheck:
4646 return status
4647
1ea39643 4648 # verify kprobes
03bc39be
TB
4649 if sysvals.usekprobes:
4650 for name in sysvals.tracefuncs:
4651 sysvals.defaultKprobe(name, sysvals.tracefuncs[name])
4652 if sysvals.usedevsrc:
4653 for name in sysvals.dev_tracefuncs:
4654 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])
4655 sysvals.addKprobes(True)
af1e45e6 4656
b8432c6f 4657 return status
ee8b09cd 4658
b8432c6f
TB
4659# Function: doError
4660# Description:
4661# generic error function for catastrphic failures
4662# Arguments:
4663# msg: the error message to print
4664# help: True if printHelp should be called after, False otherwise
03bc39be 4665def doError(msg, help=False):
ee8b09cd
TB
4666 if(help == True):
4667 printHelp()
b8432c6f 4668 print('ERROR: %s\n') % msg
ee8b09cd
TB
4669 sys.exit()
4670
b8432c6f
TB
4671# Function: rootCheck
4672# Description:
4673# quick check to see if we have root access
af1e45e6 4674def rootCheck(fatal):
af1e45e6
TB
4675 if(os.access(sysvals.powerfile, os.W_OK)):
4676 return True
4677 if fatal:
03bc39be 4678 doError('This command must be run as root')
af1e45e6 4679 return False
ee8b09cd 4680
b8432c6f
TB
4681# Function: getArgInt
4682# Description:
4683# pull out an integer argument from the command line with checks
af1e45e6
TB
4684def getArgInt(name, args, min, max, main=True):
4685 if main:
4686 try:
4687 arg = args.next()
4688 except:
4689 doError(name+': no argument supplied', True)
4690 else:
4691 arg = args
b8432c6f
TB
4692 try:
4693 val = int(arg)
4694 except:
4695 doError(name+': non-integer value given', True)
4696 if(val < min or val > max):
4697 doError(name+': value should be between %d and %d' % (min, max), True)
4698 return val
4699
af1e45e6
TB
4700# Function: getArgFloat
4701# Description:
4702# pull out a float argument from the command line with checks
4703def getArgFloat(name, args, min, max, main=True):
4704 if main:
4705 try:
4706 arg = args.next()
4707 except:
4708 doError(name+': no argument supplied', True)
4709 else:
4710 arg = args
4711 try:
4712 val = float(arg)
4713 except:
4714 doError(name+': non-numerical value given', True)
4715 if(val < min or val > max):
4716 doError(name+': value should be between %f and %f' % (min, max), True)
4717 return val
4718
03bc39be 4719def processData():
b8432c6f
TB
4720 print('PROCESSING DATA')
4721 if(sysvals.usetraceeventsonly):
4722 testruns = parseTraceLog()
03bc39be
TB
4723 if sysvals.dmesgfile:
4724 dmesgtext = loadKernelLog(True)
4725 for data in testruns:
4726 data.extractErrorInfo(dmesgtext)
b8432c6f
TB
4727 else:
4728 testruns = loadKernelLog()
4729 for data in testruns:
4730 parseKernelLog(data)
03bc39be 4731 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
b8432c6f
TB
4732 appendIncompleteTraceLog(testruns)
4733 createHTML(testruns)
4734
03bc39be
TB
4735# Function: rerunTest
4736# Description:
4737# generate an output from an existing set of ftrace/dmesg logs
4738def rerunTest():
4739 if sysvals.ftracefile:
4740 doesTraceLogHaveTraceEvents()
4741 if not sysvals.dmesgfile and not sysvals.usetraceeventsonly:
4742 doError('recreating this html output requires a dmesg file')
4743 sysvals.setOutputFile()
4744 vprint('Output file: %s' % sysvals.htmlfile)
4745 if(os.path.exists(sysvals.htmlfile) and not os.access(sysvals.htmlfile, os.W_OK)):
4746 doError('missing permission to write to %s' % sysvals.htmlfile)
4747 processData()
4748
b8432c6f
TB
4749# Function: runTest
4750# Description:
4751# execute a suspend/resume, gather the logs, and generate the output
af1e45e6 4752def runTest(subdir, testpath=''):
b8432c6f 4753 # prepare for the test
af1e45e6
TB
4754 sysvals.initFtrace()
4755 sysvals.initTestOutput(subdir, testpath)
03bc39be
TB
4756 vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
4757 (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
b8432c6f
TB
4758
4759 # execute the test
af1e45e6
TB
4760 executeSuspend()
4761 sysvals.cleanupFtrace()
03bc39be 4762 processData()
b8432c6f 4763
1ea39643
TB
4764 # if running as root, change output dir owner to sudo_user
4765 if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \
4766 'SUDO_USER' in os.environ:
4767 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
4768 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
b8432c6f
TB
4769
4770# Function: runSummary
4771# Description:
4772# create a summary of tests in a sub-directory
4773def runSummary(subdir, output):
b8432c6f
TB
4774 # get a list of ftrace output files
4775 files = []
4776 for dirname, dirnames, filenames in os.walk(subdir):
4777 for filename in filenames:
4778 if(re.match('.*_ftrace.txt', filename)):
4779 files.append("%s/%s" % (dirname, filename))
4780
4781 # process the files in order and get an array of data objects
4782 testruns = []
4783 for file in sorted(files):
4784 if output:
4785 print("Test found in %s" % os.path.dirname(file))
4786 sysvals.ftracefile = file
4787 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt')
4788 doesTraceLogHaveTraceEvents()
4789 sysvals.usecallgraph = False
4790 if not sysvals.usetraceeventsonly:
4791 if(not os.path.exists(sysvals.dmesgfile)):
4792 print("Skipping %s: not a valid test input" % file)
4793 continue
4794 else:
4795 if output:
4796 f = os.path.basename(sysvals.ftracefile)
4797 d = os.path.basename(sysvals.dmesgfile)
4798 print("\tInput files: %s and %s" % (f, d))
4799 testdata = loadKernelLog()
4800 data = testdata[0]
4801 parseKernelLog(data)
4802 testdata = [data]
4803 appendIncompleteTraceLog(testdata)
4804 else:
4805 if output:
4806 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
4807 testdata = parseTraceLog()
4808 data = testdata[0]
4809 data.normalizeTime(data.tSuspended)
4810 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
4811 data.outfile = link
4812 testruns.append(data)
4813
4814 createHTMLSummarySimple(testruns, subdir+'/summary.html')
4815
af1e45e6
TB
4816# Function: checkArgBool
4817# Description:
4818# check if a boolean string value is true or false
4819def checkArgBool(value):
4820 yes = ['1', 'true', 'yes', 'on']
4821 if value.lower() in yes:
4822 return True
4823 return False
4824
4825# Function: configFromFile
4826# Description:
4827# Configure the script via the info in a config file
4828def configFromFile(file):
af1e45e6
TB
4829 Config = ConfigParser.ConfigParser()
4830
af1e45e6
TB
4831 Config.read(file)
4832 sections = Config.sections()
1ea39643
TB
4833 overridekprobes = False
4834 overridedevkprobes = False
af1e45e6
TB
4835 if 'Settings' in sections:
4836 for opt in Config.options('Settings'):
4837 value = Config.get('Settings', opt).lower()
4838 if(opt.lower() == 'verbose'):
4839 sysvals.verbose = checkArgBool(value)
4840 elif(opt.lower() == 'addlogs'):
4841 sysvals.addlogs = checkArgBool(value)
4842 elif(opt.lower() == 'dev'):
4843 sysvals.usedevsrc = checkArgBool(value)
203f1f98
TB
4844 elif(opt.lower() == 'proc'):
4845 sysvals.useprocmon = checkArgBool(value)
af1e45e6
TB
4846 elif(opt.lower() == 'x2'):
4847 if checkArgBool(value):
4848 sysvals.execcount = 2
4849 elif(opt.lower() == 'callgraph'):
4850 sysvals.usecallgraph = checkArgBool(value)
1ea39643
TB
4851 elif(opt.lower() == 'override-timeline-functions'):
4852 overridekprobes = checkArgBool(value)
4853 elif(opt.lower() == 'override-dev-timeline-functions'):
4854 overridedevkprobes = checkArgBool(value)
203f1f98
TB
4855 elif(opt.lower() == 'devicefilter'):
4856 sysvals.setDeviceFilter(value)
af1e45e6
TB
4857 elif(opt.lower() == 'expandcg'):
4858 sysvals.cgexp = checkArgBool(value)
4859 elif(opt.lower() == 'srgap'):
4860 if checkArgBool(value):
4861 sysvals.srgap = 5
4862 elif(opt.lower() == 'mode'):
4863 sysvals.suspendmode = value
4864 elif(opt.lower() == 'command'):
4865 sysvals.testcommand = value
4866 elif(opt.lower() == 'x2delay'):
4867 sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
203f1f98
TB
4868 elif(opt.lower() == 'predelay'):
4869 sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False)
4870 elif(opt.lower() == 'postdelay'):
4871 sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False)
af1e45e6
TB
4872 elif(opt.lower() == 'rtcwake'):
4873 sysvals.rtcwake = True
4874 sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
4875 elif(opt.lower() == 'timeprec'):
4876 sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
4877 elif(opt.lower() == 'mindev'):
4878 sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
1ea39643
TB
4879 elif(opt.lower() == 'callloop-maxgap'):
4880 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False)
4881 elif(opt.lower() == 'callloop-maxlen'):
4882 sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False)
af1e45e6
TB
4883 elif(opt.lower() == 'mincg'):
4884 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
af1e45e6 4885 elif(opt.lower() == 'output-dir'):
203f1f98 4886 sysvals.setOutputFolder(value)
af1e45e6
TB
4887
4888 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
03bc39be 4889 doError('No command supplied for mode "command"')
203f1f98
TB
4890
4891 # compatibility errors
af1e45e6 4892 if sysvals.usedevsrc and sysvals.usecallgraph:
03bc39be 4893 doError('-dev is not compatible with -f')
203f1f98 4894 if sysvals.usecallgraph and sysvals.useprocmon:
03bc39be 4895 doError('-proc is not compatible with -f')
af1e45e6 4896
1ea39643
TB
4897 if overridekprobes:
4898 sysvals.tracefuncs = dict()
4899 if overridedevkprobes:
4900 sysvals.dev_tracefuncs = dict()
af1e45e6
TB
4901
4902 kprobes = dict()
1ea39643
TB
4903 kprobesec = 'dev_timeline_functions_'+platform.machine()
4904 if kprobesec in sections:
4905 for name in Config.options(kprobesec):
4906 text = Config.get(kprobesec, name)
4907 kprobes[name] = (text, True)
4908 kprobesec = 'timeline_functions_'+platform.machine()
4909 if kprobesec in sections:
4910 for name in Config.options(kprobesec):
4911 if name in kprobes:
03bc39be 4912 doError('Duplicate timeline function found "%s"' % (name))
1ea39643
TB
4913 text = Config.get(kprobesec, name)
4914 kprobes[name] = (text, False)
af1e45e6
TB
4915
4916 for name in kprobes:
4917 function = name
4918 format = name
4919 color = ''
4920 args = dict()
1ea39643
TB
4921 text, dev = kprobes[name]
4922 data = text.split()
af1e45e6
TB
4923 i = 0
4924 for val in data:
4925 # bracketted strings are special formatting, read them separately
4926 if val[0] == '[' and val[-1] == ']':
4927 for prop in val[1:-1].split(','):
4928 p = prop.split('=')
4929 if p[0] == 'color':
4930 try:
4931 color = int(p[1], 16)
4932 color = '#'+p[1]
4933 except:
4934 color = p[1]
4935 continue
4936 # first real arg should be the format string
4937 if i == 0:
4938 format = val
4939 # all other args are actual function args
4940 else:
4941 d = val.split('=')
4942 args[d[0]] = d[1]
4943 i += 1
4944 if not function or not format:
03bc39be 4945 doError('Invalid kprobe: %s' % name)
af1e45e6
TB
4946 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
4947 if arg not in args:
03bc39be 4948 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
1ea39643 4949 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
03bc39be 4950 doError('Duplicate timeline function found "%s"' % (name))
1ea39643
TB
4951
4952 kp = {
af1e45e6
TB
4953 'name': name,
4954 'func': function,
4955 'format': format,
1ea39643 4956 sysvals.archargs: args
af1e45e6
TB
4957 }
4958 if color:
1ea39643
TB
4959 kp['color'] = color
4960 if dev:
4961 sysvals.dev_tracefuncs[name] = kp
4962 else:
4963 sysvals.tracefuncs[name] = kp
af1e45e6 4964
b8432c6f
TB
4965# Function: printHelp
4966# Description:
4967# print out the help text
4968def printHelp():
b8432c6f
TB
4969 modes = getModes()
4970
4971 print('')
af1e45e6 4972 print('AnalyzeSuspend v%s' % sysvals.version)
b8432c6f
TB
4973 print('Usage: sudo analyze_suspend.py <options>')
4974 print('')
4975 print('Description:')
4976 print(' This tool is designed to assist kernel and OS developers in optimizing')
4977 print(' their linux stack\'s suspend/resume time. Using a kernel image built')
4978 print(' with a few extra options enabled, the tool will execute a suspend and')
4979 print(' capture dmesg and ftrace data until resume is complete. This data is')
4980 print(' transformed into a device timeline and an optional callgraph to give')
4981 print(' a detailed view of which devices/subsystems are taking the most')
4982 print(' time in suspend/resume.')
4983 print('')
4984 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
4985 print(' HTML output: <hostname>_<mode>.html')
4986 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
4987 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
4988 print('')
4989 print('Options:')
4990 print(' [general]')
203f1f98
TB
4991 print(' -h Print this help text')
4992 print(' -v Print the current tool version')
4993 print(' -config fn Pull arguments and config options from file fn')
4994 print(' -verbose Print extra information during execution and analysis')
4995 print(' -status Test to see if the system is enabled to run this tool')
4996 print(' -modes List available suspend modes')
4997 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
4998 print(' -o subdir Override the output subdirectory')
4999 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
5000 print(' -addlogs Add the dmesg and ftrace logs to the html output')
5001 print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
b8432c6f 5002 print(' [advanced]')
203f1f98
TB
5003 print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"')
5004 print(' -proc Add usermode process info into the timeline (default: disabled)')
5005 print(' -dev Add kernel function calls and threads to the timeline (default: disabled)')
5006 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
5007 print(' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)')
5008 print(' -predelay t Include t ms delay before 1st suspend (default: 0 ms)')
5009 print(' -postdelay t Include t ms delay after last resume (default: 0 ms)')
5010 print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
5011 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
af1e45e6 5012 print(' be created in a new subdirectory with a summary page.')
af1e45e6 5013 print(' [debug]')
203f1f98
TB
5014 print(' -f Use ftrace to create device callgraphs (default: disabled)')
5015 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
5016 print(' -flist Print the list of functions currently being captured in ftrace')
5017 print(' -flistall Print all functions capable of being captured in ftrace')
5018 print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
5019 print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names')
5020 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
03bc39be
TB
5021 print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)')
5022 print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
203f1f98 5023 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
b8432c6f 5024 print(' [utilities]')
203f1f98
TB
5025 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
5026 print(' -usbtopo Print out the current USB topology with power info')
5027 print(' -usbauto Enable autosuspend for all connected USB devices')
b8432c6f 5028 print(' [re-analyze data from previous runs]')
203f1f98
TB
5029 print(' -ftrace ftracefile Create HTML output using ftrace input')
5030 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)')
5031 print(' -summary directory Create a summary of all test in this dir')
b8432c6f
TB
5032 print('')
5033 return True
ee8b09cd 5034
b8432c6f
TB
5035# ----------------- MAIN --------------------
5036# exec start (skipped if script is loaded as library)
5037if __name__ == '__main__':
5038 cmd = ''
5039 cmdarg = ''
5040 multitest = {'run': False, 'count': 0, 'delay': 0}
af1e45e6 5041 simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
b8432c6f
TB
5042 # loop through the command line arguments
5043 args = iter(sys.argv[1:])
5044 for arg in args:
5045 if(arg == '-m'):
5046 try:
5047 val = args.next()
5048 except:
5049 doError('No mode supplied', True)
af1e45e6
TB
5050 if val == 'command' and not sysvals.testcommand:
5051 doError('No command supplied for mode "command"', True)
b8432c6f 5052 sysvals.suspendmode = val
af1e45e6
TB
5053 elif(arg in simplecmds):
5054 cmd = arg[1:]
5055 elif(arg == '-h'):
5056 printHelp()
5057 sys.exit()
5058 elif(arg == '-v'):
5059 print("Version %s" % sysvals.version)
5060 sys.exit()
b8432c6f 5061 elif(arg == '-x2'):
b8432c6f
TB
5062 sysvals.execcount = 2
5063 elif(arg == '-x2delay'):
5064 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
203f1f98
TB
5065 elif(arg == '-predelay'):
5066 sysvals.predelay = getArgInt('-predelay', args, 0, 60000)
5067 elif(arg == '-postdelay'):
5068 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
b8432c6f
TB
5069 elif(arg == '-f'):
5070 sysvals.usecallgraph = True
af1e45e6
TB
5071 elif(arg == '-addlogs'):
5072 sysvals.addlogs = True
b8432c6f
TB
5073 elif(arg == '-verbose'):
5074 sysvals.verbose = True
203f1f98
TB
5075 elif(arg == '-proc'):
5076 sysvals.useprocmon = True
af1e45e6
TB
5077 elif(arg == '-dev'):
5078 sysvals.usedevsrc = True
b8432c6f
TB
5079 elif(arg == '-rtcwake'):
5080 sysvals.rtcwake = True
5081 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
af1e45e6
TB
5082 elif(arg == '-timeprec'):
5083 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
5084 elif(arg == '-mindev'):
5085 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
5086 elif(arg == '-mincg'):
5087 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
03bc39be
TB
5088 elif(arg == '-cgtest'):
5089 sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
5090 elif(arg == '-cgphase'):
5091 try:
5092 val = args.next()
5093 except:
5094 doError('No phase name supplied', True)
5095 d = Data(0)
5096 if val not in d.phases:
5097 doError('Invalid phase, valid phaess are %s' % d.phases, True)
5098 sysvals.cgphase = val
1ea39643
TB
5099 elif(arg == '-callloop-maxgap'):
5100 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
5101 elif(arg == '-callloop-maxlen'):
5102 sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)
af1e45e6
TB
5103 elif(arg == '-cmd'):
5104 try:
5105 val = args.next()
5106 except:
5107 doError('No command string supplied', True)
5108 sysvals.testcommand = val
5109 sysvals.suspendmode = 'command'
5110 elif(arg == '-expandcg'):
5111 sysvals.cgexp = True
5112 elif(arg == '-srgap'):
5113 sysvals.srgap = 5
b8432c6f
TB
5114 elif(arg == '-multi'):
5115 multitest['run'] = True
5116 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
5117 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
af1e45e6
TB
5118 elif(arg == '-o'):
5119 try:
5120 val = args.next()
5121 except:
5122 doError('No subdirectory name supplied', True)
203f1f98 5123 sysvals.setOutputFolder(val)
af1e45e6
TB
5124 elif(arg == '-config'):
5125 try:
5126 val = args.next()
5127 except:
5128 doError('No text file supplied', True)
5129 if(os.path.exists(val) == False):
03bc39be 5130 doError('%s does not exist' % val)
af1e45e6
TB
5131 configFromFile(val)
5132 elif(arg == '-fadd'):
5133 try:
5134 val = args.next()
5135 except:
5136 doError('No text file supplied', True)
5137 if(os.path.exists(val) == False):
03bc39be 5138 doError('%s does not exist' % val)
af1e45e6 5139 sysvals.addFtraceFilterFunctions(val)
b8432c6f
TB
5140 elif(arg == '-dmesg'):
5141 try:
5142 val = args.next()
5143 except:
5144 doError('No dmesg file supplied', True)
5145 sysvals.notestrun = True
5146 sysvals.dmesgfile = val
5147 if(os.path.exists(sysvals.dmesgfile) == False):
03bc39be 5148 doError('%s does not exist' % sysvals.dmesgfile)
b8432c6f
TB
5149 elif(arg == '-ftrace'):
5150 try:
5151 val = args.next()
5152 except:
5153 doError('No ftrace file supplied', True)
5154 sysvals.notestrun = True
b8432c6f
TB
5155 sysvals.ftracefile = val
5156 if(os.path.exists(sysvals.ftracefile) == False):
03bc39be 5157 doError('%s does not exist' % sysvals.ftracefile)
b8432c6f
TB
5158 elif(arg == '-summary'):
5159 try:
5160 val = args.next()
5161 except:
5162 doError('No directory supplied', True)
5163 cmd = 'summary'
5164 cmdarg = val
5165 sysvals.notestrun = True
5166 if(os.path.isdir(val) == False):
03bc39be 5167 doError('%s is not accesible' % val)
b8432c6f
TB
5168 elif(arg == '-filter'):
5169 try:
5170 val = args.next()
5171 except:
5172 doError('No devnames supplied', True)
5173 sysvals.setDeviceFilter(val)
b8432c6f
TB
5174 else:
5175 doError('Invalid argument: '+arg, True)
5176
203f1f98 5177 # compatibility errors
203f1f98 5178 if(sysvals.usecallgraph and sysvals.usedevsrc):
03bc39be 5179 doError('-dev is not compatible with -f')
203f1f98 5180 if(sysvals.usecallgraph and sysvals.useprocmon):
03bc39be 5181 doError('-proc is not compatible with -f')
203f1f98 5182
af1e45e6
TB
5183 # callgraph size cannot exceed device size
5184 if sysvals.mincglen < sysvals.mindevlen:
5185 sysvals.mincglen = sysvals.mindevlen
5186
b8432c6f
TB
5187 # just run a utility command and exit
5188 if(cmd != ''):
5189 if(cmd == 'status'):
af1e45e6 5190 statusCheck(True)
b8432c6f 5191 elif(cmd == 'fpdt'):
b8432c6f
TB
5192 getFPDT(True)
5193 elif(cmd == 'usbtopo'):
af1e45e6 5194 detectUSB()
b8432c6f 5195 elif(cmd == 'modes'):
03bc39be 5196 print getModes()
af1e45e6
TB
5197 elif(cmd == 'flist'):
5198 sysvals.getFtraceFilterFunctions(True)
5199 elif(cmd == 'flistall'):
5200 sysvals.getFtraceFilterFunctions(False)
b8432c6f
TB
5201 elif(cmd == 'usbauto'):
5202 setUSBDevicesAuto()
5203 elif(cmd == 'summary'):
5204 print("Generating a summary of folder \"%s\"" % cmdarg)
5205 runSummary(cmdarg, True)
5206 sys.exit()
5207
b8432c6f
TB
5208 # if instructed, re-analyze existing data files
5209 if(sysvals.notestrun):
5210 rerunTest()
5211 sys.exit()
5212
5213 # verify that we can run a test
5214 if(not statusCheck()):
5215 print('Check FAILED, aborting the test run!')
5216 sys.exit()
5217
5218 if multitest['run']:
af1e45e6 5219 # run multiple tests in a separate subdirectory
b8432c6f 5220 s = 'x%d' % multitest['count']
af1e45e6
TB
5221 if not sysvals.outdir:
5222 sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
5223 if not os.path.isdir(sysvals.outdir):
5224 os.mkdir(sysvals.outdir)
b8432c6f
TB
5225 for i in range(multitest['count']):
5226 if(i != 0):
5227 print('Waiting %d seconds...' % (multitest['delay']))
5228 time.sleep(multitest['delay'])
5229 print('TEST (%d/%d) START' % (i+1, multitest['count']))
af1e45e6 5230 runTest(sysvals.outdir)
b8432c6f 5231 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
af1e45e6 5232 runSummary(sysvals.outdir, False)
b8432c6f
TB
5233 else:
5234 # run the test in the current directory
af1e45e6 5235 runTest('.', sysvals.outdir)