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