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