3 # Tool for analyzing suspend/resume timing
4 # Copyright (c) 2013, Intel Corporation.
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.
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
16 # Todd Brandt <todd.e.brandt@linux.intel.com>
20 # https://01.org/suspendresume
22 # git@github.com:01org/pm-graph
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.
34 # The following kernel build options are required:
36 # CONFIG_PM_SLEEP_DEBUG=y
38 # CONFIG_FUNCTION_TRACER=y
39 # CONFIG_FUNCTION_GRAPH_TRACER=y
41 # CONFIG_KPROBES_ON_FTRACE=y
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 ..."
49 # ----------------- LIBRARIES --------------------
58 from datetime import datetime
62 from threading import Thread
63 from subprocess import call, Popen, PIPE
69 # ----------------- CLASSES --------------------
73 # A global, single-instance container used to
74 # store system values and test parameters
92 multitest = {'run': False, 'count': 0, 'delay': 0}
94 callloopmaxgap = 0.0001
95 callloopmaxlen = 0.005
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'
110 'device_pm_callback_end',
111 'device_pm_callback_start'
116 powerfile = '/sys/power/state'
117 mempowerfile = '/sys/power/mem_sleep'
118 diskpowerfile = '/sys/power/disk'
122 hostname = 'localhost'
129 htmlfile = 'output.html'
141 usetraceevents = False
142 usetracemarkers = True
149 mixedphaseheight = True
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': {},
169 'hibernate_preallocate_memory': {},
170 'create_basic_memory_bitmaps': {},
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': {},
180 'pm_restore_gfp_mask': {},
181 'thaw_processes': {},
182 'pm_restore_console': {},
185 'args_x86_64': {'cpu':'%di:s32'},
186 'format': 'CPU_OFF[{cpu}]'
190 'args_x86_64': {'cpu':'%di:s32'},
191 'format': 'CPU_ON[{cpu}]'
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},
203 'acpi_resume_power_resources': {},
204 'acpi_ps_parse_aml': {},
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': {},
231 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
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': {},
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': {},
251 cmdline = '%s %s' % \
252 (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
255 self.archargs = 'args_'+platform.machine()
256 self.hostname = platform.node()
257 if(self.hostname == ''):
258 self.hostname = 'localhost'
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'):
266 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
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:'):
276 def signalHandler(self, signum, frame):
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})
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()
290 signum = getattr(signal, s)
291 signal.signal(signum, self.signalHandler)
294 self.signames[signum] = s
295 def rootCheck(self, fatal=True):
296 if(os.access(self.powerfile, os.W_OK)):
299 msg = 'This command requires sysfs mount and root access'
300 pprint('ERROR: %s\n' % msg)
301 self.outputResult({'error':msg})
304 def rootUser(self, fatal=False):
305 if 'USER' in os.environ and os.environ['USER'] == 'root':
308 msg = 'This command must be run as root'
309 pprint('ERROR: %s\n' % msg)
310 self.outputResult({'error':msg})
313 def getExec(self, cmd):
314 dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
315 '/usr/local/sbin', '/usr/local/bin']
317 cmdfull = os.path.join(path, cmd)
318 if os.path.exists(cmdfull):
321 def setPrecision(self, num):
322 if num < 0 or num > 6:
324 self.timeformat = '%.{0}f'.format(num)
325 def setOutputFolder(self, value):
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)
336 self.htmlfile = m.group('name')+'.html'
337 if self.ftracefile != '':
338 m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
340 self.htmlfile = m.group('name')+'.html'
341 def systemInfo(self, info):
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):
359 out = dmidecode(self.mempath, fatal)
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))
370 fp = open('/proc/cpuinfo', 'r')
372 if re.match('^processor[ \t]*:[ \t]*[0-9]*', line):
375 fp = open('/proc/meminfo', 'r')
377 m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
379 self.memtotal = int(m.group('sz'))
380 m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)
382 self.memfree = int(m.group('sz'))
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)
391 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
396 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
398 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
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):
405 for i in value.split(','):
407 out.append(i.strip())
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()
419 nowtime = int(nowtime)
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)
428 # get the latest time stamp from the dmesg log
429 fp = Popen('dmesg', stdout=PIPE).stdout
432 line = line.replace('\r\n', '')
436 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
438 ktime = m.group('ktime')
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
446 line = line.replace('\r\n', '')
450 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
453 ktime = float(m.group('ktime'))
454 if ktime > self.dmesgstart:
458 def listFromFile(self, file):
461 for i in fp.read().split('\n'):
463 if i and i[0] != '#':
467 def addFtraceFilterFunctions(self, file):
468 for i in self.listFromFile(file):
471 self.tracefuncs[i] = dict()
472 def getFtraceFilterFunctions(self, current):
475 call('cat '+self.tpath+'available_filter_functions', shell=True)
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']
484 print self.colorText(i)
485 def setFtraceFilterFunctions(self, list):
486 master = self.listFromFile(self.tpath+'available_filter_functions')
492 flist += i.split(' ')[0]+'\n'
495 fp = open(self.tpath+'set_graph_function', 'w')
498 def basicKprobe(self, name):
499 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
500 def defaultKprobe(self, name, kdata):
502 for field in ['name', 'format', 'func']:
505 if self.archargs in k:
506 k['args'] = k[self.archargs]
510 self.kprobes[name] = k
511 def kprobeColor(self, name):
512 if name not in self.kprobes or 'color' not in self.kprobes[name]:
514 return self.kprobes[name]['color']
515 def kprobeDisplayName(self, name, dataraw):
516 if name not in self.kprobes:
517 self.basicKprobe(name)
520 # first remvoe any spaces inside quotes, and the quotes
523 quote = (quote + 1) % 2
524 if quote and c == ' ':
528 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
530 # now process the args
531 for arg in sorted(args):
533 m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
535 arglist[arg] = m.group('arg')
537 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
539 arglist[arg] = m.group('arg')
540 out = fmt.format(**arglist)
541 out = out.replace(' ', '_').replace('"', '')
543 def kprobeText(self, kname, kprobe):
544 name = fmt = func = kname
547 name = kprobe['name']
548 if 'format' in kprobe:
549 fmt = kprobe['format']
551 func = kprobe['func']
552 if self.archargs in kprobe:
553 args = kprobe[self.archargs]
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):
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)
566 def addKprobes(self, output=False):
567 if len(self.kprobes) < 1:
570 pprint(' kprobe functions in this kernel:')
571 # first test each kprobe
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')
582 if name in self.tracefuncs:
584 elif name in self.dev_tracefuncs:
585 if 'ub' in self.dev_tracefuncs[name]:
592 pprint(' %s: %s' % (name, res))
593 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
594 # remove all failed ones from the list
596 self.kprobes.pop(name)
597 # set the kprobes all at once
598 self.fsetVal('', 'kprobe_events')
601 kprobeevents += self.kprobeText(kp, self.kprobes[kp])
602 self.fsetVal(kprobeevents, 'kprobe_events')
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)
614 self.fsetVal(kprobeevents, 'kprobe_events')
615 check = self.fgetVal('kprobe_events')
618 linesout = len(kprobeevents.split('\n'))
619 linesack = len(check.split('\n'))
620 if linesack < linesout:
623 def setVal(self, val, file, mode='w'):
624 if not os.path.exists(file):
627 fp = open(file, mode, 0)
634 def fsetVal(self, val, path, mode='w'):
635 return self.setVal(val, self.tpath+path, mode)
636 def getVal(self, file):
638 if not os.path.exists(file):
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')
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':
664 for i in self.tracefuncs:
665 if 'func' in self.tracefuncs[i]:
666 f = self.tracefuncs[i]['func']
672 def initFtrace(self):
673 self.printSystemInfo(False)
674 pprint('INITIALIZING FTRACE...')
676 self.fsetVal('0', 'tracing_on')
679 pv = self.getVal(self.pmdpath)
681 self.setVal('1', self.pmdpath)
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)
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)
695 while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
696 # if the size failed to set, lower it and keep trying
699 tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
701 pprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus))
702 # initialize the callgraph trace
703 if(self.usecallgraph):
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'])
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])
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)
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
749 if(self.usecallgraph):
751 'available_filter_functions',
756 if(os.path.exists(tp+f) == False):
759 def verifyKprobes(self):
760 # files needed for kprobes to work
761 files = ['kprobe_events', 'events']
764 if(os.path.exists(tp+f) == False):
767 def colorText(self, str, color=31):
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:
778 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
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'])
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):
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']))
800 fp.write('result%s: pass\n' % n)
801 for v in ['suspend', 'resume', 'boot', 'lastinit']:
803 fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))
804 for v in ['fwsuspend', 'fwresume']:
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']))
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):
815 elif os.path.exists(dir+'/'+file):
817 elif os.path.exists(dir+'/config/'+file):
818 return dir+'/config/'+file
820 def openlog(self, filename, mode):
824 with gzip.open(filename, mode+'b') as fp:
830 return gzip.open(filename, mode+'b')
831 return open(filename, mode)
833 sysvals = SystemValues()
834 switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
835 switchoff = ['disable', 'off', 'false', '0']
837 'freeze': 'Freeze (S0)',
838 'standby': 'Standby (S1)',
839 'mem': 'Suspend (S3)',
840 'disk': 'Hibernate (S4)'
845 # Simple class which holds property values collected
846 # for all the devices used in the timeline.
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:
861 return '%s [%s]' % (self.altname, dev)
864 return ' '+self.xtraclass
870 return ' '+self.xtraclass
872 return ' async_device'
873 return ' sync_device'
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()
880 def __init__(self, nodename, nodedepth):
883 self.depth = nodedepth
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:
891 # 10 sequential, non-overlapping phases of S/R
892 # contents: times for phase start/end, order/color data for html
894 # device callback or action list for this phase
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
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'},
920 'HWERROR' : '.*\[ *Hardware Error *\].*',
921 'FWBUG' : '.*\[ *Firmware Bug *\].*',
923 'ERROR' : '.*ERROR.*',
924 'WARNING' : '.*WARNING.*',
925 'IRQ' : '.*genirq: .*',
926 'TASKFAIL': '.*Freezing of tasks failed.*',
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
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)
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():
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
970 if self.dmesg[p]['order'] == order:
974 plist = self.sortedPhases()
978 def extractErrorInfo(self):
979 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
984 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
987 t = float(m.group('ktime'))
988 if t < self.start or t > self.end:
990 dir = 'suspend' if t < self.tSuspended else 'resume'
992 for err in self.errlist:
993 if re.match(self.errlist[err], msg):
994 list.append((err, dir, t, i, i))
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))
1002 sysvals.dmesglog = True
1004 def setStart(self, time):
1006 def setEnd(self, time):
1008 def isTraceEventOutsideDeviceCalls(self, pid, time):
1009 for phase in self.sortedPhases():
1010 list = self.dmesg[phase]['list']
1013 if(d['pid'] == pid and time >= d['start'] and
1017 def sourcePhase(self, start):
1018 for phase in self.sortedPhases():
1019 if 'machine' in phase:
1021 pend = self.dmesg[phase]['end']
1024 return 'resume_complete'
1025 def sourceDevice(self, phaselist, start, end, pid, type):
1027 for phase in phaselist:
1028 list = self.dmesg[phase]['list']
1029 for devname in list:
1032 if dev['pid'] != pid:
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):
1040 elif type == 'thread':
1041 # thread target event will expand the source boundary
1043 dev['start'] = start
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:
1057 # try to place the call in a thread
1059 tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')
1060 # create new thread blocks, expand as new calls are found
1063 threadname = 'kthread-%d' % (pid)
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
1071 sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \
1072 (start, end, proc, pid, kprobename, cdata, rdata))
1074 # place the call data inside the src element of the tgtdev
1075 if('src' not in tgtdev):
1077 dtf = sysvals.dev_tracefuncs
1079 if kprobename in dtf and 'ub' in dtf[kprobename]:
1081 title = cdata+' '+rdata
1082 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
1083 m = re.match(mstr, title)
1085 c = m.group('caller')
1086 a = m.group('args').strip()
1092 if ubiquitous and c in dtf and 'ub' in dtf[c]:
1094 color = sysvals.kprobeColor(kprobename)
1095 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
1096 tgtdev['src'].append(e)
1098 def overflowDevices(self):
1099 # get a list of devices that extend beyond the end of this test run
1101 for phase in self.sortedPhases():
1102 list = self.dmesg[phase]['list']
1103 for devname in list:
1105 if dev['end'] > self.end:
1108 def mergeOverlapDevices(self, devlist):
1109 # merge any devices that overlap devlist
1111 devname = dev['name']
1112 for phase in self.sortedPhases():
1113 list = self.dmesg[phase]['list']
1114 if devname not in list:
1116 tdev = list[devname]
1117 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
1120 dev['end'] = tdev['end']
1121 if 'src' not in dev or 'src' not in tdev:
1123 dev['src'] += tdev['src']
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']
1131 if tdev['start'] - dev['end'] < 0.1:
1132 dev['end'] = tdev['end']
1133 if 'src' not in dev:
1136 dev['src'] += tdev['src']
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:
1145 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
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']
1154 if 'src' not in list[dev]:
1156 src = list[dev]['src']
1158 for e in sorted(src, key=lambda event: event.time):
1159 if not p or not e.repeat(p):
1162 # e is another iteration of p, move it into p
1164 p.length = p.end - p.time
1167 def trimTimeVal(self, t, t0, dT, left):
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)
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']
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)
1207 e.time = self.trimTimeVal(e.time, t0, dT, left)
1208 for dir in ['suspend', 'resume']:
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
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']
1223 left = True if tR > tZero else False
1224 self.trimTime(tS, tL, left)
1225 self.tLow.append('%.0f'%(tL*1000))
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):
1233 # phase start over current phase
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:
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
1249 # phase end without a start
1250 if phase not in self.currphase:
1252 sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))
1254 sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)
1256 phase = self.currphase
1257 self.dmesg[phase]['end'] = ktime
1260 def sortedDevices(self, phase):
1261 list = self.dmesg[phase]['list']
1264 for devname in list:
1266 if dev['length'] == 0:
1268 tmp[dev['start']] = devname
1269 for t in sorted(tmp):
1270 slist.append(tmp[t])
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]
1278 for p in self.sortedPhases():
1279 if self.dmesg[p]['end'] > dev['start']:
1280 dev['end'] = self.dmesg[p]['end']
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']
1289 for filter in devicefilter:
1290 if filter in name or \
1291 ('drv' in list[name] and filter in list[name]['drv']):
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):
1304 for group in self.devicegroups:
1305 for phase in phases:
1306 if phase not in group:
1309 if p not in newgroup:
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'
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))
1329 myphases.append(phase)
1330 # set the target phase to the one that overlaps most
1332 if overlap > 0 and phase == 'post_resume':
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]
1342 targetphase = phases[-1]
1347 if len(myphases) > 1:
1349 self.phaseOverlap(myphases)
1350 if targetphase in phases:
1351 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1352 return (targetphase, newname)
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']
1360 if(start >= 0 and end >= 0):
1361 length = end - start
1365 while(name in list):
1366 name = '%s[%d]' % (origname, i)
1368 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,
1369 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }
1371 list[name]['htmlclass'] = htmlclass
1373 list[name]['color'] = color
1375 def deviceChildren(self, devname, phase):
1377 list = self.dmesg[phase]['list']
1379 if(list[child]['par'] == devname):
1380 devlist.append(child)
1382 def maxDeviceNameSize(self, phase):
1384 for name in self.dmesg[phase]['list']:
1385 if len(name) > 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)
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)
1399 if not tR and ps >= self.tResumed:
1400 sysvals.vprint(' machine resumed: %f' % self.tResumed)
1402 sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc))
1404 sysvals.vprint(''.join('-' for i in range(80)))
1405 maxname = '%d' % self.maxDeviceNameSize(phase)
1406 fmt = '%3d) %'+maxname+'s - %f - %f'
1408 for name in devlist:
1409 s = devlist[name]['start']
1410 e = devlist[name]['end']
1411 sysvals.vprint(fmt % (c, name, s, e))
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):
1418 for phase in self.sortedPhases():
1419 list = self.deviceChildren(devname, phase)
1421 if dev not in devlist:
1424 def masterTopology(self, name, list, depth):
1425 node = DeviceNode(name, depth)
1430 clist = self.deviceChildrenAllPhases(cname)
1431 cnode = self.masterTopology(cname, clist, depth+1)
1432 node.children.append(cnode)
1434 def printTopology(self, node):
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>'
1449 html += '<ul>'+info+'</ul>'
1451 if len(node.children) > 0:
1453 for cnode in node.children:
1454 html += self.printTopology(cnode)
1457 def rootDeviceList(self):
1458 # list of devices graphed
1460 for phase in self.dmesg:
1461 list = self.dmesg[phase]['list']
1463 if list[dev]['pid'] >= 0 and dev not in real:
1465 # list of top-most root devices
1467 for phase in self.dmesg:
1468 list = self.dmesg[phase]['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)):
1474 if pdev and pdev not in real and pdev not in rootlist:
1475 rootlist.append(pdev)
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:
1486 list = self.dmesg[phase]['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:
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])
1502 def addProcessUsageEvent(self, name, times):
1503 # get the start and end times for this process
1508 for t in sorted(times):
1512 if name in self.pstl[t]:
1513 if start == -1 or tlast < start:
1515 if end == -1 or t > end:
1518 if start == -1 or end == -1:
1520 # add a new action for this process and get the object
1521 out = self.newActionGlobal(name, start, end, -3)
1524 phase, devname = out
1525 dev = self.dmesg[phase]['list'][devname]
1526 # get the cpu exec data
1530 for t in sorted(times):
1531 if tlast == 0 or t <= start or t > end:
1545 dev['cpuexec'] = cpuexec
1547 def createProcessUsageEvents(self):
1548 # get an array of process names
1551 pslist = self.pstl[t]
1553 if ps not in proclist:
1555 # get a list of data points for suspend and resume
1558 for t in sorted(self.pstl):
1559 if t < self.tSuspended:
1563 # process the events for suspend and resume
1564 if len(proclist) > 0:
1565 sysvals.vprint('Process Execution:')
1567 c = self.addProcessUsageEvent(ps, tsus)
1569 sysvals.vprint('%25s (sus): %d' % (ps, c))
1570 c = self.addProcessUsageEvent(ps, tres)
1572 sysvals.vprint('%25s (res): %d' % (ps, c))
1573 def handleEndMarker(self, 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)
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:
1600 dev['ftrace'].debugPrint(' [%s]' % devname)
1602 # Class: DevFunction
1604 # A container for kprobe function data we want in the dev timeline
1606 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
1611 self.caller = caller
1614 self.length = end - start
1623 cnt = '(x%d)' % self.count
1624 l = '%0.3fms' % (self.length * 1000)
1626 title = '%s(%s)%s <- %s, %s(%s)' % \
1627 (self.name, self.args, cnt, self.caller, self.ret, l)
1629 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
1630 return title.replace('"', '')
1633 text = '%s(x%d)' % (self.name, self.count)
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:
1652 # A container for a single line of ftrace data. There are six basic types:
1654 # call: " dpm_run_callback() {"
1656 # leaf: " dpm_run_callback();"
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
1662 def __init__(self, t, m='', d=''):
1665 self.freturn = False
1667 self.fkprobe = False
1671 self.time = float(t)
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
1680 # function_graph format trace event
1681 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
1682 msg = em.group('msg')
1684 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
1686 self.name = emm.group('msg')
1687 self.type = emm.group('call')
1690 km = re.match('^(?P<n>.*)_cal$', self.type)
1694 self.type = km.group('n')
1696 km = re.match('^(?P<n>.*)_ret$', self.type)
1700 self.type = km.group('n')
1704 # convert the duration to seconds
1706 self.length = float(d)/1000000
1707 # the indentation determines the depth
1708 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
1711 self.depth = self.getDepth(match.group('d'))
1712 m = match.group('o')
1717 # includes comment with function name
1718 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
1720 self.name = match.group('n').strip()
1724 # function call with children
1726 match = re.match('^(?P<n>.*) *\(.*', m)
1728 self.name = match.group('n').strip()
1729 # function call with no children (leaf)
1732 match = re.match('^(?P<n>.*) *\(.*', m)
1734 self.name = match.group('n').strip()
1735 # something else (possibly a trace marker)
1739 return self.fcall and not self.freturn
1741 return self.freturn and not self.fcall
1743 return self.fcall and self.freturn
1744 def getDepth(self, str):
1746 def debugPrint(self, info=''):
1748 pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
1749 self.depth, self.name, self.length*1000000, info))
1751 pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
1752 self.depth, self.name, self.length*1000000, info))
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?
1760 if sysvals.usetracemarkers:
1761 if(self.name == 'SUSPEND START'):
1765 if(self.type == 'suspend_resume' and
1766 re.match('suspend_enter\[.*\] begin', self.name)):
1769 def endMarker(self):
1770 # Is this the ending line of a resume?
1773 if sysvals.usetracemarkers:
1774 if(self.name == 'RESUME COMPLETE'):
1778 if(self.type == 'suspend_resume' and
1779 re.match('thaw_processes\[.*\] end', self.name)):
1783 # Class: FTraceCallGraph
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):
1793 self.invalid = False
1795 self.partial = False
1803 def addLine(self, line):
1804 # if this is already invalid, just leave
1806 if(line.depth == 0 and line.freturn):
1809 # invalidate on bad depth
1811 self.invalidate(line)
1813 # ignore data til we return to the current depth
1815 if line.depth > self.depth:
1818 self.list[-1].freturn = True
1819 self.list[-1].length = line.time - self.list[-1].time
1821 # if this is a return at self.depth, no more work is needed
1822 if line.depth == self.depth and line.isReturn():
1824 self.end = line.time
1827 # compare current depth with this lines pre-call depth
1828 prelinedep = line.depth
1832 lasttime = line.time
1833 if len(self.list) > 0:
1834 last = self.list[-1]
1835 lasttime = last.time
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
1844 # add return calls to get the depth down
1845 while prelinedep < self.depth:
1847 if idx == 0 and last and last.isCall():
1848 # special case, turn last call into a leaf
1849 last.depth = self.depth
1851 last.length = line.time - last.time
1853 info.append(('[make leaf]', last))
1855 vline = FTraceLine(lasttime)
1856 vline.depth = self.depth
1857 vline.name = self.vfname
1858 vline.freturn = True
1859 self.list.append(vline)
1862 info.append(('', last))
1863 info.append(('[add return]', vline))
1866 info.append(('', line))
1867 # handle high misalignments by inserting calls
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
1879 info.append(('[make leaf]', line))
1881 vline = FTraceLine(lasttime)
1882 vline.depth = self.depth
1883 vline.name = self.vfname
1885 self.list.append(vline)
1888 self.start = vline.time
1890 info.append(('[add call]', vline))
1892 if warning and ('[make leaf]', line) not in info:
1893 info.append(('', line))
1895 pprint('WARNING: ftrace data missing, corrections made:')
1900 # process the call and set the new depth
1902 md = self.sv.max_graph_depth
1904 # ignore blacklisted/overdepth funcs
1905 if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):
1909 elif line.isReturn():
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:
1917 if len(self.list) == 0:
1920 self.list[-1].freturn = True
1921 self.list[-1].length = line.time - self.list[-1].time
1922 self.list[-1].name = line.name
1924 if len(self.list) < 1:
1925 self.start = line.time
1926 # check for a mismatch that returned all the way to callgraph end
1928 if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn:
1929 line = self.list[-1]
1933 self.list.append(line)
1934 if(line.depth == 0 and line.freturn):
1936 self.start = line.time
1937 self.end = line.time
1939 self.end += line.length
1940 if self.list[0].name == self.vfname:
1946 def invalidate(self, line):
1947 if(len(self.list) > 0):
1948 first = self.list[0]
1950 self.list.append(first)
1952 id = 'task %s' % (self.pid)
1953 window = '(%f - %f)' % (self.start, line.time)
1955 pprint('Data misalignment for '+id+\
1956 ' (buffer overflow), ignoring this callback')
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
1966 if(l.time < dev['start'] or l.time > dev['end']):
1969 if l.name == 'mutex_lock' and l.freturn:
1972 elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall:
1977 if not good or len(minicg.list) < 1:
1980 def repair(self, enddepth):
1981 # bring the depth back to 0 with additional returns
1983 last = self.list[-1]
1984 for i in reversed(range(enddepth)):
1985 t = FTraceLine(last.time)
1988 fixed = self.addLine(t)
1990 self.end = last.time
1993 def postProcess(self):
1994 if len(self.list) > 0:
1995 self.name = self.list[0].name
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
2009 if(l.depth not in stack):
2011 pprint('Post Process Error: Depth missing')
2014 # calculate call length from call/return lines
2016 cl.length = l.time - cl.time
2017 if cl.name == self.vfname:
2024 # trace caught the whole call tree
2028 pprint('Post Process Error: Depth is less than 0')
2030 # trace ended before call tree finished
2031 return self.repair(cnt)
2032 def deviceMatch(self, pid, data):
2034 # add the callgraph data to the device hierarchy
2036 'dpm_prepare': 'suspend_prepare',
2037 'dpm_complete': 'resume_complete'
2039 if(self.name in borderphase):
2040 p = borderphase[self.name]
2041 list = data.dmesg[p]['list']
2042 for devname in list:
2044 if(pid == dev['pid'] and
2045 self.start <= dev['start'] and
2046 self.end >= dev['end']):
2047 cg = self.slice(dev)
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:
2058 if(pid == dev['pid'] and
2059 self.start <= dev['start'] and
2060 self.end >= dev['end']):
2061 dev['ftrace'] = self
2066 def newActionFromFunction(self, data):
2068 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
2072 if fs < data.start or fe > data.end:
2075 for p in data.sortedPhases():
2076 if(data.dmesg[p]['start'] <= self.start and
2077 self.start < data.dmesg[p]['end']):
2082 out = data.newActionGlobal(name, fs, fe, -2)
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))
2092 pprint('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
2093 l.depth, l.name, l.length*1000000, info))
2095 pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \
2096 l.depth, l.name, l.length*1000000, info))
2098 pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
2099 l.depth, l.name, l.length*1000000, info))
2103 def __init__(self, test, phase, dev):
2108 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:
2114 # A container for a device timeline which calculates
2115 # all the html properties to display it correctly
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}"> {2}</div>\n'
2122 def __init__(self, rowheight, scaleheight):
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']):
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>'
2139 self.html += '<button id="showdmesg" class="logbtn btnfmt">dmesg</button>'
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'])
2150 # Function: getDeviceRows
2152 # determine how may rows the device funcs will take
2154 # rawlist: the list of devices/actions for a single phase
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
2160 for item in rawlist:
2162 sortdict[item] = item.length
2163 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
2164 remaining = len(sortlist)
2167 # try to pack each row with as many ranges as possible
2168 while(remaining > 0):
2169 if(row not in rowdata):
2175 e = i.time + i.length
2177 for ritem in rowdata[row]:
2179 re = ritem.time + ritem.length
2180 if(not (((s <= rs) and (e <= rs)) or
2181 ((s >= re) and (e >= re)))):
2185 rowdata[row].append(i)
2190 # Function: getPhaseRows
2192 # Organize the timeline entries into the smallest
2193 # number of rows possible, with no entry overlapping
2195 # devlist: the list of devices/actions in a group of contiguous phases
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)
2204 # initialize all device rows to -1 and calculate devrows
2205 for item in devlist:
2207 tp = (item.test, item.phase)
2208 if tp not in myphases:
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']))
2215 # sort by length 1st, then name 2nd
2216 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])
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)
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):
2231 if(row not in rowdata):
2233 for item in orderedlist:
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)))):
2247 rowdata[row].append(item)
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()
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']:
2265 self.rowlines[t][p][row] = rowheight
2266 self.rowheight[t][p][row] = rowheight * rh
2268 if(row > self.rows):
2269 self.rows = int(row)
2271 def phaseRowHeight(self, test, phase, row):
2272 return self.rowheight[test][phase][row]
2273 def phaseRowTop(self, test, phase, row):
2275 for i in sorted(self.rowheight[test][phase]):
2278 top += self.rowheight[test][phase][i]
2280 def calcTotalRows(self):
2281 # Calculate the heights and offsets for the header and rows
2284 for t in self.rowlines:
2285 for p in self.rowlines[t]:
2287 for i in sorted(self.rowlines[t][p]):
2288 total += self.rowlines[t][p][i]
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':
2307 self.html += html_devlist2
2308 self.html += html_devlist1.format('1')
2310 self.html += html_devlist1.format('')
2311 self.html += html_zoombox
2312 self.html += html_timeline.format('dmesg', self.height)
2313 # Function: createTimeScale
2315 # Create the timescale for a timeline block
2317 # m0: start time (mode begin)
2318 # mMax: end time (mode end)
2319 # tTotal: total timeline time
2320 # mode: suspend or resume
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
2331 return output+'</div>\n'
2334 divTotal = int(mTotal/tS) + 1
2335 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
2336 for i in range(divTotal):
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):
2343 htmlline = timescale.format(pos, val)
2345 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
2346 val = '%0.fms' % (float(i)*tS*1000)
2347 htmlline = timescale.format(pos, val)
2349 htmlline = rline.format(mode)
2351 self.html += output+'</div>\n'
2355 # A list of values describing the properties of these test runs
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\.]*): *'+\
2385 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2386 self.cgformat = False
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
2396 doError('Invalid tracer format: [%s]' % tracer)
2397 def parseStamp(self, data, sv):
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')),
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('|'):
2412 tmp = f.strip().split(':', 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')
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
2428 m = re.match(self.cmdlinefmt, self.cmdline)
2430 sv.cmdline = m.group('cmd')
2432 m = re.match(self.kparamsfmt, self.kparams)
2434 sv.kparams = m.group('kp')
2436 sv.stamp = data.stamp
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):
2443 if len(self.battery) > data.testnumber:
2444 m = re.match(self.batteryfmt, self.battery[data.testnumber])
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])
2451 data.enterfail = m.group('e')
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.
2458 def __init__(self, dataobj):
2463 class ProcessMonitor:
2465 self.proclist = dict()
2466 self.running = False
2468 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
2469 process = Popen(c, shell=True, stdout=PIPE)
2471 for line in process.stdout:
2474 name = re.sub('[()]', '', data[1])
2475 user = int(data[13])
2476 kern = int(data[14])
2478 if pid not in self.proclist:
2479 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern}
2481 val = self.proclist[pid]
2482 ujiff = user - val['user']
2483 kjiff = kern - val['kern']
2486 if ujiff > 0 or kjiff > 0:
2487 running[pid] = ujiff + kjiff
2491 jiffies = running[pid]
2492 val = self.proclist[pid]
2495 out += '%s-%s %d' % (val['name'], pid, jiffies)
2497 def processMonitor(self, tid):
2499 out = self.procstat()
2501 sysvals.fsetVal(out, 'trace_marker')
2503 self.thread = Thread(target=self.processMonitor, args=(0,))
2507 self.running = False
2509 # ----------------- FUNCTIONS --------------------
2511 # Function: doesTraceLogHaveTraceEvents
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')
2523 if not sysvals.usekprobes:
2526 sysvals.usekprobes = True
2527 # check for all necessary trace events
2533 # check for all necessary trace markers
2540 sysvals.usetraceevents = True if len(techeck) < 2 else False
2541 sysvals.usetracemarkers = True if len(tmcheck) == 0 else False
2543 # Function: appendIncompleteTraceLog
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
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)
2555 for data in testruns:
2556 testrun.append(TestRun(data))
2558 # extract the callgraph and traceevent data
2559 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
2560 os.path.basename(sysvals.ftracefile))
2562 tf = sysvals.openlog(sysvals.ftracefile, 'r')
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):
2571 elif re.match(tp.sysinfofmt, line):
2574 elif re.match(tp.cmdlinefmt, line):
2577 elif re.match(tp.batteryfmt, line):
2578 tp.battery.append(line)
2580 elif re.match(tp.testerrfmt, line):
2581 tp.testerror.append(line)
2583 # determine the trace data type (required for further parsing)
2584 m = re.match(tp.tracertypefmt, line)
2586 tp.setTracerType(m.group('t'))
2588 # device properties line
2589 if(re.match(tp.devpropfmt, line)):
2592 # parse only valid lines, if this is not one move on
2593 m = re.match(tp.ftrace_line_fmt, line)
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')
2601 m_param3 = m.group('dur')
2603 m_param3 = 'traceevent'
2604 if(m_time and m_pid and m_msg):
2605 t = FTraceLine(m_time, m_msg, m_param3)
2609 # the line should be a call, return, or event
2610 if(not t.fcall and not t.freturn and not t.fevent):
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)
2620 # find the end of resume
2624 if(testidx >= testcnt):
2627 # trace event processing
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]
2640 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
2642 testrun[testidx].ftemp[pid][-1].addLine(t)
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):
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')
2656 callstart = cg.start
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:
2664 if(pid == dev['pid'] and
2665 callstart <= dev['start'] and
2666 callend >= dev['end']):
2670 # Function: parseTraceLog
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
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)
2684 sysvals.setupAllKprobes()
2685 ksuscalls = ['pm_prepare_console']
2686 krescalls = ['pm_restore_console']
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']
2693 # extract the callgraph and traceevent data
2699 tf = sysvals.openlog(sysvals.ftracefile, 'r')
2700 phase = 'suspend_prepare'
2702 # remove any latent carriage returns
2703 line = line.replace('\r\n', '')
2704 # stamp and sysinfo lines
2705 if re.match(tp.stampfmt, line):
2708 elif re.match(tp.sysinfofmt, line):
2711 elif re.match(tp.cmdlinefmt, line):
2714 elif re.match(tp.batteryfmt, line):
2715 tp.battery.append(line)
2717 elif re.match(tp.testerrfmt, line):
2718 tp.testerror.append(line)
2720 # firmware line: pull out any firmware data
2721 m = re.match(tp.firmwarefmt, line)
2723 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2725 # tracer type line: determine the trace data type
2726 m = re.match(tp.tracertypefmt, line)
2728 tp.setTracerType(m.group('t'))
2730 # device properties line
2731 if(re.match(tp.devpropfmt, line)):
2734 # ignore all other commented lines
2737 # ftrace line: parse only valid lines
2738 m = re.match(tp.ftrace_line_fmt, line)
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')
2747 m_param3 = m.group('dur')
2749 m_param3 = 'traceevent'
2750 if(m_time and m_pid and m_msg):
2751 t = FTraceLine(m_time, m_msg, m_param3)
2755 # the line should be a call, return, or event
2756 if(not t.fcall and not t.freturn and not t.fevent):
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)
2771 # process cpu exec line
2772 if t.type == 'tracing_mark_write':
2773 m = re.match(tp.procexecfmt, t.name)
2776 for ps in m.group('ps').split(','):
2780 name = val[0].replace('--', '-')
2781 proclist[name] = int(val[1])
2782 data.pstl[t.time] = proclist
2784 # find the end of resume
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
2795 # trace event processing
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)):
2801 elif(re.match('(?P<name>.*) end$', t.name)):
2805 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2807 val = m.group('val')
2809 name = m.group('name')
2811 name = m.group('name')+'['+val+']'
2813 m = re.match('(?P<name>.*) .*', t.name)
2814 name = m.group('name')
2815 # ignore these events
2816 if(name.split('[')[0] in tracewatch):
2818 # -- phase changes --
2819 # start of kernel suspend
2820 if(re.match('suspend_enter\[.*', t.name)):
2822 data.tKernSus = t.time
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
2831 phase = data.setPhase('suspend_prepare', t.time, isbegin)
2834 elif(re.match('dpm_suspend\[.*', t.name)):
2835 phase = data.setPhase('suspend', t.time, isbegin)
2837 # suspend_late start
2838 elif(re.match('dpm_suspend_late\[.*', t.name)):
2839 phase = data.setPhase('suspend_late', t.time, isbegin)
2841 # suspend_noirq start
2842 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2843 phase = data.setPhase('suspend_noirq', t.time, isbegin)
2845 # suspend_machine/resume_machine
2846 elif(re.match('machine_suspend\[.*', t.name)):
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
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
2862 # resume_noirq start
2863 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2864 phase = data.setPhase('resume_noirq', t.time, isbegin)
2866 # resume_early start
2867 elif(re.match('dpm_resume_early\[.*', t.name)):
2868 phase = data.setPhase('resume_early', t.time, isbegin)
2871 elif(re.match('dpm_resume\[.*', t.name)):
2872 phase = data.setPhase('resume', t.time, isbegin)
2874 # resume complete start
2875 elif(re.match('dpm_complete\[.*', t.name)):
2876 phase = data.setPhase('resume_complete', t.time, isbegin)
2878 # skip trace events inside devices calls
2879 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2881 # global events (outside device calls) are graphed
2882 if(name not in testrun.ttemp):
2883 testrun.ttemp[name] = []
2885 # create a new list entry
2886 testrun.ttemp[name].append(\
2887 {'begin': t.time, 'end': t.time, 'pid': pid})
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:
2896 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2900 drv = m.group('drv')
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:
2911 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2915 list = data.dmesg[phase]['list']
2918 dev['length'] = t.time - dev['start']
2920 # kprobe event processing
2924 key = (kprobename, pid)
2925 # displayname is generated from kprobe data
2928 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2931 if(key not in tp.ktemp):
2933 tp.ktemp[key].append({
2937 'name': displayname,
2938 'cdata': kprobedata,
2941 # start of kernel resume
2942 if(phase == 'suspend_prepare' and kprobename in ksuscalls):
2943 data.tKernSus = t.time
2945 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2947 e = tp.ktemp[key][-1]
2948 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
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
2959 # callgraph processing
2960 elif sysvals.usecallgraph:
2961 # create a callgraph object for the data
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]
2970 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
2972 testrun.ftemp[key][-1].addLine(t)
2974 if data and not data.devicegroups:
2975 sysvals.vprint('WARNING: end marker is missing')
2976 data.handleEndMarker(t.time)
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
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
2991 # dev source and procmon events can be unreadable with mixed phase height
2992 if sysvals.usedevsrc or sysvals.useprocmon:
2993 sysvals.mixedphaseheight = False
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']
3003 for i in range(len(testruns)):
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:
3022 if name not in sysvals.tracefuncs:
3024 for e in tp.ktemp[key]:
3025 kb, ke = e['begin'], e['end']
3026 if kb == ke or tlb > kb or tle <= kb:
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:
3034 if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs:
3036 for e in tp.ktemp[key]:
3037 kb, ke = e['begin'], e['end']
3038 if kb == ke or tlb > kb or tle <= kb:
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
3045 for key in test.ftemp:
3047 for cg in test.ftemp[key]:
3048 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
3050 if(not cg.postProcess()):
3051 id = 'task %s' % (pid)
3052 sysvals.vprint('Sanity check failed for '+\
3053 id+', ignoring this callback')
3055 # match cg data to devices
3057 if sysvals.suspendmode != 'command':
3058 devname = cg.deviceMatch(pid, data)
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]
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, '')
3075 # fill in any missing phases
3077 for data in testdata:
3078 tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))
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:
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)
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)
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)
3099 if data.tSuspended == 0:
3100 data.tSuspended = data.tKernRes
3101 if data.tResumed == 0:
3102 data.tResumed = data.tSuspended
3104 if(len(sysvals.devicefilter) > 0):
3105 data.deviceFilter(sysvals.devicefilter)
3106 data.fixupInitcallsThatDidntReturn()
3107 if sysvals.usedevsrc:
3108 data.optimizeDevSrc()
3110 # x2: merge any overlapping devices between test runs
3111 if sysvals.usedevsrc and len(testdata) > 1:
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))
3120 # Function: loadKernelLog
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
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)
3133 # there can be multiple test runs in a single file
3135 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
3138 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
3140 line = line.replace('\r\n', '')
3141 idx = line.find('[')
3144 # grab the stamp and sysinfo
3145 if re.match(tp.stampfmt, line):
3148 elif re.match(tp.sysinfofmt, line):
3151 elif re.match(tp.cmdlinefmt, line):
3154 elif re.match(tp.batteryfmt, line):
3155 tp.battery.append(line)
3157 elif re.match(tp.testerrfmt, line):
3158 tp.testerror.append(line)
3160 m = re.match(tp.firmwarefmt, line)
3162 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
3164 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
3167 msg = m.group("msg")
3168 if(re.match('PM: Syncing filesystems.*', msg)):
3170 testruns.append(data)
3171 data = Data(len(testruns))
3172 tp.parseStamp(data, sysvals)
3175 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
3177 sysvals.stamp['kernel'] = m.group('k')
3178 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
3180 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')
3181 data.dmesgtext.append(line)
3185 testruns.append(data)
3186 if len(testruns) < 1:
3187 pprint('ERROR: dmesg log has no suspend/resume data: %s' \
3188 % sysvals.dmesgfile)
3190 # fix lines with same timestamp/function with the call and return swapped
3191 for data in testruns:
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
3207 # Function: parseKernelLog
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.
3216 # data: an empty Data object (with dmesgtext) obtained from loadKernelLog
3218 # The filled Data object
3219 def parseKernelLog(data):
3220 phase = 'suspend_runtime'
3223 sysvals.vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
3224 (data.fwSuspend, data.fwResume))
3226 # dmesg phase match table
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 \.\.\..*'],
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']
3253 # action table (expected events that occur and show up in dmesg)
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.*' },
3262 'smsg': 'Freezing remaining freezable tasks.*',
3263 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
3265 'smsg': 'ACPI: Preparing to enter system sleep state.*',
3266 'emsg': 'PM: Saving platform NVS memory.*' },
3268 'smsg': 'PM: Saving platform NVS memory.*',
3269 'emsg': 'Disabling non-boot CPUs .*' },
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)
3280 val = m.group('ktime')
3285 msg = m.group('msg')
3286 # initialize data start to first line time
3288 data.setStart(ktime)
3293 # check for a phase change line
3297 if(re.match(s, msg)):
3298 phasechange, phase = True, p
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)
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()
3317 data.setPhase(lp, ktime, False)
3318 data.setPhase(phase, ktime, True)
3319 elif phase == 'suspend_late':
3320 lp = data.lastPhase()
3322 data.setPhase(lp, ktime, False)
3323 data.setPhase(phase, ktime, True)
3324 elif phase == 'suspend_noirq':
3325 lp = data.lastPhase()
3327 data.setPhase(lp, ktime, False)
3328 data.setPhase(phase, ktime, True)
3329 elif phase == 'suspend_machine':
3330 lp = data.lastPhase()
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
3339 data.setPhase(lp, prevktime, False)
3341 data.tSuspended = ktime
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()
3349 data.setPhase(lp, ktime, False)
3350 data.setPhase(phase, ktime, True)
3351 elif phase == 'resume_early':
3352 lp = data.lastPhase()
3354 data.setPhase(lp, ktime, False)
3355 data.setPhase(phase, ktime, True)
3356 elif phase == 'resume':
3357 lp = data.lastPhase()
3359 data.setPhase(lp, ktime, False)
3360 data.setPhase(phase, ktime, True)
3361 elif phase == 'resume_complete':
3362 lp = data.lastPhase()
3364 data.setPhase(lp, ktime, False)
3365 data.setPhase(phase, ktime, True)
3366 elif phase == 'post_resume':
3367 lp = data.lastPhase()
3369 data.setPhase(lp, ktime, False)
3371 data.tKernRes = ktime
3374 # -- device callbacks --
3375 if(phase in data.sortedPhases()):
3377 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3378 sm = re.match('calling (?P<f>.*)\+ @ '+\
3379 '(?P<n>.*), parent: (?P<p>.*)', msg);
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);
3392 list = data.dmesg[phase]['list']
3395 dev['length'] = int(t)
3398 # if trace events are not available, these are better than nothing
3399 if(not sysvals.usetraceevents):
3400 # look for known actions
3402 if(re.match(at[a]['smsg'], msg)):
3403 if(a not in actions):
3405 actions[a].append({'begin': ktime, 'end': ktime})
3406 if(re.match(at[a]['emsg'], msg)):
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
3413 elif(re.match('Enabling non-boot CPUs .*', msg)):
3414 # start of first cpu resume
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):
3422 actions[cpu].append({'begin': cpu_start, 'end': 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):
3430 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3433 data.initDevicegroups()
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:
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)
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']
3454 if data.tSuspended == 0:
3455 data.tSuspended = data.tKernRes
3456 if data.tResumed == 0:
3457 data.tResumed = data.tSuspended
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'])
3464 if(len(sysvals.devicefilter) > 0):
3465 data.deviceFilter(sysvals.devicefilter)
3466 data.fixupInitcallsThatDidntReturn()
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'
3478 cglen = (cg.end - cg.start) * 1000
3479 if cglen < sv.mincglen:
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))
3486 for line in cg.list:
3487 if(line.length < 0.000000001):
3490 fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'
3491 flen = fmt % (line.length*1000, line.time)
3493 hf.write(html_func_leaf.format(line.name, flen))
3495 hf.write(html_func_end)
3497 hf.write(html_func_start.format(num, line.name, flen))
3499 hf.write(html_func_end)
3502 def addCallgraphs(sv, hf, data):
3503 hf.write('<section id="callgraphs" class="callgraph">\n')
3504 # write out the ftrace data converted to html
3506 for p in data.sortedPhases():
3507 if sv.cgphase and p != sv.cgphase:
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:
3515 if 'color' in data.dmesg[p]:
3516 color = data.dmesg[p]['color']
3518 color = dev['color']
3520 if(devname in sv.devprops):
3521 name = sv.devprops[devname].altName(devname)
3522 if sv.suspendmode in suspendmodename:
3524 if('ftrace' in dev):
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+' → '+cg.name, color, dev['id'])
3532 hf.write('\n\n </section>\n')
3534 # Function: createHTMLSummarySimple
3536 # Create summary html file for a series of tests
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'
3559 # extract the test data into list
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]
3566 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
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:
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]
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
3591 cnt[data['result']] += 1
3592 if data['result'] == 'pass':
3594 tMed[i].append(tVal[i])
3596 if tMin[i] == 0 or tVal[i] < tMin[i]:
3599 if tMax[i] == 0 or tVal[i] > tMax[i]:
3604 if lastmode and num > 0:
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)
3616 for ilk in sorted(cnt, reverse=True):
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'
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'
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> '+\
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>'+\
3645 headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=12></td></tr>\n'
3647 # header line for each suspend mode
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],
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 []
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)
3672 tag = 's%s' % mode if i == 0 else 'r%s' % mode
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
3696 # flush the data to file
3697 hf = open(htmlfile, 'w')
3698 hf.write(html+'</table>\n</body>\n</html>\n')
3703 if value < 10 or value > 19:
3706 elif value % 10 == 2:
3708 elif value % 10 == 3:
3710 return '%d%s' % (value, suffix)
3712 # Function: createHTML
3714 # Create the output html file from the resident test data
3716 # testruns: array of Data objects from parseKernelLog or parseTraceLog
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')
3725 for data in testruns:
3728 if(sysvals.suspendmode in ['freeze', 'standby']):
3729 data.trimFreezeTime(testruns[-1].tSuspended)
3731 # html function templates
3732 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</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>'\
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>'\
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>'\
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>'\
3754 html_fail = '<table class="testfail"><tr><td>{0}</td></tr></table>\n'
3756 # html format variables
3762 devtl = Timeline(30, scaleH)
3764 # write the test title and general info header
3765 devtl.createHeader(sysvals, testruns[0].stamp)
3767 # Generate the header for this timeline
3768 for data in testruns:
3769 tTotal = data.end - data.start
3770 sktime, rktime = data.getTimeValues()
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
3780 testdesc = 'unknown'
3781 if(len(testruns) > 1):
3782 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3783 thtml = html_timetotal3.format(run_time, testdesc)
3786 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3787 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
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)
3795 if(len(data.tLow) == 0):
3796 thtml = html_timetotal.format(suspend_time, \
3797 resume_time, testdesc1, stitle, rtitle)
3799 thtml = html_timetotal2.format(suspend_time, low_time, \
3800 resume_time, testdesc1, stitle, rtitle)
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)
3807 suspend_time = '%.3f' % sktime
3808 resume_time = '%.3f' % rktime
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)
3818 thtml = html_timetotal2.format(suspend_time, low_time, \
3819 resume_time, testdesc, stitle, rtitle)
3823 devtl.html += html_fail.format(testfail)
3825 # time scale for potentially multiple datasets
3826 t0 = testruns[0].start
3827 tMax = testruns[-1].end
3830 # determine the maximum number of rows we need to draw
3835 for data in testruns:
3836 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
3837 for group in data.devicegroups:
3840 for devname in data.tdevlist[phase]:
3841 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3844 threadlist.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'
3858 msg = 'user processes'
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()
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)
3879 phases['suspend'].append(phase)
3880 # now draw the actual timeline blocks
3882 # draw suspend and resume blocks separately
3883 bname = '%s%d' % (dir[0], data.testnumber)
3884 if dir == 'suspend':
3886 mMax = data.tSuspended
3887 left = '%f' % (((m0-t0)*100.0)/tTotal)
3889 m0 = data.tSuspended
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)
3896 # if a timeline block is 0 length, skip altogether
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]:
3926 if 'htmlclass' in dev:
3927 xtraclass = dev['htmlclass']
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':
3949 title += 'pre_suspend_process'
3951 title += 'post_resume_process'
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']):
3960 j = float(dev['cpuexec'][t]) / 5
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
3969 html_cpuexec.format(left, top, height, width, color)
3970 if('src' not in dev):
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)
3980 xtrastyle = 'background:%s;' % e.color
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'
3988 # timeline is finished
3989 devtl.html += '</div>\n</div>\n'
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('_'):
4001 order = '%.2f' % ((p['order'] * pdelta) + pmargin)
4002 name = string.replace(phase, '_', ' ')
4003 devtl.html += devtl.html_legend.format(order, p['color'], name, id)
4004 devtl.html += '</div>\n'
4006 hf = open(sysvals.htmlfile, 'w')
4007 addCSS(hf, sysvals, len(testruns), kerror)
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', \
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', \
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')
4033 # write the ftrace data (callgraph)
4034 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
4035 data = testruns[sysvals.cgtest]
4038 if sysvals.usecallgraph:
4039 addCallgraphs(sysvals, hf, data)
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')
4049 line = line.replace('<', '<').replace('>', '>')
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')
4060 hf.write('</div>\n')
4062 # write the footer and close
4063 addScriptCode(hf, testruns)
4064 hf.write('</body>\n</html>\n')
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
4076 # various format changes by flags
4078 cgnchk = 'not(:checked)'
4080 cgchk = 'not(:checked)'
4083 hoverZ = 'z-index:8;'
4087 devlistpos = 'absolute'
4089 devlistpos = 'relative'
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\
4161 </style>\n</head>\n<body>\n'
4162 hf.write(html_header)
4164 # Function: addScriptCode
4166 # Adds the javascript code to the output html
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
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→</cS></div>\';\n'\
4207 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
4209 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
4211 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
4213 ' if(mode == "r")\n'\
4214 ' htmlline = rline+"<cS>←R</cS></div>";\n'\
4216 ' htmlline = rline+"<cS>0ms</div>";\n'\
4218 ' html += htmlline;\n'\
4220 ' timescale.innerHTML = html;\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'\
4241 ' zoombox.scrollLeft = 0;\n'\
4242 ' dmesg.style.width = "100%";\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'\
4256 ' function deviceName(title) {\n'\
4257 ' var name = title.slice(0, title.indexOf(" ("));\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'\
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'\
4275 ' dev[i].className = "hover "+cname;\n'\
4277 ' dev[i].className = cname;\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'\
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'\
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'\
4312 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\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'\
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'\
4337 ' idlist[idlist.length] = dev[i].id;\n'\
4339 ' if(dev[i].id[0] == "a") {\n'\
4340 ' pd = pdata[0];\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'\
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'\
4354 ' total[tidx+1] += pd[pname];\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'\
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'\
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'\
4377 ' phases[i].style.width = "0%";\n'\
4378 ' phases[i].style.left = left+"%";\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'\
4393 ' cg[i].style.display = "none";\n'\
4397 ' function callDetail(devid, devtitle) {\n'\
4398 ' if(!(devid in devstats) || devstats[devid].length < 1)\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'\
4408 ' for(var i in list) {\n'\
4409 ' if(list[i][0] == "@") {\n'\
4410 ' info = list[i].split("|");\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'\
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'\
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'\
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'\
4458 ' cg[i].style.display = "none";\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'\
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'\
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'\
4488 ' html += text[i]+"\\n";\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'\
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'\
4503 ' function onMouseDown(e) {\n'\
4504 ' dragval[0] = e.clientX;\n'\
4505 ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\
4506 ' document.onmousemove = onMouseMove;\n'\
4508 ' function onMouseMove(e) {\n'\
4509 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4510 ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\
4512 ' function onMouseUp(e) {\n'\
4513 ' document.onmousemove = null;\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'\
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'\
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'\
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'\
4558 hf.write(script_code);
4560 def setRuntimeSuspend(before=True):
4566 # runtime suspend disable or enable
4568 sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled'
4570 sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled'
4571 pprint('CONFIGURING RUNTIME SUSPEND...')
4572 sv.rslist = deviceInfo(sv.rstgt)
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...')
4579 # runtime suspend re-enable or re-disable
4581 sv.setVal(sv.rstgt, i)
4582 pprint('runtime suspend settings restored on %d devices' % len(sv.rslist))
4584 # Function: executeSuspend
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()
4592 battery = True if getBattery() else False
4593 # run these commands to prepare the system for suspend
4595 pprint('SET DISPLAY TO %s' % sysvals.display.upper())
4596 displayControl(sysvals.display)
4599 pprint('SYNCING FILESYSTEMS')
4600 call('sync', shell=True)
4601 # mark the start point in the kernel ring buffer just as we start
4604 if(sysvals.usecallgraph or sysvals.usetraceevents):
4605 pprint('START TRACING')
4606 sysvals.fsetVal('1', 'tracing_on')
4607 if sysvals.useprocmon:
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')
4617 if sysvals.testcommand != '':
4618 pprint('COMMAND START')
4620 if(sysvals.rtcwake):
4621 pprint('SUSPEND START')
4623 pprint('SUSPEND START (press a key to resume)')
4624 bat1 = getBattery() if battery else False
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')
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);
4642 tdata['error'] = 'cmd returned %d' % res
4644 mode = sysvals.suspendmode
4645 if sysvals.memmode and os.path.exists(sysvals.mempowerfile):
4647 pf = open(sysvals.mempowerfile, 'w')
4648 pf.write(sysvals.memmode)
4650 if sysvals.diskmode and os.path.exists(sysvals.diskpowerfile):
4652 pf = open(sysvals.diskpowerfile, 'w')
4653 pf.write(sysvals.diskmode)
4655 pf = open(sysvals.powerfile, 'w')
4657 # execution will pause here
4660 except Exception as e:
4661 tdata['error'] = str(e)
4662 if(sysvals.rtcwake):
4663 sysvals.rtcWakeAlarmOff()
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)
4680 if(sysvals.usecallgraph or sysvals.usetraceevents):
4681 if sysvals.useprocmon:
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')
4695 sysvals.fsetVal('', 'trace')
4699 if os.path.islink(file):
4700 return os.readlink(file).split('/')[-1]
4702 return sysvals.getVal(file).strip()
4706 # Print out a very concise time string in minutes and seconds
4708 # The time string, e.g. "1901m16s"
4712 m = (val / 60000) % 60
4713 s = (val / 1000) % 60
4715 return '%d:%02d:%02d' % (h, m, s)
4717 return '%02d:%02d' % (m, s)
4721 list = {'enabled':'A', 'disabled':'S', 'auto':'E', 'on':'D',
4722 'active':'A', 'suspended':'S', 'suspending':'S'}
4727 # Function: deviceInfo
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=''):
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 '---------------------------------------------------------------------------------------------')
4744 tgtval = 'runtime_status'
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):
4752 dirname = dirname[:-6]
4753 device = dirname.split('/')[-1]
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']:
4759 for i in ['product', 'driver', 'subsystem']:
4760 file = '%s/%s' % (dirname, i)
4761 if os.path.exists(file):
4762 name = readFile(file)
4764 for i in ['async', 'control', 'runtime_status', 'runtime_usage',
4765 'runtime_active_kids', 'runtime_active_time',
4766 'runtime_suspended_time']:
4768 power[i] = readFile('%s/power/%s' % (dirname, i))
4770 if power['control'] == output:
4771 res.append('%s/power/control' % dirname)
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):
4786 # Function: devProps
4788 # Retrieve a list of properties for all devices in the trace log
4789 def devProps(data=0):
4793 idx = data.index(': ') + 2
4794 if idx >= len(data):
4796 devlist = data[idx:].split(';')
4802 props[dev] = DevProps()
4803 props[dev].altname = f[1]
4805 props[dev].async = True
4807 props[dev].async = False
4808 sysvals.devprops = props
4809 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4810 sysvals.testcommand = props['testcommandstring'].altname
4813 if(os.path.exists(sysvals.ftracefile) == False):
4814 doError('%s does not exist' % sysvals.ftracefile)
4816 # first get the list of devices we need properties for
4817 msghead = 'Additional data added by AnalyzeSuspend'
4818 alreadystamped = False
4820 tf = sysvals.openlog(sysvals.ftracefile, 'r')
4823 alreadystamped = True
4825 # determine the trace data type (required for further parsing)
4826 m = re.match(tp.tracertypefmt, line)
4828 tp.setTracerType(m.group('t'))
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):
4834 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
4838 if dev not in props:
4839 props[dev] = DevProps()
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:
4847 sysvals.devprops = props
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]
4857 # now fill in the properties for our target devices
4859 dirname = props[dev].syspath
4860 if not dirname or not os.path.exists(dirname):
4862 with open(dirname+'/power/async') as fp:
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:
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)
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
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:
4905 sysvals.devprops = props
4907 # Function: getModes
4909 # Determine the supported power modes on this system
4911 # A string list of the available modes
4914 if(os.path.exists(sysvals.powerfile)):
4915 fp = open(sysvals.powerfile, 'r')
4916 modes = string.split(fp.read())
4918 if(os.path.exists(sysvals.mempowerfile)):
4920 fp = open(sysvals.mempowerfile, 'r')
4921 for m in string.split(fp.read()):
4922 memmode = m.strip('[]')
4923 if memmode == 'deep':
4926 modes.append('mem-%s' % memmode)
4928 if 'mem' in modes and not deep:
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('[]'))
4937 # Function: dmidecode
4939 # Read the bios tables and pull out system info
4941 # mempath: /dev/mem or custom mem path
4942 # fatal: True to exit on error, False to return empty dict
4944 # A dict object with all available key/values
4945 def dmidecode(mempath, fatal=False):
4948 # the list of values to retrieve, with hardcoded (type, idx)
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),
4968 if(not os.path.exists(mempath)):
4970 doError('file does not exist: %s' % mempath)
4972 if(not os.access(mempath, os.R_OK)):
4974 doError('file is not readable: %s' % mempath)
4977 # by default use legacy scan, but try to use EFI first
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):
4986 i = buf.find('SMBIOS=')
4989 memaddr = int(buf[i+7:], 16)
4994 # read in the memory for scanning
4995 fp = open(mempath, 'rb')
4998 buf = fp.read(memsize)
5001 doError('DMI table is unreachable, sorry')
5006 # search for either an SM table or DMI table
5007 i = base = length = num = 0
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])
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])
5018 if base == 0 and length == 0 and num == 0:
5020 doError('Neither SMBIOS nor DMI were found')
5024 # read in the SM or DMI table
5025 fp = open(mempath, 'rb')
5028 buf = fp.read(length)
5031 doError('DMI table is unreachable, sorry')
5036 # scan the table for the values we want
5038 while(count < num and i <= len(buf) - 4):
5039 type, size, handle = struct.unpack('BBH', buf[i:i+4])
5041 while n < len(buf) - 1:
5042 if 0 == struct.unpack('H', buf[n:n+2])[0]:
5045 data = buf[i+size:n+2].split('\0')
5047 itype, idxadr = info[name]
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]
5059 p, charge, bat = '/sys/class/power_supply', 0, {}
5060 if not os.path.exists(p):
5062 for d in os.listdir(p):
5063 type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower()
5064 if type != 'battery':
5066 for v in ['status', 'energy_now', 'capacity_now']:
5067 bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower()
5069 if 'status' not in bat:
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])
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)
5082 ret = call(xset.format('dpms 0 0 0'), shell=True)
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)
5091 curr = displayControl('stat')
5092 sysvals.vprint('Display Switched: %s -> %s' % (b4, curr))
5094 sysvals.vprint('WARNING: Display failed to change to %s' % cmd)
5096 sysvals.vprint('WARNING: Display failed to change to %s with xset' % cmd)
5099 fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout
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
5112 # Read the acpi bios tables and pull out FPDT, the firmware data
5114 # output: True to output the info to stdout, False otherwise
5115 def getFPDT(output):
5117 rectype[0] = 'Firmware Basic Boot Performance Record'
5118 rectype[1] = 'S3 Performance Table Record'
5120 prectype[0] = 'Basic S3 Resume Performance Record'
5121 prectype[1] = 'Basic S3 Suspend Performance Record'
5123 sysvals.rootCheck(True)
5124 if(not os.path.exists(sysvals.fpdtpath)):
5126 doError('file does not exist: %s' % sysvals.fpdtpath)
5128 if(not os.access(sysvals.fpdtpath, os.R_OK)):
5130 doError('file is not readable: %s' % sysvals.fpdtpath)
5132 if(not os.path.exists(sysvals.mempath)):
5134 doError('file does not exist: %s' % sysvals.mempath)
5136 if(not os.access(sysvals.mempath, os.R_OK)):
5138 doError('file is not readable: %s' % sysvals.mempath)
5141 fp = open(sysvals.fpdtpath, 'rb')
5147 doError('Invalid FPDT table data, should '+\
5148 'be at least 36 bytes')
5151 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
5154 'Firmware Performance Data Table (%s)\n'\
5155 ' Signature : %s\n'\
5156 ' Table Length : %u\n'\
5158 ' Checksum : 0x%x\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]))
5167 if(table[0] != 'FPDT'):
5169 doError('Invalid FPDT table')
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):
5182 if(header[1] != 16):
5185 addr = struct.unpack('Q', records[i+8:i+16])[0]
5191 pprint('Bad address 0x%x in %s' % (addr, sysvals.mempath))
5193 rechead = struct.unpack('4sI', first)
5194 recdata = fp.read(rechead[1]-8)
5195 if(rechead[0] == 'FBPT'):
5196 record = struct.unpack('HBBIQQQQQ', recdata)
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'):
5208 pprint('%s (%s)' % (rectype[header[0]], rechead[0]))
5210 while(j < len(recdata)):
5211 prechead = struct.unpack('HBB', recdata[j:j+4])
5212 if(prechead[0] not in prectype):
5214 if(prechead[0] == 0):
5215 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
5216 fwData[1] = record[2]
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]
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]))
5242 # Function: statusCheck
5244 # Verify that the requested command and options will work, and
5245 # print the results to the terminal
5247 # True if the test will work, False if not
5248 def statusCheck(probecheck=False):
5251 pprint('Checking this system (%s)...' % platform.node())
5253 # check we have root access
5254 res = sysvals.colorText('NO (No features of this tool will work!)')
5255 if(sysvals.rootCheck(False)):
5257 pprint(' have root access: %s' % res)
5259 pprint(' Try running this script with sudo')
5260 return 'missing root access'
5262 # check sysfs is mounted
5263 res = sysvals.colorText('NO (No features of this tool will work!)')
5264 if(os.path.exists(sysvals.powerfile)):
5266 pprint(' is sysfs mounted: %s' % res)
5268 return 'sysfs is missing'
5270 # check target mode is a valid mode
5271 if sysvals.suspendmode != 'command':
5272 res = sysvals.colorText('NO')
5274 if(sysvals.suspendmode in modes):
5277 status = '%s mode is not supported' % sysvals.suspendmode
5278 pprint(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
5280 pprint(' valid power modes are: %s' % modes)
5281 pprint(' please choose one with -m')
5283 # check if ftrace is available
5284 res = sysvals.colorText('NO')
5285 ftgood = sysvals.verifyFtrace()
5288 elif(sysvals.usecallgraph):
5289 status = 'ftrace is not properly supported'
5290 pprint(' is ftrace supported: %s' % res)
5292 # check if kprobes are available
5293 res = sysvals.colorText('NO')
5294 sysvals.usekprobes = sysvals.verifyKprobes()
5295 if(sysvals.usekprobes):
5298 sysvals.usedevsrc = False
5299 pprint(' are kprobes supported: %s' % res)
5301 # what data source are we using
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)
5313 res = sysvals.colorText('NO')
5314 if(sysvals.rtcpath != ''):
5316 elif(sysvals.rtcwake):
5317 status = 'rtcwake is not properly supported'
5318 pprint(' is rtcwake supported: %s' % res)
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)
5336 # generic error function for catastrphic failures
5338 # msg: the error message to print
5339 # help: True if printHelp should be called after, False otherwise
5340 def doError(msg, help=False):
5343 pprint('ERROR: %s\n' % msg)
5344 sysvals.outputResult({'error':msg})
5347 # Function: getArgInt
5349 # pull out an integer argument from the command line with checks
5350 def getArgInt(name, args, min, max, main=True):
5355 doError(name+': no argument supplied', True)
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)
5366 # Function: getArgFloat
5368 # pull out a float argument from the command line with checks
5369 def getArgFloat(name, args, min, max, main=True):
5374 doError(name+': no argument supplied', True)
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)
5385 def processData(live=False):
5386 pprint('PROCESSING DATA')
5388 if(sysvals.usetraceevents):
5389 testruns, error = parseTraceLog(live)
5390 if sysvals.dmesgfile:
5391 for data in testruns:
5392 data.extractErrorInfo()
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:
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))
5408 for data in testruns:
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)
5419 stamp['suspend'], stamp['resume'] = data.getTimeValues()
5421 stamp['fwsuspend'], stamp['fwresume'] = data.fwSuspend, data.fwResume
5423 stamp['error'] = error
5424 return (testruns, stamp)
5426 # Function: rerunTest
5428 # generate an output from an existing set of ftrace/dmesg logs
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)
5446 # execute a suspend/resume, gather the logs, and generate the output
5448 # prepare for the test
5449 sysvals.initFtrace()
5450 sysvals.initTestOutput('suspend')
5454 sysvals.cleanupFtrace()
5455 if sysvals.skiphtml:
5456 sysvals.sudoUserchown(sysvals.testdir)
5458 testruns, stamp = processData(True)
5459 for data in testruns:
5461 sysvals.sudoUserchown(sysvals.testdir)
5462 sysvals.outputResult(stamp, n)
5463 if 'error' in stamp:
5467 def find_in_html(html, start, end, firstonly=True):
5469 while n < len(html):
5470 m = re.search(start, html[n:])
5474 m = re.search(end, html[n+i:])
5478 str = html[n+i:n+i+j]
5480 num = re.search(r'[-+]?\d*\.\d+|\d+', str)
5481 str = num.group() if num else 'NaN'
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>')
5496 if not suspend or not resume or len(stmp) != 8:
5499 dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
5502 tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
5503 error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
5505 m = re.match('[a-z]* failed in (?P<p>[a-z0-9_]*) phase', error)
5507 result = 'fail in %s' % m.group('p')
5513 e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '→</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('|')))
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:
5524 m = re.match('(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title'))
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:
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}}
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]
5551 'issues': ' '.join(ilist),
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),
5561 data['devlist'] = devices
5564 # Function: runSummary
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)
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)
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)):
5592 data = data_from_html(os.path.join(dirname, filename), outpath)
5595 testruns.append(data)
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])
5605 createHTMLSummarySimple(testruns, outfile, title)
5607 # Function: checkArgBool
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:
5615 doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True)
5618 # Function: configFromFile
5620 # Configure the script via the info in a config file
5621 def configFromFile(file):
5622 Config = ConfigParser.ConfigParser()
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:
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:
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'):
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)
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()
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):
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
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)
5739 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
5740 doError('No command supplied for mode "command"')
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')
5749 sysvals.tracefuncs = dict()
5750 if overridedevkprobes:
5751 sysvals.dev_tracefuncs = 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):
5763 doError('Duplicate timeline function found "%s"' % (name))
5764 text = Config.get(kprobesec, name)
5765 kprobes[name] = (text, False)
5767 for name in kprobes:
5772 text, dev = kprobes[name]
5776 # bracketted strings are special formatting, read them separately
5777 if val[0] == '[' and val[-1] == ']':
5778 for prop in val[1:-1].split(','):
5782 color = int(p[1], 16)
5787 # first real arg should be the format string
5790 # all other args are actual function args
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):
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))
5807 sysvals.archargs: args
5812 sysvals.dev_tracefuncs[name] = kp
5814 sysvals.tracefuncs[name] = kp
5816 # Function: printHelp
5818 # print out the help text
5820 pprint('\n%s v%s\n'\
5821 'Usage: sudo sleepgraph <options> <commands>\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'\
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'\
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'\
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'\
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'\
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'\
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'\
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'\
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))
5902 # ----------------- MAIN --------------------
5903 # exec start (skipped if script is loaded as library)
5904 if __name__ == '__main__':
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:])
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):
5929 pprint("Version %s" % sysvals.version)
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)
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'):
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'):
5963 elif(arg == '-gzip'):
5969 doError('-rs requires "enable" or "disable"', True)
5970 if val.lower() in switchvalues:
5971 if val.lower() in switchoff:
5976 doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True)
5977 elif(arg == '-display'):
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'):
5992 doError('No rtcwake time supplied', True)
5993 if val.lower() in switchoff:
5994 sysvals.rtcwake = False
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'):
6012 doError('No phase name supplied', True)
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'):
6022 doError('No callgraph functions supplied', True)
6023 sysvals.setCallgraphFilter(val)
6024 elif(arg == '-cgskip'):
6028 doError('No file supplied', True)
6029 if val.lower() in switchoff:
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'):
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'):
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)
6058 doError('No subdirectory name supplied', True)
6059 sysvals.outdir = sysvals.setOutputFolder(val)
6060 elif(arg == '-config'):
6064 doError('No text file supplied', True)
6065 file = sysvals.configFile(val)
6067 doError('%s does not exist' % val)
6068 configFromFile(file)
6069 elif(arg == '-fadd'):
6073 doError('No text file supplied', True)
6074 file = sysvals.configFile(val)
6076 doError('%s does not exist' % val)
6077 sysvals.addFtraceFilterFunctions(file)
6078 elif(arg == '-dmesg'):
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'):
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'):
6100 doError('No directory supplied', True)
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'):
6110 doError('No devnames supplied', True)
6111 sysvals.setDeviceFilter(val)
6112 elif(arg == '-result'):
6116 doError('No result file supplied', True)
6117 sysvals.result = val
6118 sysvals.signalHandlerInit()
6120 doError('Invalid argument: '+arg, True)
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')
6128 if sysvals.usecallgraph and sysvals.cgskip:
6129 sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip)
6130 sysvals.setCallgraphBlacklist(sysvals.cgskip)
6132 # callgraph size cannot exceed device size
6133 if sysvals.mincglen < sysvals.mindevlen:
6134 sysvals.mincglen = sysvals.mindevlen
6136 # remove existing buffers before calculating memory
6137 if(sysvals.usecallgraph or sysvals.usedevsrc):
6138 sysvals.fsetVal('16', 'buffer_size_kb')
6141 # just run a utility command and exit
6144 if(cmd == 'status'):
6145 if not statusCheck(True):
6147 elif(cmd == 'fpdt'):
6148 if not getFPDT(True):
6150 elif(cmd == 'battery'):
6153 pprint('AC Connect : %s\nBattery Charge: %d' % out)
6155 pprint('no battery found')
6157 elif(cmd == 'sysinfo'):
6158 sysvals.printSystemInfo(True)
6159 elif(cmd == 'devinfo'):
6161 elif(cmd == 'modes'):
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())
6176 # if instructed, re-analyze existing data files
6177 if(sysvals.notestrun):
6179 sysvals.outputResult(stamp)
6182 # verify that we can run a test
6183 error = statusCheck()
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':
6193 elif memmode == 's2idle':
6197 sysvals.memmode = memmode
6198 sysvals.suspendmode = mode
6199 if mode.startswith('disk-'):
6200 sysvals.diskmode = mode.split('-', 1)[-1]
6201 sysvals.suspendmode = 'disk'
6203 sysvals.systemInfo(dmidecode(sysvals.mempath))
6205 setRuntimeSuspend(True)
6207 displayControl('init')
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']):
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))
6224 pprint('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
6226 if not sysvals.skiphtml:
6227 runSummary(sysvals.outdir, False, False)
6228 sysvals.sudoUserchown(sysvals.outdir)
6231 sysvals.testdir = sysvals.outdir
6232 # run the test in the current directory
6235 displayControl('reset')
6236 setRuntimeSuspend(False)