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