]> git.proxmox.com Git - mirror_ubuntu-artful-kernel.git/blob - scripts/analyze_suspend.py
projects / mirror_ubuntu-artful-kernel.git / blob
? search:
summary | shortlog | log | commit | commitdiff | tree
blame | history | raw | HEAD
Merge tag 'staging-4.11-rc6' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh...
[mirror_ubuntu-artful-kernel.git] / scripts / analyze_suspend.py
1 #!/usr/bin/python
2 #
3 # Tool for analyzing suspend/resume timing
4 # Copyright (c) 2013, Intel Corporation.
5 #
6 # This program is free software; you can redistribute it and/or modify it
7 # under the terms and conditions of the GNU General Public License,
8 # version 2, as published by the Free Software Foundation.
9 #
10 # This program is distributed in the hope it will be useful, but WITHOUT
11 # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12 # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
13 # more details.
14 #
15 # You should have received a copy of the GNU General Public License along with
16 # this program; if not, write to the Free Software Foundation, Inc.,
17 # 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
18 #
19 # Authors:
20 # Todd Brandt <todd.e.brandt@linux.intel.com>
21 #
22 # Links:
23 # Home Page
24 # https://01.org/suspendresume
25 # Source repo
26 # https://github.com/01org/suspendresume
27 #
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
44 # CONFIG_KPROBES=y
45 # CONFIG_KPROBES_ON_FTRACE=y
46 #
47 # For kernel versions older than 3.15:
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
53 # ----------------- LIBRARIES --------------------
54
55 import sys
56 import time
57 import os
58 import string
59 import re
60 import platform
61 from datetime import datetime
62 import struct
63 import ConfigParser
64 from threading import Thread
65 from subprocess import call, Popen, PIPE
66
67 # ----------------- CLASSES --------------------
68
69 # Class: SystemValues
70 # Description:
71 # A global, single-instance container used to
72 # store system values and test parameters
73 class SystemValues:
74 ansi = False
75 version = '4.5'
76 verbose = False
77 addlogs = False
78 mindevlen = 0.0
79 mincglen = 0.0
80 cgphase = ''
81 cgtest = -1
82 callloopmaxgap = 0.0001
83 callloopmaxlen = 0.005
84 srgap = 0
85 cgexp = False
86 outdir = ''
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 ]
96 logmsg = ''
97 testcommand = ''
98 mempath = '/dev/mem'
99 powerfile = '/sys/power/state'
100 suspendmode = 'mem'
101 hostname = 'localhost'
102 prefix = 'test'
103 teststamp = ''
104 dmesgstart = 0.0
105 dmesgfile = ''
106 ftracefile = ''
107 htmlfile = ''
108 embedded = False
109 rtcwake = False
110 rtcwaketime = 10
111 rtcpath = ''
112 devicefilter = []
113 stamp = 0
114 execcount = 1
115 x2delay = 0
116 usecallgraph = False
117 usetraceevents = False
118 usetraceeventsonly = False
119 usetracemarkers = True
120 usekprobes = True
121 usedevsrc = False
122 useprocmon = False
123 notestrun = False
124 mixedphaseheight = True
125 devprops = dict()
126 predelay = 0
127 postdelay = 0
128 procexecfmt = 'ps - (?P<ps>.*)$'
129 devpropfmt = '# Device Properties: .*'
130 tracertypefmt = '# tracer: (?P<t>.*)'
131 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
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>.*)$'
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'},
157 'format': 'CPU_OFF[{cpu}]'
158 },
159 'CPU_ON': {
160 'func':'_cpu_up',
161 'args_x86_64': {'cpu':'%di:s32'},
162 'format': 'CPU_ON[{cpu}]'
163 },
164 }
165 dev_tracefuncs = {
166 # general wait/delay/sleep
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},
174 # ACPI
175 'acpi_resume_power_resources': dict(),
176 'acpi_ps_parse_aml': dict(),
177 # filesystem
178 'ext4_sync_fs': dict(),
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(),
199 # ATA
200 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
201 # i915
202 'i915_gem_resume': dict(),
203 'i915_restore_state': dict(),
204 'intel_opregion_setup': dict(),
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(),
212 'intel_dp_detect': dict(),
213 'intel_hdmi_detect': dict(),
214 'intel_opregion_init': dict(),
215 'intel_fbdev_set_suspend': dict(),
216 }
217 kprobes = dict()
218 timeformat = '%.3f'
219 def __init__(self):
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']
225 self.archargs = 'args_'+platform.machine()
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
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)
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)
249 def setOutputFile(self):
250 if((self.htmlfile == '') and (self.dmesgfile != '')):
251 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
252 if(m):
253 self.htmlfile = m.group('name')+'.html'
254 if((self.htmlfile == '') and (self.ftracefile != '')):
255 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
256 if(m):
257 self.htmlfile = m.group('name')+'.html'
258 if(self.htmlfile == ''):
259 self.htmlfile = 'output.html'
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')
268 if(subdir != "."):
269 self.testdir = subdir+"/"+testpath
270 else:
271 self.testdir = testpath
272 self.teststamp = \
273 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
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
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'
286 if not os.path.isdir(self.testdir):
287 os.mkdir(self.testdir)
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())
294 def rtcWakeAlarmOn(self):
295 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
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
311 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
312 def rtcWakeAlarmOff(self):
313 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
314 def initdmesg(self):
315 # get the latest time stamp from the dmesg log
316 fp = Popen('dmesg', stdout=PIPE).stdout
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
330 fp = Popen('dmesg', stdout=PIPE).stdout
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:
356 call('cat '+self.tpath+'available_filter_functions', shell=True)
357 return
358 fp = open(self.tpath+'available_filter_functions')
359 master = fp.read().split('\n')
360 fp.close()
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)
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()
383 def basicKprobe(self, name):
384 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
385 def defaultKprobe(self, name, kdata):
386 k = kdata
387 for field in ['name', 'format', 'func']:
388 if field not in k:
389 k[field] = name
390 if self.archargs in k:
391 k['args'] = k[self.archargs]
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
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']
441 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
442 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
443 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
444 if arg not in args:
445 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
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
451 def addKprobes(self, output=False):
452 if len(sysvals.kprobes) < 1:
453 return
454 if output:
455 print(' kprobe functions in this kernel:')
456 # first test each kprobe
457 rejects = []
458 # sort kprobes: trace, ub-dev, custom, dev
459 kpl = [[], [], [], []]
460 for name in sorted(self.kprobes):
461 res = self.colorText('YES', 32)
462 if not self.testKprobe(name, self.kprobes[name]):
463 res = self.colorText('NO')
464 rejects.append(name)
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]
478 # remove all failed ones from the list
479 for name in rejects:
480 self.kprobes.pop(name)
481 # set the kprobes all at once
482 self.fsetVal('', 'kprobe_events')
483 kprobeevents = ''
484 for kp in kplist:
485 kprobeevents += self.kprobeText(kp, self.kprobes[kp])
486 self.fsetVal(kprobeevents, 'kprobe_events')
487 # verify that the kprobes were set as ordered
488 check = self.fgetVal('kprobe_events')
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)
498 self.fsetVal('1', 'events/kprobes/enable')
499 def testKprobe(self, kname, kprobe):
500 self.fsetVal('0', 'events/kprobes/enable')
501 kprobeevents = self.kprobeText(kname, kprobe)
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:
519 fp = open(file, mode, 0)
520 fp.write(val)
521 fp.flush()
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):
548 if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
549 return True
550 for i in self.tracefuncs:
551 if 'func' in self.tracefuncs[i]:
552 f = self.tracefuncs[i]['func']
553 else:
554 f = i
555 if name == f:
556 return True
557 return False
558 def initFtrace(self, testing=False):
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
571 # initialize the callgraph trace
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')
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])
603 print('INITIALIZING KPROBES...')
604 self.addKprobes(self.verbose)
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
636 def colorText(self, str, color=31):
637 if not self.ansi:
638 return str
639 return '\x1B[%d;40m%s\x1B[m' % (color, str)
640
641 sysvals = SystemValues()
642
643 # Class: DevProps
644 # Description:
645 # Simple class which holds property values collected
646 # for all the devices used in the timeline.
647 class 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:
671 return ' async_device'
672 return ' sync_device'
673
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()
678 class 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 {
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
702 # optionally includes dev/ps data
703 # }
704 # }
705 # }
706 # }
707 #
708 class Data:
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
715 tKernSus = 0.0 # kernel level suspend start
716 tKernRes = 0.0 # kernel level resume end
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
722 pstl = 0 # process timeline
723 testnumber = 0
724 idstr = ''
725 html_device_id = 0
726 stamp = 0
727 outfile = ''
728 devpids = []
729 kerror = False
730 def __init__(self, num):
731 idchar = 'abcdefghij'
732 self.pstl = dict()
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},
744 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
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},
750 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
751 'row': 0, 'color': '#FF9900', 'order': 6},
752 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
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}
758 }
759 self.phases = self.sortedPhases()
760 self.devicegroups = []
761 for phase in self.phases:
762 self.devicegroups.append([phase])
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 = ''
792 def setStart(self, time):
793 self.start = time
794 def setEnd(self, time):
795 self.end = time
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
802 time < d['end']):
803 return False
804 return True
805 def sourcePhase(self, start):
806 for phase in self.phases:
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):
812 tgtdev = ''
813 for phase in phaselist:
814 list = self.dmesg[phase]['list']
815 for devname in list:
816 dev = list[devname]
817 # pid must match
818 if dev['pid'] != pid:
819 continue
820 devS = dev['start']
821 devE = dev['end']
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
832 tgtdev = dev
833 break
834 return tgtdev
835 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
836 # try to place the call in a device
837 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device')
838 # calls with device pids that occur outside device bounds are dropped
839 # TODO: include these somehow
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:
844 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread')
845 # create new thread blocks, expand as new calls are found
846 if not tgtdev:
847 if proc == '<...>':
848 threadname = 'kthread-%d' % (pid)
849 else:
850 threadname = '%s-%d' % (proc, pid)
851 tgtphase = self.sourcePhase(start)
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))
858 return False
859 # place the call data inside the src element of the tgtdev
860 if('src' not in tgtdev):
861 tgtdev['src'] = []
862 dtf = sysvals.dev_tracefuncs
863 ubiquitous = False
864 if kprobename in dtf and 'ub' in dtf[kprobename]:
865 ubiquitous = True
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
877 if ubiquitous and c in dtf and 'ub' in dtf[c]:
878 return False
879 color = sysvals.kprobeColor(kprobename)
880 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
881 tgtdev['src'].append(e)
882 return True
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]
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)
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)
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)
971 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
972 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
973 self.end = self.trimTimeVal(self.end, t0, dT, left)
974 for phase in self.phases:
975 p = self.dmesg[phase]
976 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
977 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
978 list = p['list']
979 for name in list:
980 d = list[name]
981 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
982 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
983 if('ftrace' in d):
984 cg = d['ftrace']
985 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
986 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
987 for line in cg.list:
988 line.time = self.trimTimeVal(line.time, t0, dT, left)
989 if('src' in d):
990 for e in d['src']:
991 e.time = self.trimTimeVal(e.time, t0, dT, left)
992 def normalizeTime(self, tZero):
993 # trim out any standby or freeze clock time
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)
1001 def setPhase(self, phase, ktime, isbegin):
1002 if(isbegin):
1003 self.dmesg[phase]['start'] = ktime
1004 else:
1005 self.dmesg[phase]['end'] = ktime
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
1020 def fixupInitcalls(self, phase):
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):
1026 for p in self.phases:
1027 if self.dmesg[p]['end'] > dev['start']:
1028 dev['end'] = self.dmesg[p]['end']
1029 break
1030 vprint('%s (%s): callback didnt return' % (devname, phase))
1031 def deviceFilter(self, devicefilter):
1032 for phase in self.phases:
1033 list = self.dmesg[phase]['list']
1034 rmlist = []
1035 for name in list:
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:
1042 rmlist.append(name)
1043 for name in rmlist:
1044 del list[name]
1045 def fixupInitcallsThatDidntReturn(self):
1046 # if any calls never returned, clip them at system resume end
1047 for phase in self.phases:
1048 self.fixupInitcalls(phase)
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=''):
1065 # which phase is this device callback or action in
1066 targetphase = 'none'
1067 htmlclass = ''
1068 overlap = 0.0
1069 phases = []
1070 for phase in self.phases:
1071 pstart = self.dmesg[phase]['start']
1072 pend = self.dmesg[phase]['end']
1073 # see if the action overlaps this phase
1074 o = max(0, min(end, pend) - max(start, pstart))
1075 if o > 0:
1076 phases.append(phase)
1077 # set the target phase to the one that overlaps most
1078 if o > overlap:
1079 if overlap > 0 and phase == 'post_resume':
1080 continue
1081 targetphase = phase
1082 overlap = o
1083 # if no target phase was found, pin it to the edge
1084 if targetphase == 'none':
1085 p0start = self.dmesg[self.phases[0]]['start']
1086 if start <= p0start:
1087 targetphase = self.phases[0]
1088 else:
1089 targetphase = self.phases[-1]
1090 if pid == -2:
1091 htmlclass = ' bg'
1092 elif pid == -3:
1093 htmlclass = ' ps'
1094 if len(phases) > 1:
1095 htmlclass = ' bg'
1096 self.phaseOverlap(phases)
1097 if targetphase in self.phases:
1098 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1099 return (targetphase, newname)
1100 return False
1101 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
1102 # new device callback for a specific phase
1103 self.html_device_id += 1
1104 devid = '%s%d' % (self.idstr, self.html_device_id)
1105 list = self.dmesg[phase]['list']
1106 length = -1.0
1107 if(start >= 0 and end >= 0):
1108 length = end - start
1109 if pid == -2:
1110 i = 2
1111 origname = name
1112 while(name in list):
1113 name = '%s[%d]' % (origname, i)
1114 i += 1
1115 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,
1116 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }
1117 if htmlclass:
1118 list[name]['htmlclass'] = htmlclass
1119 if color:
1120 list[name]['color'] = color
1121 return name
1122 def deviceChildren(self, devname, phase):
1123 devlist = []
1124 list = self.dmesg[phase]['list']
1125 for child in list:
1126 if(list[child]['par'] == devname):
1127 devlist.append(child)
1128 return devlist
1129 def printDetails(self):
1130 vprint('Timeline Details:')
1131 vprint(' test start: %f' % self.start)
1132 vprint('kernel suspend start: %f' % self.tKernSus)
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))
1137 vprint(' kernel resume end: %f' % self.tKernRes)
1138 vprint(' test end: %f' % self.end)
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
1147 def masterTopology(self, name, list, depth):
1148 node = DeviceNode(name, depth)
1149 for cname in list:
1150 # avoid recursions
1151 if name == cname:
1152 continue
1153 clist = self.deviceChildrenAllPhases(cname)
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']
1194 pid = list[dev]['pid']
1195 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
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)
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
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
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
1298 # Description:
1299 # A container for kprobe function data we want in the dev timeline
1300 class DevFunction:
1301 row = 0
1302 count = 1
1303 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
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
1314 self.color = color
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:
1321 title = '%s(%s)%s <- %s, %s(%s)' % \
1322 (self.name, self.args, cnt, self.caller, self.ret, l)
1323 else:
1324 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
1325 return title.replace('"', '')
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):
1333 # is the tgt call just a repeat of this call (e.g. are we in a loop)
1334 dt = self.time - tgt.end
1335 # only combine calls if -all- attributes are identical
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 \
1339 tgt.ret == self.ret and dt >= 0 and \
1340 dt <= sysvals.callloopmaxgap and \
1341 self.length < sysvals.callloopmaxlen:
1342 return True
1343 return False
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
1356 class FTraceLine:
1357 time = 0.0
1358 length = 0.0
1359 fcall = False
1360 freturn = False
1361 fevent = False
1362 fkprobe = False
1363 depth = 0
1364 name = ''
1365 type = ''
1366 def __init__(self, t, m='', d=''):
1367 self.time = float(t)
1368 if not m and not d:
1369 return
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
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
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
1404 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
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
1414 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
1415 if(match):
1416 self.name = match.group('n').strip()
1417 # function call
1418 else:
1419 self.fcall = True
1420 # function call with children
1421 if(m[-1] == '{'):
1422 match = re.match('^(?P<n>.*) *\(.*', m)
1423 if(match):
1424 self.name = match.group('n').strip()
1425 # function call with no children (leaf)
1426 elif(m[-1] == ';'):
1427 self.freturn = True
1428 match = re.match('^(?P<n>.*) *\(.*', m)
1429 if(match):
1430 self.name = match.group('n').strip()
1431 # something else (possibly a trace marker)
1432 else:
1433 self.name = m
1434 def getDepth(self, str):
1435 return len(str)/2
1436 def debugPrint(self, dev=''):
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))
1446 def startMarker(self):
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
1472
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
1479 class FTraceCallGraph:
1480 start = -1.0
1481 end = -1.0
1482 list = []
1483 invalid = False
1484 depth = 0
1485 pid = 0
1486 def __init__(self, pid):
1487 self.start = -1.0
1488 self.end = -1.0
1489 self.list = []
1490 self.depth = 0
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
1570 if(line.fcall and not line.freturn):
1571 self.depth += 1
1572 elif(line.freturn and not line.fcall):
1573 self.depth -= 1
1574 if len(self.list) < 1:
1575 self.start = line.time
1576 self.list.append(line)
1577 if(line.depth == 0 and line.freturn):
1578 if(self.start < 0):
1579 self.start = line.time
1580 self.end = line.time
1581 if line.fcall:
1582 self.end += line.length
1583 if self.list[0].name == virtualfname:
1584 self.invalid = True
1585 return True
1586 return False
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')
1601 def slice(self, t0, tN):
1602 minicg = FTraceCallGraph(0)
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
1614 minicg.addLine(l)
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
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):
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):
1641 if(l.depth not in stack):
1642 if debug:
1643 print 'Post Process Error: Depth missing'
1644 l.debugPrint()
1645 return False
1646 # transfer total time from return line to call line
1647 stack[l.depth].length = l.length
1648 stack.pop(l.depth)
1649 l.length = 0
1650 cnt -= 1
1651 if(cnt == 0):
1652 # trace caught the whole call tree
1653 return True
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(' ')
1725
1726 class DevItem:
1727 def __init__(self, test, phase, dev):
1728 self.test = test
1729 self.phase = phase
1730 self.dev = dev
1731 def isa(self, cls):
1732 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:
1733 return True
1734 return False
1735
1736 # Class: Timeline
1737 # Description:
1738 # A container for a device timeline which calculates
1739 # all the html properties to display it correctly
1740 class Timeline:
1741 html = {}
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
1747 rowlines = dict()
1748 rowheight = dict()
1749 def __init__(self, rowheight, scaleheight):
1750 self.rowH = rowheight
1751 self.scaleH = scaleheight
1752 self.html = {
1753 'header': '',
1754 'timeline': '',
1755 'legend': '',
1756 }
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
1766 sortdict = dict()
1767 for item in rawlist:
1768 item.row = -1
1769 sortdict[item] = item.length
1770 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
1771 remaining = len(sortlist)
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] = []
1778 for i in sortlist:
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:
1802 # devlist: the list of devices/actions in a group of contiguous phases
1803 # Output:
1804 # The total number of rows needed to display this phase of the timeline
1805 def getPhaseRows(self, devlist, row=0):
1806 # clear all rows and set them to undefined
1807 remaining = len(devlist)
1808 rowdata = dict()
1809 sortdict = dict()
1810 myphases = []
1811 # initialize all device rows to -1 and calculate devrows
1812 for item in devlist:
1813 dev = item.dev
1814 tp = (item.test, item.phase)
1815 if tp not in myphases:
1816 myphases.append(tp)
1817 dev['row'] = -1
1818 # sort by length 1st, then name 2nd
1819 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])
1820 if 'src' in dev:
1821 dev['devrows'] = self.getDeviceRows(dev['src'])
1822 # sort the devlist by length so that large items graph on top
1823 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
1824 orderedlist = []
1825 for item in sortlist:
1826 if item.dev['pid'] == -2:
1827 orderedlist.append(item)
1828 for item in sortlist:
1829 if item not in orderedlist:
1830 orderedlist.append(item)
1831 # try to pack each row with as many devices as possible
1832 while(remaining > 0):
1833 rowheight = 1
1834 if(row not in rowdata):
1835 rowdata[row] = []
1836 for item in orderedlist:
1837 dev = item.dev
1838 if(dev['row'] < 0):
1839 s = dev['start']
1840 e = dev['end']
1841 valid = True
1842 for ritem in rowdata[row]:
1843 rs = ritem.dev['start']
1844 re = ritem.dev['end']
1845 if(not (((s <= rs) and (e <= rs)) or
1846 ((s >= re) and (e >= re)))):
1847 valid = False
1848 break
1849 if(valid):
1850 rowdata[row].append(item)
1851 dev['row'] = row
1852 remaining -= 1
1853 if 'devrows' in dev and dev['devrows'] > rowheight:
1854 rowheight = dev['devrows']
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()
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
1868 self.rowlines[t][p][row] = rowheight
1869 self.rowheight[t][p][row] = rowheight * rh
1870 row += 1
1871 if(row > self.rows):
1872 self.rows = int(row)
1873 return row
1874 def phaseRowHeight(self, test, phase, row):
1875 return self.rowheight[test][phase][row]
1876 def phaseRowTop(self, test, phase, row):
1877 top = 0
1878 for i in sorted(self.rowheight[test][phase]):
1879 if i >= row:
1880 break
1881 top += self.rowheight[test][phase][i]
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 = []
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))
1898 self.height = self.scaleH + (maxrows*self.rowH)
1899 self.bodyH = self.height - self.scaleH
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])
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
1944
1945 # Class: TestProps
1946 # Description:
1947 # A list of values describing the properties of these test runs
1948 class TestProps:
1949 stamp = ''
1950 S0i3 = False
1951 fwdata = []
1952 ftrace_line_fmt_fg = \
1953 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
1954 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
1955 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
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
1962 data = 0
1963 ktemp = dict()
1964 def __init__(self):
1965 self.ktemp = dict()
1966 def setTracerType(self, tracer):
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:
1973 doError('Invalid tracer format: [%s]' % tracer)
1974
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.
1979 class 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
1988 class ProcessMonitor:
1989 proclist = dict()
1990 running = False
1991 def procstat(self):
1992 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
1993 process = Popen(c, shell=True, stdout=PIPE)
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):
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
2033 # ----------------- FUNCTIONS --------------------
2034
2035 # Function: vprint
2036 # Description:
2037 # verbose print (prints only with -verbose option)
2038 # Arguments:
2039 # msg: the debug/log message to print
2040 def vprint(msg):
2041 sysvals.logmsg += msg+'\n'
2042 if(sysvals.verbose):
2043 print(msg)
2044
2045 # Function: parseStamp
2046 # Description:
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
2051 def parseStamp(line, data):
2052 m = re.match(sysvals.stampfmt, line)
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')
2061 sysvals.hostname = data.stamp['host']
2062 sysvals.suspendmode = data.stamp['mode']
2063 if sysvals.suspendmode == 'command' and sysvals.ftracefile != '':
2064 modes = ['on', 'freeze', 'standby', 'mem']
2065 out = Popen(['grep', 'suspend_enter', sysvals.ftracefile],
2066 stderr=PIPE, stdout=PIPE).stdout.read()
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
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
2082 def 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
2099 def doesTraceLogHaveTraceEvents():
2100 # check for kprobes
2101 sysvals.usekprobes = False
2102 out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True)
2103 if(out == 0):
2104 sysvals.usekprobes = True
2105 # check for callgraph data on trace event blocks
2106 out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True)
2107 if(out == 0):
2108 sysvals.usekprobes = True
2109 out = Popen(['head', '-1', sysvals.ftracefile],
2110 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
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
2117 sysvals.usetraceeventsonly = True
2118 sysvals.usetraceevents = False
2119 for e in sysvals.traceevents:
2120 out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True)
2121 if(out != 0):
2122 sysvals.usetraceeventsonly = False
2123 if(e == 'suspend_resume' and out == 0):
2124 sysvals.usetraceevents = True
2125 # determine is this log is properly formatted
2126 for e in ['SUSPEND START', 'RESUME COMPLETE']:
2127 out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True)
2128 if(out != 0):
2129 sysvals.usetracemarkers = False
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
2141 def appendIncompleteTraceLog(testruns):
2142 # create TestRun vessels for ftrace parsing
2143 testcnt = len(testruns)
2144 testidx = 0
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...')
2151 tp = TestProps()
2152 tf = open(sysvals.ftracefile, 'r')
2153 data = 0
2154 for line in tf:
2155 # remove any latent carriage returns
2156 line = line.replace('\r\n', '')
2157 # grab the time stamp
2158 m = re.match(sysvals.stampfmt, line)
2159 if(m):
2160 tp.stamp = line
2161 continue
2162 # determine the trace data type (required for further parsing)
2163 m = re.match(sysvals.tracertypefmt, line)
2164 if(m):
2165 tp.setTracerType(m.group('t'))
2166 continue
2167 # device properties line
2168 if(re.match(sysvals.devpropfmt, line)):
2169 devProps(line)
2170 continue
2171 # parse only valid lines, if this is not one move on
2172 m = re.match(tp.ftrace_line_fmt, line)
2173 if(not m):
2174 continue
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')
2179 if(tp.cgformat):
2180 m_param3 = m.group('dur')
2181 else:
2182 m_param3 = 'traceevent'
2183 if(m_time and m_pid and m_msg):
2184 t = FTraceLine(m_time, m_msg, m_param3)
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
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:
2214 continue
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')
2220 else:
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
2241 else:
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
2247 else:
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))
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]:
2306 test.data.newActionGlobal(name, event['begin'], event['end'])
2307
2308 # add the callgraph data to the device hierarchy
2309 for pid in test.ftemp:
2310 for cg in test.ftemp[pid]:
2311 if len(cg.list) < 1 or cg.invalid:
2312 continue
2313 if(not cg.postProcess()):
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
2332 test.data.printDetails()
2333
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
2342 def parseTraceLog():
2343 vprint('Analyzing the ftrace data...')
2344 if(os.path.exists(sysvals.ftracefile) == False):
2345 doError('%s does not exist' % sysvals.ftracefile)
2346
2347 sysvals.setupAllKprobes()
2348 tracewatch = []
2349 if sysvals.usekprobes:
2350 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2351 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
2352
2353 # extract the callgraph and traceevent data
2354 tp = TestProps()
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):
2367 tp.stamp = line
2368 continue
2369 # firmware line: pull out any firmware data
2370 m = re.match(sysvals.firmwarefmt, line)
2371 if(m):
2372 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2373 continue
2374 # tracer type line: determine the trace data type
2375 m = re.match(sysvals.tracertypefmt, line)
2376 if(m):
2377 tp.setTracerType(m.group('t'))
2378 continue
2379 # device properties line
2380 if(re.match(sysvals.devpropfmt, line)):
2381 devProps(line)
2382 continue
2383 # ignore all other commented lines
2384 if line[0] == '#':
2385 continue
2386 # ftrace line: parse only valid lines
2387 m = re.match(tp.ftrace_line_fmt, line)
2388 if(not m):
2389 continue
2390 # gather the basic message data from the line
2391 m_time = m.group('time')
2392 m_proc = m.group('proc')
2393 m_pid = m.group('pid')
2394 m_msg = m.group('msg')
2395 if(tp.cgformat):
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
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)
2415 data.setStart(t.time)
2416 data.tKernSus = t.time
2417 continue
2418 if(not data):
2419 continue
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
2433 # find the end of resume
2434 if(t.endMarker()):
2435 data.setEnd(t.time)
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
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
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
2452 continue
2453 # trace event processing
2454 if(t.fevent):
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
2476 if(name.split('[')[0] in tracewatch):
2477 continue
2478 # -- phase changes --
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
2485 # suspend_prepare start
2486 elif(re.match('dpm_prepare\[.*', t.name)):
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:
2516 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
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
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
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
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})
2566 else:
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})
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)
2586 if pid not in data.devpids:
2587 data.devpids.append(pid)
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
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
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
2635 # callgraph processing
2636 elif sysvals.usecallgraph:
2637 # create a callgraph object for the data
2638 key = (m_proc, pid)
2639 if(key not in testrun.ftemp):
2640 testrun.ftemp[key] = []
2641 testrun.ftemp[key].append(FTraceCallGraph(pid))
2642 # when the call is finished, see which device matches it
2643 cg = testrun.ftemp[key][-1]
2644 if(cg.addLine(t)):
2645 testrun.ftemp[key].append(FTraceCallGraph(pid))
2646 tf.close()
2647
2648 if sysvals.suspendmode == 'command':
2649 for test in testruns:
2650 for p in test.data.phases:
2651 if p == 'suspend_prepare':
2652 test.data.dmesg[p]['start'] = test.data.start
2653 test.data.dmesg[p]['end'] = test.data.end
2654 else:
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
2659 test.data.tLow = 0
2660 test.data.fwValid = False
2661
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
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
2673 # add the process usage data to the timeline
2674 if sysvals.useprocmon:
2675 data.createProcessUsageEvents()
2676 # add the traceevent data to the device hierarchy
2677 if(sysvals.usetraceevents):
2678 # add actual trace funcs
2679 for name in test.ttemp:
2680 for event in test.ttemp[name]:
2681 data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
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:
2686 continue
2687 for e in tp.ktemp[key]:
2688 kb, ke = e['begin'], e['end']
2689 if kb == ke or tlb > kb or tle <= kb:
2690 continue
2691 color = sysvals.kprobeColor(name)
2692 data.newActionGlobal(e['name'], kb, ke, pid, color)
2693 # add config base kprobes and dev kprobes
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:
2698 continue
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,
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
2719 if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, data):
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))
2728 cg.newActionFromFunction(data)
2729
2730 if sysvals.suspendmode == 'command':
2731 for data in testdata:
2732 data.printDetails()
2733 return testdata
2734
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):
2740 vprint('WARNING: phase "%s" is missing!' % p)
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']
2749 if(p != lp and not ('machine' in p and 'machine' in lp)):
2750 data.dmesg[lp]['end'] = data.dmesg[p]['start']
2751 lp = p
2752
2753 if(len(sysvals.devicefilter) > 0):
2754 data.deviceFilter(sysvals.devicefilter)
2755 data.fixupInitcallsThatDidntReturn()
2756 if sysvals.usedevsrc:
2757 data.optimizeDevSrc()
2758 data.printDetails()
2759
2760 # x2: merge any overlapping devices between test runs
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)
2767 testdata[0].stitchTouchingThreads(testdata[1:])
2768 return testdata
2769
2770 # Function: loadKernelLog
2771 # Description:
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
2777 def loadKernelLog(justtext=False):
2778 vprint('Analyzing the dmesg data...')
2779 if(os.path.exists(sysvals.dmesgfile) == False):
2780 doError('%s does not exist' % sysvals.dmesgfile)
2781
2782 if justtext:
2783 dmesgtext = []
2784 # there can be multiple test runs in a single file
2785 tp = TestProps()
2786 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
2787 testruns = []
2788 data = 0
2789 lf = open(sysvals.dmesgfile, 'r')
2790 for line in lf:
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):
2797 tp.stamp = line
2798 continue
2799 m = re.match(sysvals.firmwarefmt, line)
2800 if(m):
2801 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2802 continue
2803 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2804 if(not m):
2805 continue
2806 msg = m.group("msg")
2807 if justtext:
2808 dmesgtext.append(line)
2809 continue
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
2819 if(not data):
2820 continue
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')
2827 data.dmesgtext.append(line)
2828 lf.close()
2829
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)
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
2856 # Description:
2857 # [deprecated for kernel 3.15.0 or newer]
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
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
2867 def parseKernelLog(data):
2868 phase = 'suspend_runtime'
2869
2870 if(data.fwValid):
2871 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
2872 (data.fwSuspend, data.fwResume))
2873
2874 # dmesg phase match table
2875 dm = {
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 \.\.\..*',
2887 }
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:
2925 # parse each dmesg line into the time and message
2926 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2927 if(m):
2928 val = m.group('ktime')
2929 try:
2930 ktime = float(val)
2931 except:
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
2938 else:
2939 continue
2940
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
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)
2954 data.tKernSus = ktime
2955 # suspend start
2956 elif(re.match(dm['suspend'], msg)):
2957 data.dmesg['suspend_prepare']['end'] = ktime
2958 phase = 'suspend'
2959 data.dmesg[phase]['start'] = ktime
2960 # suspend_late start
2961 elif(re.match(dm['suspend_late'], msg)):
2962 data.dmesg['suspend']['end'] = ktime
2963 phase = 'suspend_late'
2964 data.dmesg[phase]['start'] = ktime
2965 # suspend_noirq start
2966 elif(re.match(dm['suspend_noirq'], msg)):
2967 data.dmesg['suspend_late']['end'] = ktime
2968 phase = 'suspend_noirq'
2969 data.dmesg[phase]['start'] = ktime
2970 # suspend_machine start
2971 elif(re.match(dm['suspend_machine'], msg)):
2972 data.dmesg['suspend_noirq']['end'] = ktime
2973 phase = 'suspend_machine'
2974 data.dmesg[phase]['start'] = ktime
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
2986 data.dmesg[phase]['start'] = ktime
2987 # resume_noirq start
2988 elif(re.match(dm['resume_noirq'], msg)):
2989 data.dmesg['resume_machine']['end'] = ktime
2990 phase = 'resume_noirq'
2991 data.dmesg[phase]['start'] = ktime
2992 # resume_early start
2993 elif(re.match(dm['resume_early'], msg)):
2994 data.dmesg['resume_noirq']['end'] = ktime
2995 phase = 'resume_early'
2996 data.dmesg[phase]['start'] = ktime
2997 # resume start
2998 elif(re.match(dm['resume'], msg)):
2999 data.dmesg['resume_early']['end'] = ktime
3000 phase = 'resume'
3001 data.dmesg[phase]['start'] = ktime
3002 # resume complete start
3003 elif(re.match(dm['resume_complete'], msg)):
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)
3011 data.tKernRes = ktime
3012 break
3013
3014 # -- device callbacks --
3015 if(phase in data.phases):
3016 # device init call
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')
3023 if(f and n and p):
3024 data.newAction(phase, f, int(n), p, ktime, -1, '')
3025 # device init return
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')
3032 list = data.dmesg[phase]['list']
3033 if(f in list):
3034 dev = list[f]
3035 dev['length'] = int(t)
3036 dev['end'] = ktime
3037
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)):
3047 if(a in actions):
3048 actions[a][-1]['end'] = ktime
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
3073
3074 # fill in any missing phases
3075 lp = data.phases[0]
3076 for p in data.phases:
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])
3082 if(data.dmesg[p]['start'] < 0):
3083 data.dmesg[p]['start'] = data.dmesg[lp]['end']
3084 if(p == 'resume_machine'):
3085 data.tSuspended = data.dmesg[lp]['end']
3086 data.tResumed = data.dmesg[lp]['end']
3087 data.tLow = 0
3088 if(data.dmesg[p]['end'] < 0):
3089 data.dmesg[p]['end'] = data.dmesg[p]['start']
3090 lp = p
3091
3092 # fill in any actions we've found
3093 for name in actions:
3094 for event in actions[name]:
3095 data.newActionGlobal(name, event['begin'], event['end'])
3096
3097 data.printDetails()
3098 if(len(sysvals.devicefilter) > 0):
3099 data.deviceFilter(sysvals.devicefilter)
3100 data.fixupInitcallsThatDidntReturn()
3101 return True
3102
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
3108 def createHTMLSummarySimple(testruns, htmlfile):
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
3232 def htmlTitle():
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
3246 def 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
3257 # Function: createHTML
3258 # Description:
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
3264 def createHTML(testruns):
3265 if len(testruns) < 1:
3266 print('ERROR: Not enough test data to build a timeline')
3267 return
3268
3269 kerror = False
3270 for data in testruns:
3271 if data.kerror:
3272 kerror = True
3273 data.normalizeTime(testruns[-1].tSuspended)
3274
3275 x2changes = ['', 'absolute']
3276 if len(testruns) > 1:
3277 x2changes = ['1', 'relative']
3278 # html function templates
3279 headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version
3280 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
3281 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
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'
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'
3285 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
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'
3287 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR&rarr;</div>\n'
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'
3289 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
3290 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
3291 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
3292 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
3293 html_timetotal = '<table class="time1">\n<tr>'\
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>'\
3296 '</tr>\n</table>\n'
3297 html_timetotal2 = '<table class="time1">\n<tr>'\
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>'\
3301 '</tr>\n</table>\n'
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'
3306 html_timegroups = '<table class="time2">\n<tr>'\
3307 '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\
3308 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3309 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
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>'\
3311 '</tr>\n</table>\n'
3312
3313 # html format variables
3314 hoverZ = 'z-index:8;'
3315 if sysvals.usedevsrc:
3316 hoverZ = ''
3317 scaleH = 20
3318 scaleTH = 20
3319 if kerror:
3320 scaleH = 40
3321 scaleTH = 60
3322
3323 # device timeline
3324 vprint('Creating Device Timeline...')
3325
3326 devtl = Timeline(30, scaleH)
3327
3328 # Generate the header for this timeline
3329 for data in testruns:
3330 tTotal = data.end - data.start
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
3335 if(tTotal == 0):
3336 print('ERROR: No timeline data')
3337 sys.exit()
3338 if(data.tLow > 0):
3339 low_time = '%.0f'%(data.tLow*1000)
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:
3351 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3352 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
3353 testdesc1 = 'Total'
3354 testdesc2 = ''
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
3357 if(len(testruns) > 1):
3358 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3359 testdesc2 += ' '
3360 if(data.tLow == 0):
3361 thtml = html_timetotal.format(suspend_time, \
3362 resume_time, testdesc1, stitle, rtitle)
3363 else:
3364 thtml = html_timetotal2.format(suspend_time, low_time, \
3365 resume_time, testdesc1, stitle, rtitle)
3366 devtl.html['header'] += thtml
3367 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3368 rftime = '%.3f'%(data.fwResume / 1000000.0)
3369 devtl.html['header'] += html_timegroups.format('%.3f'%sktime, \
3370 sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode)
3371 else:
3372 suspend_time = '%.3f' % sktime
3373 resume_time = '%.3f' % rktime
3374 testdesc = 'Kernel'
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
3377 if(len(testruns) > 1):
3378 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3379 if(data.tLow == 0):
3380 thtml = html_timetotal.format(suspend_time, \
3381 resume_time, testdesc, stitle, rtitle)
3382 else:
3383 thtml = html_timetotal2.format(suspend_time, low_time, \
3384 resume_time, testdesc, stitle, rtitle)
3385 devtl.html['header'] += thtml
3386
3387 # time scale for potentially multiple datasets
3388 t0 = testruns[0].start
3389 tMax = testruns[-1].end
3390 tTotal = tMax - t0
3391
3392 # determine the maximum number of rows we need to draw
3393 fulllist = []
3394 threadlist = []
3395 pscnt = 0
3396 devcnt = 0
3397 for data in testruns:
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]:
3403 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3404 devlist.append(d)
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)
3413 if sysvals.mixedphaseheight:
3414 devtl.getPhaseRows(devlist)
3415 if not sysvals.mixedphaseheight:
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)
3425 devtl.getPhaseRows(fulllist)
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)
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
3437 devtl.html['timeline'] += html_zoombox
3438 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
3439
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)
3447
3448 # draw each test run chronologically
3449 for data in testruns:
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
3462 # in an x2 run, remove any gap between blocks
3463 if len(testruns) > 1 and data.testnumber == 0:
3464 mMax = testruns[1].start
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)
3471 devtl.html['timeline'] += html_tblock.format(bname, left, width, devtl.scaleH)
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'], '')
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)
3486 for b in sorted(phases[dir]):
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']
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()
3504 elif xtraclass == ' kth':
3505 xtrainfo = ' kernel_thread'
3506 if('drv' in dev and dev['drv']):
3507 drv = ' {%s}' % dev['drv']
3508 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row'])
3509 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row'])
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)
3514 title = name+drv+xtrainfo+length
3515 if sysvals.suspendmode == 'command':
3516 title += sysvals.testcommand
3517 elif xtraclass == ' ps':
3518 if 'suspend' in b:
3519 title += 'pre_suspend_process'
3520 else:
3521 title += 'post_resume_process'
3522 else:
3523 title += b
3524 devtl.html['timeline'] += html_device.format(dev['id'], \
3525 title, left, top, '%.3f'%rowheight, width, \
3526 d+drv, xtraclass, xtrastyle)
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)
3540 if('src' not in dev):
3541 continue
3542 # draw any trace events for this device
3543 for e in dev['src']:
3544 height = '%.3f' % devtl.rowH
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)
3548 xtrastyle = ''
3549 if e.color:
3550 xtrastyle = 'background:%s;' % e.color
3551 devtl.html['timeline'] += \
3552 html_traceevent.format(e.title(), \
3553 left, top, height, width, e.text(), '', xtrastyle)
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'
3557
3558 # timeline is finished
3559 devtl.html['timeline'] += '</div>\n</div>\n'
3560
3561 # draw a legend which describes the phases by color
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'
3577
3578 hf = open(sysvals.htmlfile, 'w')
3579
3580 if not sysvals.cgexp:
3581 cgchk = 'checked'
3582 cgnchk = 'not(:checked)'
3583 else:
3584 cgchk = 'not(:checked)'
3585 cgnchk = 'checked'
3586
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\
3590 <title>'+htmlTitle()+'</title>\n\
3591 <style type=\'text/css\'>\n\
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\
3602 cS {font:bold 13px Times;}\n\
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\
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\
3611 r {color:#500000;font:15px Tahoma;}\n\
3612 n {color:#505050;font:15px Tahoma;}\n\
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\
3619 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\
3620 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
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\
3622 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\
3623 .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
3624 .thread.sec,.thread.sec:hover {background-color:black;border:0;color:white;line-height:15px;font-size:10px;}\n\
3625 .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
3626 .hover.sync {background-color:white;}\n\
3627 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background-color:white;}\n\
3628 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\
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\
3631 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
3632 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
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\
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\
3637 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
3638 .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
3639 .devlist {position:'+x2changes[1]+';width:190px;}\n\
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\
3646 .tblock {position:absolute;height:100%;background-color:#ddd;}\n\
3647 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\
3648 .bg {z-index:1;}\n\
3649 </style>\n</head>\n<body>\n'
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)
3658
3659 # write the test title and general info header
3660 if(sysvals.stamp['time'] != ""):
3661 hf.write(headline_version)
3662 if sysvals.logmsg:
3663 hf.write('<button id="showtest" class="logbtn">log</button>')
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>')
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
3673 hf.write(devtl.html['header'])
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)
3681 pscolor = 'linear-gradient(to top left, #ccc, #eee)'
3682 hf.write(html_phaselet.format('pre_suspend_process', \
3683 '0', '0', pscolor))
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']))
3691 hf.write(html_phaselet.format('post_resume_process', \
3692 '0', '0', pscolor))
3693 if sysvals.suspendmode == 'command':
3694 hf.write(html_phaselet.format('cmdexec', '0', '0', pscolor))
3695 hf.write('</div>\n')
3696 hf.write('</div>\n')
3697
3698 # write the ftrace data (callgraph)
3699 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
3700 data = testruns[sysvals.cgtest]
3701 else:
3702 data = testruns[-1]
3703 if(sysvals.usecallgraph and not sysvals.embedded):
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:
3712 if sysvals.cgphase and p != sysvals.cgphase:
3713 continue
3714 list = data.dmesg[p]['list']
3715 for devname in data.sortedDevices(p):
3716 if('ftrace' not in list[devname]):
3717 continue
3718 devid = list[devname]['id']
3719 cg = list[devname]['ftrace']
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
3732 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
3733 num, ftitle, flen))
3734 num += 1
3735 for line in cg.list:
3736 if(line.length < 0.000000001):
3737 flen = ''
3738 else:
3739 fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>'
3740 flen = fmt % (line.length*1000, line.time)
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)
3749 hf.write('\n\n </section>\n')
3750
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')
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:
3759 line = line.replace('<', '&lt').replace('>', '&gt')
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')
3788 hf.close()
3789 return True
3790
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
3797 def addScriptCode(hf, testruns):
3798 t0 = testruns[0].start * 1000
3799 tMax = testruns[-1].end * 1000
3800 # create an array in javascript memory with the device details
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)
3806 # add the code which will manipulate the data in the browser
3807 script_code = \
3808 '<script type="text/javascript">\n'+detail+\
3809 ' var resolution = -1;\n'\
3810 ' var dragval = [0, 0];\n'\
3811 ' function redrawTimescale(t0, tMax, tS) {\n'\
3812 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cS>&larr;R</cS></div>\';\n'\
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'\
3837 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S&rarr;</cS></div>\';\n'\
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'\
3846 ' function zoomTimeline() {\n'\
3847 ' var dmesg = document.getElementById("dmesg");\n'\
3848 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
3849 ' var left = zoombox.scrollLeft;\n'\
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'\
3855 ' if(newval > 910034) newval = 910034;\n'\
3856 ' dmesg.style.width = newval+"%";\n'\
3857 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
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'\
3862 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
3863 ' } else {\n'\
3864 ' zoombox.scrollLeft = 0;\n'\
3865 ' dmesg.style.width = "100%";\n'\
3866 ' }\n'\
3867 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
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'\
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'\
3878 ' }\n'\
3879 ' function deviceName(title) {\n'\
3880 ' var name = title.slice(0, title.indexOf(" ("));\n'\
3881 ' return name;\n'\
3882 ' }\n'\
3883 ' function deviceHover() {\n'\
3884 ' var name = deviceName(this.title);\n'\
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'\
3893 ' dname = deviceName(dev[i].title);\n'\
3894 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3895 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3896 ' (name == dname))\n'\
3897 ' {\n'\
3898 ' dev[i].className = "hover "+cname;\n'\
3899 ' } else {\n'\
3900 ' dev[i].className = cname;\n'\
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'\
3908 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
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'\
3919 ' var name = deviceName(title);\n'\
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'\
3938 ' function deviceDetail() {\n'\
3939 ' var devinfo = document.getElementById("devicedetail");\n'\
3940 ' devinfo.style.display = "block";\n'\
3941 ' var name = deviceName(this.title);\n'\
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'\
3951 ' if(document.getElementById("devicedetail1"))\n'\
3952 ' pdata = [[], []];\n'\
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'\
3956 ' dname = deviceName(dev[i].title);\n'\
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'\
3997 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\
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'\
4005 ' var cglist = document.getElementById("callgraphs");\n'\
4006 ' if(!cglist) return;\n'\
4007 ' var cg = cglist.getElementsByClassName("atop");\n'\
4008 ' if(cg.length < 10) return;\n'\
4009 ' for (var i = 0; i < cg.length; i++) {\n'\
4010 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
4011 ' cg[i].style.display = "block";\n'\
4012 ' } else {\n'\
4013 ' cg[i].style.display = "none";\n'\
4014 ' }\n'\
4015 ' }\n'\
4016 ' }\n'\
4017 ' function devListWindow(e) {\n'\
4018 ' var win = window.open();\n'\
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'\
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'\
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'\
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'\
4068 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
4069 ' window.addEventListener("load", function () {\n'\
4070 ' var dmesg = document.getElementById("dmesg");\n'\
4071 ' dmesg.style.width = "100%"\n'\
4072 ' dmesg.onmousedown = onMouseDown;\n'\
4073 ' document.onmouseup = onMouseUp;\n'\
4074 ' document.onkeypress = onKeyPress;\n'\
4075 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
4076 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
4077 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
4078 ' var list = document.getElementsByClassName("square");\n'\
4079 ' for (var i = 0; i < list.length; i++)\n'\
4080 ' list[i].onclick = onClickPhase;\n'\
4081 ' var list = document.getElementsByClassName("err");\n'\
4082 ' for (var i = 0; i < list.length; i++)\n'\
4083 ' list[i].onclick = errWindow;\n'\
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'\
4090 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4091 ' for (var i = 0; i < dev.length; i++) {\n'\
4092 ' dev[i].onclick = deviceDetail;\n'\
4093 ' dev[i].onmouseover = deviceHover;\n'\
4094 ' dev[i].onmouseout = deviceUnhover;\n'\
4095 ' }\n'\
4096 ' zoomTimeline();\n'\
4097 ' });\n'\
4098 '</script>\n'
4099 hf.write(script_code);
4100
4101 # Function: executeSuspend
4102 # Description:
4103 # Execute system suspend through the sysfs interface, then copy the output
4104 # dmesg and ftrace files to the test output directory.
4105 def executeSuspend():
4106 pm = ProcessMonitor()
4107 tp = sysvals.tpath
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')
4115 if sysvals.useprocmon:
4116 pm.start()
4117 # execute however many s/r runs requested
4118 for count in range(1,sysvals.execcount+1):
4119 # x2delay in between test runs
4120 if(count > 1 and sysvals.x2delay > 0):
4121 sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
4122 time.sleep(sysvals.x2delay/1000.0)
4123 sysvals.fsetVal('WAIT END', 'trace_marker')
4124 # start message
4125 if sysvals.testcommand != '':
4126 print('COMMAND START')
4127 else:
4128 if(sysvals.rtcwake):
4129 print('SUSPEND START')
4130 else:
4131 print('SUSPEND START (press a key to resume)')
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):
4141 sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
4142 time.sleep(sysvals.predelay/1000.0)
4143 sysvals.fsetVal('WAIT END', 'trace_marker')
4144 # initiate suspend or command
4145 if sysvals.testcommand != '':
4146 call(sysvals.testcommand+' 2>&1', shell=True);
4147 else:
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
4155 if(sysvals.rtcwake):
4156 sysvals.rtcWakeAlarmOff()
4157 # postdelay delay
4158 if(count == sysvals.execcount and sysvals.postdelay > 0):
4159 sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
4160 time.sleep(sysvals.postdelay/1000.0)
4161 sysvals.fsetVal('WAIT END', 'trace_marker')
4162 # return from suspend
4163 print('RESUME COMPLETE')
4164 if(sysvals.usecallgraph or sysvals.usetraceevents):
4165 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
4166 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4167 fwdata.append(getFPDT(False))
4168 # stop ftrace
4169 if(sysvals.usecallgraph or sysvals.usetraceevents):
4170 if sysvals.useprocmon:
4171 pm.stop()
4172 sysvals.fsetVal('0', 'tracing_on')
4173 print('CAPTURING TRACE')
4174 writeDatafileHeader(sysvals.ftracefile, fwdata)
4175 call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True)
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
4183 def writeDatafileHeader(filename, fwdata):
4184 fp = open(filename, 'a')
4185 fp.write(sysvals.teststamp+'\n')
4186 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4187 for fw in fwdata:
4188 if(fw):
4189 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
4190 fp.close()
4191
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
4198 def setUSBDevicesAuto():
4199 rootCheck(True)
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):
4203 call('echo auto > %s/power/control' % dirname, shell=True)
4204 name = dirname.split('/')[-1]
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', '')
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
4216 def 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"
4230 def 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)
4239
4240 # Function: detectUSB
4241 # Description:
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
4244 def detectUSB():
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':''}
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('---------------------------------------------------------------------------------------------')
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:
4270 field[i] = Popen(['cat', '%s/%s' % (dirname, i)],
4271 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4272 name = dirname.split('/')[-1]
4273 for i in power:
4274 power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)],
4275 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4276 if(re.match('usb[0-9]*', name)):
4277 first = '%-8s' % name
4278 else:
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
4298 def devProps(data=0):
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):
4323 doError('%s does not exist' % sysvals.ftracefile)
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
4346 dev = m.group('d')
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
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
4421 def getModes():
4422 modes = ''
4423 if(os.path.exists(sysvals.powerfile)):
4424 fp = open(sysvals.powerfile, 'r')
4425 modes = string.split(fp.read())
4426 fp.close()
4427 return modes
4428
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
4434 def getFPDT(output):
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
4442 rootCheck(True)
4443 if(not os.path.exists(sysvals.fpdtpath)):
4444 if(output):
4445 doError('file does not exist: %s' % sysvals.fpdtpath)
4446 return False
4447 if(not os.access(sysvals.fpdtpath, os.R_OK)):
4448 if(output):
4449 doError('file is not readable: %s' % sysvals.fpdtpath)
4450 return False
4451 if(not os.path.exists(sysvals.mempath)):
4452 if(output):
4453 doError('file does not exist: %s' % sysvals.mempath)
4454 return False
4455 if(not os.access(sysvals.mempath, os.R_OK)):
4456 if(output):
4457 doError('file is not readable: %s' % sysvals.mempath)
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 '+\
4467 'be at least 36 bytes')
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):
4498 i += header[1]
4499 continue
4500 if(header[1] != 16):
4501 i += header[1]
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:
4508 if(output):
4509 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
4510 return [0, 0]
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
4559 # Function: statusCheck
4560 # Description:
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
4565 def statusCheck(probecheck=False):
4566 status = True
4567
4568 print('Checking this system (%s)...' % platform.node())
4569
4570 # check we have root access
4571 res = sysvals.colorText('NO (No features of this tool will work!)')
4572 if(rootCheck(False)):
4573 res = 'YES'
4574 print(' have root access: %s' % res)
4575 if(res != 'YES'):
4576 print(' Try running this script with sudo')
4577 return False
4578
4579 # check sysfs is mounted
4580 res = sysvals.colorText('NO (No features of this tool will work!)')
4581 if(os.path.exists(sysvals.powerfile)):
4582 res = 'YES'
4583 print(' is sysfs mounted: %s' % res)
4584 if(res != 'YES'):
4585 return False
4586
4587 # check target mode is a valid mode
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')
4599
4600 # check if ftrace is available
4601 res = sysvals.colorText('NO')
4602 ftgood = sysvals.verifyFtrace()
4603 if(ftgood):
4604 res = 'YES'
4605 elif(sysvals.usecallgraph):
4606 status = False
4607 print(' is ftrace supported: %s' % res)
4608
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
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
4625 if(os.path.exists(sysvals.epath+e)):
4626 check = True
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)
4636
4637 # check if rtcwake
4638 res = sysvals.colorText('NO')
4639 if(sysvals.rtcpath != ''):
4640 res = 'YES'
4641 elif(sysvals.rtcwake):
4642 status = False
4643 print(' is rtcwake supported: %s' % res)
4644
4645 if not probecheck:
4646 return status
4647
4648 # verify kprobes
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)
4656
4657 return status
4658
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
4665 def doError(msg, help=False):
4666 if(help == True):
4667 printHelp()
4668 print('ERROR: %s\n') % msg
4669 sys.exit()
4670
4671 # Function: rootCheck
4672 # Description:
4673 # quick check to see if we have root access
4674 def rootCheck(fatal):
4675 if(os.access(sysvals.powerfile, os.W_OK)):
4676 return True
4677 if fatal:
4678 doError('This command must be run as root')
4679 return False
4680
4681 # Function: getArgInt
4682 # Description:
4683 # pull out an integer argument from the command line with checks
4684 def 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
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
4700 # Function: getArgFloat
4701 # Description:
4702 # pull out a float argument from the command line with checks
4703 def 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
4719 def processData():
4720 print('PROCESSING DATA')
4721 if(sysvals.usetraceeventsonly):
4722 testruns = parseTraceLog()
4723 if sysvals.dmesgfile:
4724 dmesgtext = loadKernelLog(True)
4725 for data in testruns:
4726 data.extractErrorInfo(dmesgtext)
4727 else:
4728 testruns = loadKernelLog()
4729 for data in testruns:
4730 parseKernelLog(data)
4731 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
4732 appendIncompleteTraceLog(testruns)
4733 createHTML(testruns)
4734
4735 # Function: rerunTest
4736 # Description:
4737 # generate an output from an existing set of ftrace/dmesg logs
4738 def 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
4749 # Function: runTest
4750 # Description:
4751 # execute a suspend/resume, gather the logs, and generate the output
4752 def runTest(subdir, testpath=''):
4753 # prepare for the test
4754 sysvals.initFtrace()
4755 sysvals.initTestOutput(subdir, testpath)
4756 vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
4757 (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
4758
4759 # execute the test
4760 executeSuspend()
4761 sysvals.cleanupFtrace()
4762 processData()
4763
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)
4769
4770 # Function: runSummary
4771 # Description:
4772 # create a summary of tests in a sub-directory
4773 def runSummary(subdir, output):
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
4816 # Function: checkArgBool
4817 # Description:
4818 # check if a boolean string value is true or false
4819 def 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
4828 def configFromFile(file):
4829 Config = ConfigParser.ConfigParser()
4830
4831 Config.read(file)
4832 sections = Config.sections()
4833 overridekprobes = False
4834 overridedevkprobes = False
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)
4844 elif(opt.lower() == 'proc'):
4845 sysvals.useprocmon = checkArgBool(value)
4846 elif(opt.lower() == 'x2'):
4847 if checkArgBool(value):
4848 sysvals.execcount = 2
4849 elif(opt.lower() == 'callgraph'):
4850 sysvals.usecallgraph = checkArgBool(value)
4851 elif(opt.lower() == 'override-timeline-functions'):
4852 overridekprobes = checkArgBool(value)
4853 elif(opt.lower() == 'override-dev-timeline-functions'):
4854 overridedevkprobes = checkArgBool(value)
4855 elif(opt.lower() == 'devicefilter'):
4856 sysvals.setDeviceFilter(value)
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)
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)
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)
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)
4883 elif(opt.lower() == 'mincg'):
4884 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
4885 elif(opt.lower() == 'output-dir'):
4886 sysvals.setOutputFolder(value)
4887
4888 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
4889 doError('No command supplied for mode "command"')
4890
4891 # compatibility errors
4892 if sysvals.usedevsrc and sysvals.usecallgraph:
4893 doError('-dev is not compatible with -f')
4894 if sysvals.usecallgraph and sysvals.useprocmon:
4895 doError('-proc is not compatible with -f')
4896
4897 if overridekprobes:
4898 sysvals.tracefuncs = dict()
4899 if overridedevkprobes:
4900 sysvals.dev_tracefuncs = dict()
4901
4902 kprobes = dict()
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:
4912 doError('Duplicate timeline function found "%s"' % (name))
4913 text = Config.get(kprobesec, name)
4914 kprobes[name] = (text, False)
4915
4916 for name in kprobes:
4917 function = name
4918 format = name
4919 color = ''
4920 args = dict()
4921 text, dev = kprobes[name]
4922 data = text.split()
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:
4945 doError('Invalid kprobe: %s' % name)
4946 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
4947 if arg not in args:
4948 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
4949 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
4950 doError('Duplicate timeline function found "%s"' % (name))
4951
4952 kp = {
4953 'name': name,
4954 'func': function,
4955 'format': format,
4956 sysvals.archargs: args
4957 }
4958 if color:
4959 kp['color'] = color
4960 if dev:
4961 sysvals.dev_tracefuncs[name] = kp
4962 else:
4963 sysvals.tracefuncs[name] = kp
4964
4965 # Function: printHelp
4966 # Description:
4967 # print out the help text
4968 def printHelp():
4969 modes = getModes()
4970
4971 print('')
4972 print('AnalyzeSuspend v%s' % sysvals.version)
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]')
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)')
5002 print(' [advanced]')
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')
5012 print(' be created in a new subdirectory with a summary page.')
5013 print(' [debug]')
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)')
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)')
5023 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
5024 print(' [utilities]')
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')
5028 print(' [re-analyze data from previous runs]')
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')
5032 print('')
5033 return True
5034
5035 # ----------------- MAIN --------------------
5036 # exec start (skipped if script is loaded as library)
5037 if __name__ == '__main__':
5038 cmd = ''
5039 cmdarg = ''
5040 multitest = {'run': False, 'count': 0, 'delay': 0}
5041 simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
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)
5050 if val == 'command' and not sysvals.testcommand:
5051 doError('No command supplied for mode "command"', True)
5052 sysvals.suspendmode = val
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()
5061 elif(arg == '-x2'):
5062 sysvals.execcount = 2
5063 elif(arg == '-x2delay'):
5064 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
5065 elif(arg == '-predelay'):
5066 sysvals.predelay = getArgInt('-predelay', args, 0, 60000)
5067 elif(arg == '-postdelay'):
5068 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
5069 elif(arg == '-f'):
5070 sysvals.usecallgraph = True
5071 elif(arg == '-addlogs'):
5072 sysvals.addlogs = True
5073 elif(arg == '-verbose'):
5074 sysvals.verbose = True
5075 elif(arg == '-proc'):
5076 sysvals.useprocmon = True
5077 elif(arg == '-dev'):
5078 sysvals.usedevsrc = True
5079 elif(arg == '-rtcwake'):
5080 sysvals.rtcwake = True
5081 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
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)
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
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)
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
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)
5118 elif(arg == '-o'):
5119 try:
5120 val = args.next()
5121 except:
5122 doError('No subdirectory name supplied', True)
5123 sysvals.setOutputFolder(val)
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):
5130 doError('%s does not exist' % val)
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):
5138 doError('%s does not exist' % val)
5139 sysvals.addFtraceFilterFunctions(val)
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):
5148 doError('%s does not exist' % sysvals.dmesgfile)
5149 elif(arg == '-ftrace'):
5150 try:
5151 val = args.next()
5152 except:
5153 doError('No ftrace file supplied', True)
5154 sysvals.notestrun = True
5155 sysvals.ftracefile = val
5156 if(os.path.exists(sysvals.ftracefile) == False):
5157 doError('%s does not exist' % sysvals.ftracefile)
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):
5167 doError('%s is not accesible' % val)
5168 elif(arg == '-filter'):
5169 try:
5170 val = args.next()
5171 except:
5172 doError('No devnames supplied', True)
5173 sysvals.setDeviceFilter(val)
5174 else:
5175 doError('Invalid argument: '+arg, True)
5176
5177 # compatibility errors
5178 if(sysvals.usecallgraph and sysvals.usedevsrc):
5179 doError('-dev is not compatible with -f')
5180 if(sysvals.usecallgraph and sysvals.useprocmon):
5181 doError('-proc is not compatible with -f')
5182
5183 # callgraph size cannot exceed device size
5184 if sysvals.mincglen < sysvals.mindevlen:
5185 sysvals.mincglen = sysvals.mindevlen
5186
5187 # just run a utility command and exit
5188 if(cmd != ''):
5189 if(cmd == 'status'):
5190 statusCheck(True)
5191 elif(cmd == 'fpdt'):
5192 getFPDT(True)
5193 elif(cmd == 'usbtopo'):
5194 detectUSB()
5195 elif(cmd == 'modes'):
5196 print getModes()
5197 elif(cmd == 'flist'):
5198 sysvals.getFtraceFilterFunctions(True)
5199 elif(cmd == 'flistall'):
5200 sysvals.getFtraceFilterFunctions(False)
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
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']:
5219 # run multiple tests in a separate subdirectory
5220 s = 'x%d' % multitest['count']
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)
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']))
5230 runTest(sysvals.outdir)
5231 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
5232 runSummary(sysvals.outdir, False)
5233 else:
5234 # run the test in the current directory
5235 runTest('.', sysvals.outdir)
Ubuntu Artful kernel mirror