]> git.proxmox.com Git - mirror_ubuntu-focal-kernel.git/blob - tools/power/pm-graph/sleepgraph.py
projects / mirror_ubuntu-focal-kernel.git / blob
? search:


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