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