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