2 # SPDX-License-Identifier: GPL-2.0-only
4 # Tool for analyzing suspend/resume timing
5 # Copyright (c) 2013, Intel Corporation.
8 # Todd Brandt <todd.e.brandt@linux.intel.com>
12 # https://01.org/suspendresume
14 # git@github.com:01org/pm-graph
17 # This tool is designed to assist kernel and OS developers in optimizing
18 # their linux stack's suspend/resume time. Using a kernel image built
19 # with a few extra options enabled, the tool will execute a suspend and
20 # will capture dmesg and ftrace data until resume is complete. This data
21 # is transformed into a device timeline and a callgraph to give a quick
22 # and detailed view of which devices and callbacks are taking the most
23 # time in suspend/resume. The output is a single html file which can be
24 # viewed in firefox or chrome.
26 # The following kernel build options are required:
28 # CONFIG_PM_SLEEP_DEBUG=y
30 # CONFIG_FUNCTION_TRACER=y
31 # CONFIG_FUNCTION_GRAPH_TRACER=y
33 # CONFIG_KPROBES_ON_FTRACE=y
35 # For kernel versions older than 3.15:
36 # The following additional kernel parameters are required:
37 # (e.g. in file /etc/default/grub)
38 # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
41 # ----------------- LIBRARIES --------------------
50 from datetime import datetime
54 from threading import Thread
55 from subprocess import call, Popen, PIPE
61 # ----------------- CLASSES --------------------
65 # A global, single-instance container used to
66 # store system values and test parameters
84 multitest = {'run': False, 'count': 0, 'delay': 0}
86 callloopmaxgap = 0.0001
87 callloopmaxlen = 0.005
96 tpath = '/sys/kernel/debug/tracing/'
97 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
98 epath = '/sys/kernel/debug/tracing/events/power/'
99 pmdpath = '/sys/power/pm_debug_messages'
102 'device_pm_callback_end',
103 'device_pm_callback_start'
108 powerfile = '/sys/power/state'
109 mempowerfile = '/sys/power/mem_sleep'
110 diskpowerfile = '/sys/power/disk'
114 hostname = 'localhost'
121 htmlfile = 'output.html'
133 usetraceevents = False
134 usetracemarkers = True
141 mixedphaseheight = True
149 '__pm_notifier_call_chain': {},
150 'pm_prepare_console': {},
151 'pm_notifier_call_chain': {},
152 'freeze_processes': {},
153 'freeze_kernel_threads': {},
154 'pm_restrict_gfp_mask': {},
155 'acpi_suspend_begin': {},
156 'acpi_hibernation_begin': {},
157 'acpi_hibernation_enter': {},
158 'acpi_hibernation_leave': {},
159 'acpi_pm_freeze': {},
161 'hibernate_preallocate_memory': {},
162 'create_basic_memory_bitmaps': {},
164 'suspend_console': {},
165 'acpi_pm_prepare': {},
166 'syscore_suspend': {},
167 'arch_enable_nonboot_cpus_end': {},
168 'syscore_resume': {},
169 'acpi_pm_finish': {},
170 'resume_console': {},
172 'pm_restore_gfp_mask': {},
173 'thaw_processes': {},
174 'pm_restore_console': {},
177 'args_x86_64': {'cpu':'%di:s32'},
178 'format': 'CPU_OFF[{cpu}]'
182 'args_x86_64': {'cpu':'%di:s32'},
183 'format': 'CPU_ON[{cpu}]'
187 # general wait/delay/sleep
188 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
189 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
190 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
191 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
192 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
193 'acpi_os_stall': {'ub': 1},
195 'acpi_resume_power_resources': {},
196 'acpi_ps_parse_aml': {},
200 'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} },
201 'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} },
202 'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} },
203 'iwlagn_mac_start': {},
204 'iwlagn_alloc_bcast_station': {},
205 'iwl_trans_pcie_start_hw': {},
206 'iwl_trans_pcie_start_fw': {},
207 'iwl_run_init_ucode': {},
208 'iwl_load_ucode_wait_alive': {},
209 'iwl_alive_start': {},
210 'iwlagn_mac_stop': {},
211 'iwlagn_mac_suspend': {},
212 'iwlagn_mac_resume': {},
213 'iwlagn_mac_add_interface': {},
214 'iwlagn_mac_remove_interface': {},
215 'iwlagn_mac_change_interface': {},
216 'iwlagn_mac_config': {},
217 'iwlagn_configure_filter': {},
218 'iwlagn_mac_hw_scan': {},
219 'iwlagn_bss_info_changed': {},
220 'iwlagn_mac_channel_switch': {},
221 'iwlagn_mac_flush': {},
223 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
225 'i915_gem_resume': {},
226 'i915_restore_state': {},
227 'intel_opregion_setup': {},
228 'g4x_pre_enable_dp': {},
229 'vlv_pre_enable_dp': {},
230 'chv_pre_enable_dp': {},
233 'intel_hpd_init': {},
234 'intel_opregion_register': {},
235 'intel_dp_detect': {},
236 'intel_hdmi_detect': {},
237 'intel_opregion_init': {},
238 'intel_fbdev_set_suspend': {},
243 cmdline = '%s %s' % \
244 (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
247 self.archargs = 'args_'+platform.machine()
248 self.hostname = platform.node()
249 if(self.hostname == ''):
250 self.hostname = 'localhost'
252 if os.path.exists('/dev/rtc'):
253 rtc = os.readlink('/dev/rtc')
254 rtc = '/sys/class/rtc/'+rtc
255 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
256 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
258 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
260 self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
261 if os.getuid() == 0 and 'SUDO_USER' in os.environ and \
262 os.environ['SUDO_USER']:
263 self.sudouser = os.environ['SUDO_USER']
264 def vprint(self, msg):
265 self.logmsg += msg+'\n'
266 if self.verbose or msg.startswith('WARNING:'):
268 def signalHandler(self, signum, frame):
271 signame = self.signames[signum] if signum in self.signames else 'UNKNOWN'
272 msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno)
273 sysvals.outputResult({'error':msg})
275 def signalHandlerInit(self):
276 capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT',
277 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM', 'TSTP']
278 self.signames = dict()
282 signum = getattr(signal, s)
283 signal.signal(signum, self.signalHandler)
286 self.signames[signum] = s
287 def rootCheck(self, fatal=True):
288 if(os.access(self.powerfile, os.W_OK)):
291 msg = 'This command requires sysfs mount and root access'
292 pprint('ERROR: %s\n' % msg)
293 self.outputResult({'error':msg})
296 def rootUser(self, fatal=False):
297 if 'USER' in os.environ and os.environ['USER'] == 'root':
300 msg = 'This command must be run as root'
301 pprint('ERROR: %s\n' % msg)
302 self.outputResult({'error':msg})
305 def getExec(self, cmd):
306 dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
307 '/usr/local/sbin', '/usr/local/bin']
309 cmdfull = os.path.join(path, cmd)
310 if os.path.exists(cmdfull):
313 def setPrecision(self, num):
314 if num < 0 or num > 6:
316 self.timeformat = '%.{0}f'.format(num)
317 def setOutputFolder(self, value):
320 args['date'] = n.strftime('%y%m%d')
321 args['time'] = n.strftime('%H%M%S')
322 args['hostname'] = args['host'] = self.hostname
323 return value.format(**args)
324 def setOutputFile(self):
325 if self.dmesgfile != '':
326 m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)
328 self.htmlfile = m.group('name')+'.html'
329 if self.ftracefile != '':
330 m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
332 self.htmlfile = m.group('name')+'.html'
333 def systemInfo(self, info):
335 if 'baseboard-manufacturer' in info:
336 m = info['baseboard-manufacturer']
337 elif 'system-manufacturer' in info:
338 m = info['system-manufacturer']
339 if 'baseboard-product-name' in info:
340 p = info['baseboard-product-name']
341 elif 'system-product-name' in info:
342 p = info['system-product-name']
343 if 'processor-version' in info:
344 c = info['processor-version']
345 if 'bios-version' in info:
346 b = info['bios-version']
347 self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \
348 (m, p, c, b, self.cpucount, self.memtotal, self.memfree)
349 def printSystemInfo(self, fatal=False):
351 out = dmidecode(self.mempath, fatal)
355 for name in sorted(out):
356 print fmt % (name, out[name])
357 print fmt % ('cpucount', ('%d' % self.cpucount))
358 print fmt % ('memtotal', ('%d kB' % self.memtotal))
359 print fmt % ('memfree', ('%d kB' % self.memfree))
362 fp = open('/proc/cpuinfo', 'r')
364 if re.match('^processor[ \t]*:[ \t]*[0-9]*', line):
367 fp = open('/proc/meminfo', 'r')
369 m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
371 self.memtotal = int(m.group('sz'))
372 m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)
374 self.memfree = int(m.group('sz'))
376 def initTestOutput(self, name):
377 self.prefix = self.hostname
378 v = open('/proc/version', 'r').read().strip()
379 kver = string.split(v)[2]
380 fmt = name+'-%m%d%y-%H%M%S'
381 testtime = datetime.now().strftime(fmt)
383 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
388 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
390 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
392 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
393 if not os.path.isdir(self.testdir):
394 os.mkdir(self.testdir)
395 def getValueList(self, value):
397 for i in value.split(','):
399 out.append(i.strip())
401 def setDeviceFilter(self, value):
402 self.devicefilter = self.getValueList(value)
403 def setCallgraphFilter(self, value):
404 self.cgfilter = self.getValueList(value)
405 def setCallgraphBlacklist(self, file):
406 self.cgblacklist = self.listFromFile(file)
407 def rtcWakeAlarmOn(self):
408 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
409 nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()
411 nowtime = int(nowtime)
413 # if hardware time fails, use the software time
414 nowtime = int(datetime.now().strftime('%s'))
415 alarm = nowtime + self.rtcwaketime
416 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
417 def rtcWakeAlarmOff(self):
418 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
420 # get the latest time stamp from the dmesg log
421 fp = Popen('dmesg', stdout=PIPE).stdout
424 line = line.replace('\r\n', '')
428 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
430 ktime = m.group('ktime')
432 self.dmesgstart = float(ktime)
433 def getdmesg(self, testdata):
434 op = self.writeDatafileHeader(sysvals.dmesgfile, testdata)
435 # store all new dmesg lines since initdmesg was called
436 fp = Popen('dmesg', stdout=PIPE).stdout
438 line = line.replace('\r\n', '')
442 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
445 ktime = float(m.group('ktime'))
446 if ktime > self.dmesgstart:
450 def listFromFile(self, file):
453 for i in fp.read().split('\n'):
455 if i and i[0] != '#':
459 def addFtraceFilterFunctions(self, file):
460 for i in self.listFromFile(file):
463 self.tracefuncs[i] = dict()
464 def getFtraceFilterFunctions(self, current):
467 call('cat '+self.tpath+'available_filter_functions', shell=True)
469 master = self.listFromFile(self.tpath+'available_filter_functions')
470 for i in self.tracefuncs:
471 if 'func' in self.tracefuncs[i]:
472 i = self.tracefuncs[i]['func']
476 print self.colorText(i)
477 def setFtraceFilterFunctions(self, list):
478 master = self.listFromFile(self.tpath+'available_filter_functions')
484 flist += i.split(' ')[0]+'\n'
487 fp = open(self.tpath+'set_graph_function', 'w')
490 def basicKprobe(self, name):
491 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
492 def defaultKprobe(self, name, kdata):
494 for field in ['name', 'format', 'func']:
497 if self.archargs in k:
498 k['args'] = k[self.archargs]
502 self.kprobes[name] = k
503 def kprobeColor(self, name):
504 if name not in self.kprobes or 'color' not in self.kprobes[name]:
506 return self.kprobes[name]['color']
507 def kprobeDisplayName(self, name, dataraw):
508 if name not in self.kprobes:
509 self.basicKprobe(name)
512 # first remvoe any spaces inside quotes, and the quotes
515 quote = (quote + 1) % 2
516 if quote and c == ' ':
520 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
522 # now process the args
523 for arg in sorted(args):
525 m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
527 arglist[arg] = m.group('arg')
529 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
531 arglist[arg] = m.group('arg')
532 out = fmt.format(**arglist)
533 out = out.replace(' ', '_').replace('"', '')
535 def kprobeText(self, kname, kprobe):
536 name = fmt = func = kname
539 name = kprobe['name']
540 if 'format' in kprobe:
541 fmt = kprobe['format']
543 func = kprobe['func']
544 if self.archargs in kprobe:
545 args = kprobe[self.archargs]
547 args = kprobe['args']
548 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
549 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
550 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
552 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
553 val = 'p:%s_cal %s' % (name, func)
554 for i in sorted(args):
555 val += ' %s=%s' % (i, args[i])
556 val += '\nr:%s_ret %s $retval\n' % (name, func)
558 def addKprobes(self, output=False):
559 if len(self.kprobes) < 1:
562 pprint(' kprobe functions in this kernel:')
563 # first test each kprobe
565 # sort kprobes: trace, ub-dev, custom, dev
566 kpl = [[], [], [], []]
567 linesout = len(self.kprobes)
568 for name in sorted(self.kprobes):
569 res = self.colorText('YES', 32)
570 if not self.testKprobe(name, self.kprobes[name]):
571 res = self.colorText('NO')
574 if name in self.tracefuncs:
576 elif name in self.dev_tracefuncs:
577 if 'ub' in self.dev_tracefuncs[name]:
584 pprint(' %s: %s' % (name, res))
585 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
586 # remove all failed ones from the list
588 self.kprobes.pop(name)
589 # set the kprobes all at once
590 self.fsetVal('', 'kprobe_events')
593 kprobeevents += self.kprobeText(kp, self.kprobes[kp])
594 self.fsetVal(kprobeevents, 'kprobe_events')
596 check = self.fgetVal('kprobe_events')
597 linesack = (len(check.split('\n')) - 1) / 2
598 pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout))
599 self.fsetVal('1', 'events/kprobes/enable')
600 def testKprobe(self, kname, kprobe):
601 self.fsetVal('0', 'events/kprobes/enable')
602 kprobeevents = self.kprobeText(kname, kprobe)
606 self.fsetVal(kprobeevents, 'kprobe_events')
607 check = self.fgetVal('kprobe_events')
610 linesout = len(kprobeevents.split('\n'))
611 linesack = len(check.split('\n'))
612 if linesack < linesout:
615 def setVal(self, val, file, mode='w'):
616 if not os.path.exists(file):
619 fp = open(file, mode, 0)
626 def fsetVal(self, val, path, mode='w'):
627 return self.setVal(val, self.tpath+path, mode)
628 def getVal(self, file):
630 if not os.path.exists(file):
639 def fgetVal(self, path):
640 return self.getVal(self.tpath+path)
641 def cleanupFtrace(self):
642 if(self.usecallgraph or self.usetraceevents or self.usedevsrc):
643 self.fsetVal('0', 'events/kprobes/enable')
644 self.fsetVal('', 'kprobe_events')
645 self.fsetVal('1024', 'buffer_size_kb')
647 self.setVal(self.pmdebug, self.pmdpath)
648 def setupAllKprobes(self):
649 for name in self.tracefuncs:
650 self.defaultKprobe(name, self.tracefuncs[name])
651 for name in self.dev_tracefuncs:
652 self.defaultKprobe(name, self.dev_tracefuncs[name])
653 def isCallgraphFunc(self, name):
654 if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
656 for i in self.tracefuncs:
657 if 'func' in self.tracefuncs[i]:
658 f = self.tracefuncs[i]['func']
664 def initFtrace(self):
665 self.printSystemInfo(False)
666 pprint('INITIALIZING FTRACE...')
668 self.fsetVal('0', 'tracing_on')
671 pv = self.getVal(self.pmdpath)
673 self.setVal('1', self.pmdpath)
675 # set the trace clock to global
676 self.fsetVal('global', 'trace_clock')
677 self.fsetVal('nop', 'current_tracer')
678 # set trace buffer to an appropriate value
679 cpus = max(1, self.cpucount)
681 tgtsize = self.bufsize
682 elif self.usecallgraph or self.usedevsrc:
683 bmax = (1*1024*1024) if self.suspendmode == 'disk' else (3*1024*1024)
684 tgtsize = min(self.memfree, bmax)
687 while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
688 # if the size failed to set, lower it and keep trying
691 tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
693 pprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus))
694 # initialize the callgraph trace
695 if(self.usecallgraph):
697 self.fsetVal('function_graph', 'current_tracer')
698 self.fsetVal('', 'set_ftrace_filter')
699 # set trace format options
700 self.fsetVal('print-parent', 'trace_options')
701 self.fsetVal('funcgraph-abstime', 'trace_options')
702 self.fsetVal('funcgraph-cpu', 'trace_options')
703 self.fsetVal('funcgraph-duration', 'trace_options')
704 self.fsetVal('funcgraph-proc', 'trace_options')
705 self.fsetVal('funcgraph-tail', 'trace_options')
706 self.fsetVal('nofuncgraph-overhead', 'trace_options')
707 self.fsetVal('context-info', 'trace_options')
708 self.fsetVal('graph-time', 'trace_options')
709 self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
710 cf = ['dpm_run_callback']
711 if(self.usetraceevents):
712 cf += ['dpm_prepare', 'dpm_complete']
713 for fn in self.tracefuncs:
714 if 'func' in self.tracefuncs[fn]:
715 cf.append(self.tracefuncs[fn]['func'])
718 self.setFtraceFilterFunctions(cf)
719 # initialize the kprobe trace
720 elif self.usekprobes:
721 for name in self.tracefuncs:
722 self.defaultKprobe(name, self.tracefuncs[name])
724 for name in self.dev_tracefuncs:
725 self.defaultKprobe(name, self.dev_tracefuncs[name])
726 pprint('INITIALIZING KPROBES...')
727 self.addKprobes(self.verbose)
728 if(self.usetraceevents):
729 # turn trace events on
730 events = iter(self.traceevents)
732 self.fsetVal('1', 'events/power/'+e+'/enable')
733 # clear the trace buffer
734 self.fsetVal('', 'trace')
735 def verifyFtrace(self):
736 # files needed for any trace data
737 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
738 'trace_marker', 'trace_options', 'tracing_on']
739 # files needed for callgraph trace data
741 if(self.usecallgraph):
743 'available_filter_functions',
748 if(os.path.exists(tp+f) == False):
751 def verifyKprobes(self):
752 # files needed for kprobes to work
753 files = ['kprobe_events', 'events']
756 if(os.path.exists(tp+f) == False):
759 def colorText(self, str, color=31):
762 return '\x1B[%d;40m%s\x1B[m' % (color, str)
763 def writeDatafileHeader(self, filename, testdata):
764 fp = self.openlog(filename, 'w')
765 fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
766 for test in testdata:
770 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
772 (a1, c1), (a2, c2) = test['bat']
773 fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2))
774 if test['error'] or len(testdata) > 1:
775 fp.write('# enter_sleep_error %s\n' % test['error'])
777 def sudoUserchown(self, dir):
778 if os.path.exists(dir) and self.sudouser:
779 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
780 call(cmd.format(self.sudouser, dir), shell=True)
781 def outputResult(self, testdata, num=0):
787 fp = open(self.result, 'a')
788 if 'error' in testdata:
789 fp.write('result%s: fail\n' % n)
790 fp.write('error%s: %s\n' % (n, testdata['error']))
792 fp.write('result%s: pass\n' % n)
793 for v in ['suspend', 'resume', 'boot', 'lastinit']:
795 fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))
796 for v in ['fwsuspend', 'fwresume']:
798 fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0))
799 if 'bugurl' in testdata:
800 fp.write('url%s: %s\n' % (n, testdata['bugurl']))
802 self.sudoUserchown(self.result)
803 def configFile(self, file):
804 dir = os.path.dirname(os.path.realpath(__file__))
805 if os.path.exists(file):
807 elif os.path.exists(dir+'/'+file):
809 elif os.path.exists(dir+'/config/'+file):
810 return dir+'/config/'+file
812 def openlog(self, filename, mode):
816 with gzip.open(filename, mode+'b') as fp:
822 return gzip.open(filename, mode+'b')
823 return open(filename, mode)
825 sysvals = SystemValues()
826 switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
827 switchoff = ['disable', 'off', 'false', '0']
829 'freeze': 'Freeze (S0)',
830 'standby': 'Standby (S1)',
831 'mem': 'Suspend (S3)',
832 'disk': 'Hibernate (S4)'
837 # Simple class which holds property values collected
838 # for all the devices used in the timeline.
847 return '%s,%s,%d;' % (dev, self.altname, self.async)
848 def debug(self, dev):
849 pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async))
850 def altName(self, dev):
851 if not self.altname or self.altname == dev:
853 return '%s [%s]' % (self.altname, dev)
856 return ' '+self.xtraclass
862 return ' '+self.xtraclass
864 return ' async_device'
865 return ' sync_device'
869 # A container used to create a device hierachy, with a single root node
870 # and a tree of child nodes. Used by Data.deviceTopology()
872 def __init__(self, nodename, nodedepth):
875 self.depth = nodedepth
879 # The primary container for suspend/resume test data. There is one for
880 # each test run. The data is organized into a cronological hierarchy:
883 # 10 sequential, non-overlapping phases of S/R
884 # contents: times for phase start/end, order/color data for html
886 # device callback or action list for this phase
888 # a single device callback or generic action
889 # contents: start/stop times, pid/cpu/driver info
890 # parents/children, html id for timeline/callgraph
891 # optionally includes an ftrace callgraph
892 # optionally includes dev/ps data
900 'suspend_prepare': {'order': 0, 'color': '#CCFFCC'},
901 'suspend': {'order': 1, 'color': '#88FF88'},
902 'suspend_late': {'order': 2, 'color': '#00AA00'},
903 'suspend_noirq': {'order': 3, 'color': '#008888'},
904 'suspend_machine': {'order': 4, 'color': '#0000FF'},
905 'resume_machine': {'order': 5, 'color': '#FF0000'},
906 'resume_noirq': {'order': 6, 'color': '#FF9900'},
907 'resume_early': {'order': 7, 'color': '#FFCC00'},
908 'resume': {'order': 8, 'color': '#FFFF88'},
909 'resume_complete': {'order': 9, 'color': '#FFFFCC'},
912 'HWERROR' : '.*\[ *Hardware Error *\].*',
913 'FWBUG' : '.*\[ *Firmware Bug *\].*',
915 'ERROR' : '.*ERROR.*',
916 'WARNING' : '.*WARNING.*',
917 'IRQ' : '.*genirq: .*',
918 'TASKFAIL': '.*Freezing of tasks failed.*',
920 def __init__(self, num):
921 idchar = 'abcdefghij'
922 self.start = 0.0 # test start
923 self.end = 0.0 # test end
924 self.tSuspended = 0.0 # low-level suspend start
925 self.tResumed = 0.0 # low-level resume start
926 self.tKernSus = 0.0 # kernel level suspend start
927 self.tKernRes = 0.0 # kernel level resume end
928 self.fwValid = False # is firmware data available
929 self.fwSuspend = 0 # time spent in firmware suspend
930 self.fwResume = 0 # time spent in firmware resume
931 self.html_device_id = 0
938 self.pstl = dict() # process timeline
939 self.testnumber = num
940 self.idstr = idchar[num]
941 self.dmesgtext = [] # dmesg text file in memory
942 self.dmesg = dict() # root data structure
943 self.errorinfo = {'suspend':[],'resume':[]}
944 self.tLow = [] # time spent in low-level suspends (standby/freeze)
946 self.devicegroups = 0
947 def sortedPhases(self):
948 return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order'])
949 def initDevicegroups(self):
950 # called when phases are all finished being added
951 for phase in self.dmesg.keys():
954 pnew = '%s%d' % (p[0], len(p))
955 self.dmesg[pnew] = self.dmesg.pop(phase)
956 self.devicegroups = []
957 for phase in self.sortedPhases():
958 self.devicegroups.append([phase])
959 def nextPhase(self, phase, offset):
960 order = self.dmesg[phase]['order'] + offset
962 if self.dmesg[p]['order'] == order:
966 plist = self.sortedPhases()
970 def extractErrorInfo(self):
971 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
976 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
979 t = float(m.group('ktime'))
980 if t < self.start or t > self.end:
982 dir = 'suspend' if t < self.tSuspended else 'resume'
984 for err in self.errlist:
985 if re.match(self.errlist[err], msg):
986 list.append((err, dir, t, i, i))
990 type, dir, t, idx1, idx2 = e
991 sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t))
992 self.errorinfo[dir].append((type, t, idx1, idx2))
994 sysvals.dmesglog = True
996 def setStart(self, time):
998 def setEnd(self, time):
1000 def isTraceEventOutsideDeviceCalls(self, pid, time):
1001 for phase in self.sortedPhases():
1002 list = self.dmesg[phase]['list']
1005 if(d['pid'] == pid and time >= d['start'] and
1009 def sourcePhase(self, start):
1010 for phase in self.sortedPhases():
1011 if 'machine' in phase:
1013 pend = self.dmesg[phase]['end']
1016 return 'resume_complete'
1017 def sourceDevice(self, phaselist, start, end, pid, type):
1019 for phase in phaselist:
1020 list = self.dmesg[phase]['list']
1021 for devname in list:
1024 if dev['pid'] != pid:
1028 if type == 'device':
1029 # device target event is entirely inside the source boundary
1030 if(start < devS or start >= devE or end <= devS or end > devE):
1032 elif type == 'thread':
1033 # thread target event will expand the source boundary
1035 dev['start'] = start
1041 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
1042 # try to place the call in a device
1043 phases = self.sortedPhases()
1044 tgtdev = self.sourceDevice(phases, start, end, pid, 'device')
1045 # calls with device pids that occur outside device bounds are dropped
1046 # TODO: include these somehow
1047 if not tgtdev and pid in self.devpids:
1049 # try to place the call in a thread
1051 tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')
1052 # create new thread blocks, expand as new calls are found
1055 threadname = 'kthread-%d' % (pid)
1057 threadname = '%s-%d' % (proc, pid)
1058 tgtphase = self.sourcePhase(start)
1059 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
1060 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
1061 # this should not happen
1063 sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \
1064 (start, end, proc, pid, kprobename, cdata, rdata))
1066 # place the call data inside the src element of the tgtdev
1067 if('src' not in tgtdev):
1069 dtf = sysvals.dev_tracefuncs
1071 if kprobename in dtf and 'ub' in dtf[kprobename]:
1073 title = cdata+' '+rdata
1074 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
1075 m = re.match(mstr, title)
1077 c = m.group('caller')
1078 a = m.group('args').strip()
1084 if ubiquitous and c in dtf and 'ub' in dtf[c]:
1086 color = sysvals.kprobeColor(kprobename)
1087 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
1088 tgtdev['src'].append(e)
1090 def overflowDevices(self):
1091 # get a list of devices that extend beyond the end of this test run
1093 for phase in self.sortedPhases():
1094 list = self.dmesg[phase]['list']
1095 for devname in list:
1097 if dev['end'] > self.end:
1100 def mergeOverlapDevices(self, devlist):
1101 # merge any devices that overlap devlist
1103 devname = dev['name']
1104 for phase in self.sortedPhases():
1105 list = self.dmesg[phase]['list']
1106 if devname not in list:
1108 tdev = list[devname]
1109 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
1112 dev['end'] = tdev['end']
1113 if 'src' not in dev or 'src' not in tdev:
1115 dev['src'] += tdev['src']
1117 def usurpTouchingThread(self, name, dev):
1118 # the caller test has priority of this thread, give it to him
1119 for phase in self.sortedPhases():
1120 list = self.dmesg[phase]['list']
1123 if tdev['start'] - dev['end'] < 0.1:
1124 dev['end'] = tdev['end']
1125 if 'src' not in dev:
1128 dev['src'] += tdev['src']
1131 def stitchTouchingThreads(self, testlist):
1132 # merge any threads between tests that touch
1133 for phase in self.sortedPhases():
1134 list = self.dmesg[phase]['list']
1135 for devname in list:
1137 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
1139 for data in testlist:
1140 data.usurpTouchingThread(devname, dev)
1141 def optimizeDevSrc(self):
1142 # merge any src call loops to reduce timeline size
1143 for phase in self.sortedPhases():
1144 list = self.dmesg[phase]['list']
1146 if 'src' not in list[dev]:
1148 src = list[dev]['src']
1150 for e in sorted(src, key=lambda event: event.time):
1151 if not p or not e.repeat(p):
1154 # e is another iteration of p, move it into p
1156 p.length = p.end - p.time
1159 def trimTimeVal(self, t, t0, dT, left):
1174 def trimTime(self, t0, dT, left):
1175 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
1176 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
1177 self.start = self.trimTimeVal(self.start, t0, dT, left)
1178 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
1179 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
1180 self.end = self.trimTimeVal(self.end, t0, dT, left)
1181 for phase in self.sortedPhases():
1182 p = self.dmesg[phase]
1183 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
1184 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
1188 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
1189 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
1190 d['length'] = d['end'] - d['start']
1193 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
1194 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
1195 for line in cg.list:
1196 line.time = self.trimTimeVal(line.time, t0, dT, left)
1199 e.time = self.trimTimeVal(e.time, t0, dT, left)
1200 for dir in ['suspend', 'resume']:
1202 for e in self.errorinfo[dir]:
1203 type, tm, idx1, idx2 = e
1204 tm = self.trimTimeVal(tm, t0, dT, left)
1205 list.append((type, tm, idx1, idx2))
1206 self.errorinfo[dir] = list
1207 def trimFreezeTime(self, tZero):
1208 # trim out any standby or freeze clock time
1210 for phase in self.sortedPhases():
1211 if 'resume_machine' in phase and 'suspend_machine' in lp:
1212 tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start']
1215 left = True if tR > tZero else False
1216 self.trimTime(tS, tL, left)
1217 self.tLow.append('%.0f'%(tL*1000))
1219 def getTimeValues(self):
1220 sktime = (self.tSuspended - self.tKernSus) * 1000
1221 rktime = (self.tKernRes - self.tResumed) * 1000
1222 return (sktime, rktime)
1223 def setPhase(self, phase, ktime, isbegin, order=-1):
1225 # phase start over current phase
1227 if 'resume_machine' not in self.currphase:
1228 sysvals.vprint('WARNING: phase %s failed to end' % self.currphase)
1229 self.dmesg[self.currphase]['end'] = ktime
1230 phases = self.dmesg.keys()
1231 color = self.phasedef[phase]['color']
1232 count = len(phases) if order < 0 else order
1233 # create unique name for every new phase
1234 while phase in phases:
1236 self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0,
1237 'row': 0, 'color': color, 'order': count}
1238 self.dmesg[phase]['start'] = ktime
1239 self.currphase = phase
1241 # phase end without a start
1242 if phase not in self.currphase:
1244 sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))
1246 sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)
1248 phase = self.currphase
1249 self.dmesg[phase]['end'] = ktime
1252 def sortedDevices(self, phase):
1253 list = self.dmesg[phase]['list']
1256 for devname in list:
1258 if dev['length'] == 0:
1260 tmp[dev['start']] = devname
1261 for t in sorted(tmp):
1262 slist.append(tmp[t])
1264 def fixupInitcalls(self, phase):
1265 # if any calls never returned, clip them at system resume end
1266 phaselist = self.dmesg[phase]['list']
1267 for devname in phaselist:
1268 dev = phaselist[devname]
1270 for p in self.sortedPhases():
1271 if self.dmesg[p]['end'] > dev['start']:
1272 dev['end'] = self.dmesg[p]['end']
1274 sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
1275 def deviceFilter(self, devicefilter):
1276 for phase in self.sortedPhases():
1277 list = self.dmesg[phase]['list']
1281 for filter in devicefilter:
1282 if filter in name or \
1283 ('drv' in list[name] and filter in list[name]['drv']):
1289 def fixupInitcallsThatDidntReturn(self):
1290 # if any calls never returned, clip them at system resume end
1291 for phase in self.sortedPhases():
1292 self.fixupInitcalls(phase)
1293 def phaseOverlap(self, phases):
1296 for group in self.devicegroups:
1297 for phase in phases:
1298 if phase not in group:
1301 if p not in newgroup:
1303 if group not in rmgroups:
1304 rmgroups.append(group)
1305 for group in rmgroups:
1306 self.devicegroups.remove(group)
1307 self.devicegroups.append(newgroup)
1308 def newActionGlobal(self, name, start, end, pid=-1, color=''):
1309 # which phase is this device callback or action in
1310 phases = self.sortedPhases()
1311 targetphase = 'none'
1315 for phase in phases:
1316 pstart = self.dmesg[phase]['start']
1317 pend = self.dmesg[phase]['end']
1318 # see if the action overlaps this phase
1319 o = max(0, min(end, pend) - max(start, pstart))
1321 myphases.append(phase)
1322 # set the target phase to the one that overlaps most
1324 if overlap > 0 and phase == 'post_resume':
1328 # if no target phase was found, pin it to the edge
1329 if targetphase == 'none':
1330 p0start = self.dmesg[phases[0]]['start']
1331 if start <= p0start:
1332 targetphase = phases[0]
1334 targetphase = phases[-1]
1339 if len(myphases) > 1:
1341 self.phaseOverlap(myphases)
1342 if targetphase in phases:
1343 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1344 return (targetphase, newname)
1346 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
1347 # new device callback for a specific phase
1348 self.html_device_id += 1
1349 devid = '%s%d' % (self.idstr, self.html_device_id)
1350 list = self.dmesg[phase]['list']
1352 if(start >= 0 and end >= 0):
1353 length = end - start
1357 while(name in list):
1358 name = '%s[%d]' % (origname, i)
1360 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,
1361 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }
1363 list[name]['htmlclass'] = htmlclass
1365 list[name]['color'] = color
1367 def deviceChildren(self, devname, phase):
1369 list = self.dmesg[phase]['list']
1371 if(list[child]['par'] == devname):
1372 devlist.append(child)
1374 def maxDeviceNameSize(self, phase):
1376 for name in self.dmesg[phase]['list']:
1377 if len(name) > size:
1380 def printDetails(self):
1381 sysvals.vprint('Timeline Details:')
1382 sysvals.vprint(' test start: %f' % self.start)
1383 sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
1385 for phase in self.sortedPhases():
1386 devlist = self.dmesg[phase]['list']
1387 dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end']
1388 if not tS and ps >= self.tSuspended:
1389 sysvals.vprint(' machine suspended: %f' % self.tSuspended)
1391 if not tR and ps >= self.tResumed:
1392 sysvals.vprint(' machine resumed: %f' % self.tResumed)
1394 sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc))
1396 sysvals.vprint(''.join('-' for i in range(80)))
1397 maxname = '%d' % self.maxDeviceNameSize(phase)
1398 fmt = '%3d) %'+maxname+'s - %f - %f'
1400 for name in devlist:
1401 s = devlist[name]['start']
1402 e = devlist[name]['end']
1403 sysvals.vprint(fmt % (c, name, s, e))
1405 sysvals.vprint(''.join('-' for i in range(80)))
1406 sysvals.vprint(' kernel resume end: %f' % self.tKernRes)
1407 sysvals.vprint(' test end: %f' % self.end)
1408 def deviceChildrenAllPhases(self, devname):
1410 for phase in self.sortedPhases():
1411 list = self.deviceChildren(devname, phase)
1413 if dev not in devlist:
1416 def masterTopology(self, name, list, depth):
1417 node = DeviceNode(name, depth)
1422 clist = self.deviceChildrenAllPhases(cname)
1423 cnode = self.masterTopology(cname, clist, depth+1)
1424 node.children.append(cnode)
1426 def printTopology(self, node):
1431 for phase in self.sortedPhases():
1432 list = self.dmesg[phase]['list']
1433 if node.name in list:
1434 s = list[node.name]['start']
1435 e = list[node.name]['end']
1436 if list[node.name]['drv']:
1437 drv = ' {'+list[node.name]['drv']+'}'
1438 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
1439 html += '<li><b>'+node.name+drv+'</b>'
1441 html += '<ul>'+info+'</ul>'
1443 if len(node.children) > 0:
1445 for cnode in node.children:
1446 html += self.printTopology(cnode)
1449 def rootDeviceList(self):
1450 # list of devices graphed
1452 for phase in self.dmesg:
1453 list = self.dmesg[phase]['list']
1455 if list[dev]['pid'] >= 0 and dev not in real:
1457 # list of top-most root devices
1459 for phase in self.dmesg:
1460 list = self.dmesg[phase]['list']
1462 pdev = list[dev]['par']
1463 pid = list[dev]['pid']
1464 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
1466 if pdev and pdev not in real and pdev not in rootlist:
1467 rootlist.append(pdev)
1469 def deviceTopology(self):
1470 rootlist = self.rootDeviceList()
1471 master = self.masterTopology('', rootlist, 0)
1472 return self.printTopology(master)
1473 def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
1474 # only select devices that will actually show up in html
1475 self.tdevlist = dict()
1476 for phase in self.dmesg:
1478 list = self.dmesg[phase]['list']
1480 length = (list[dev]['end'] - list[dev]['start']) * 1000
1481 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
1482 if width != '0.000000' and length >= mindevlen:
1484 self.tdevlist[phase] = devlist
1485 def addHorizontalDivider(self, devname, devend):
1486 phase = 'suspend_prepare'
1487 self.newAction(phase, devname, -2, '', \
1488 self.start, devend, '', ' sec', '')
1489 if phase not in self.tdevlist:
1490 self.tdevlist[phase] = []
1491 self.tdevlist[phase].append(devname)
1492 d = DevItem(0, phase, self.dmesg[phase]['list'][devname])
1494 def addProcessUsageEvent(self, name, times):
1495 # get the start and end times for this process
1500 for t in sorted(times):
1504 if name in self.pstl[t]:
1505 if start == -1 or tlast < start:
1507 if end == -1 or t > end:
1510 if start == -1 or end == -1:
1512 # add a new action for this process and get the object
1513 out = self.newActionGlobal(name, start, end, -3)
1516 phase, devname = out
1517 dev = self.dmesg[phase]['list'][devname]
1518 # get the cpu exec data
1522 for t in sorted(times):
1523 if tlast == 0 or t <= start or t > end:
1537 dev['cpuexec'] = cpuexec
1539 def createProcessUsageEvents(self):
1540 # get an array of process names
1543 pslist = self.pstl[t]
1545 if ps not in proclist:
1547 # get a list of data points for suspend and resume
1550 for t in sorted(self.pstl):
1551 if t < self.tSuspended:
1555 # process the events for suspend and resume
1556 if len(proclist) > 0:
1557 sysvals.vprint('Process Execution:')
1559 c = self.addProcessUsageEvent(ps, tsus)
1561 sysvals.vprint('%25s (sus): %d' % (ps, c))
1562 c = self.addProcessUsageEvent(ps, tres)
1564 sysvals.vprint('%25s (res): %d' % (ps, c))
1565 def handleEndMarker(self, time):
1568 self.initDevicegroups()
1569 # give suspend_prepare an end if needed
1570 if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0:
1571 dm['suspend_prepare']['end'] = time
1572 # assume resume machine ends at next phase start
1573 if 'resume_machine' in dm and dm['resume_machine']['end'] < 0:
1574 np = self.nextPhase('resume_machine', 1)
1576 dm['resume_machine']['end'] = dm[np]['start']
1577 # if kernel resume end not found, assume its the end marker
1578 if self.tKernRes == 0.0:
1579 self.tKernRes = time
1580 # if kernel suspend start not found, assume its the end marker
1581 if self.tKernSus == 0.0:
1582 self.tKernSus = time
1583 # set resume complete to end at end marker
1584 if 'resume_complete' in dm:
1585 dm['resume_complete']['end'] = time
1586 def debugPrint(self):
1587 for p in self.sortedPhases():
1588 list = self.dmesg[p]['list']
1589 for devname in list:
1592 dev['ftrace'].debugPrint(' [%s]' % devname)
1594 # Class: DevFunction
1596 # A container for kprobe function data we want in the dev timeline
1598 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
1603 self.caller = caller
1606 self.length = end - start
1615 cnt = '(x%d)' % self.count
1616 l = '%0.3fms' % (self.length * 1000)
1618 title = '%s(%s)%s <- %s, %s(%s)' % \
1619 (self.name, self.args, cnt, self.caller, self.ret, l)
1621 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
1622 return title.replace('"', '')
1625 text = '%s(x%d)' % (self.name, self.count)
1629 def repeat(self, tgt):
1630 # is the tgt call just a repeat of this call (e.g. are we in a loop)
1631 dt = self.time - tgt.end
1632 # only combine calls if -all- attributes are identical
1633 if tgt.caller == self.caller and \
1634 tgt.name == self.name and tgt.args == self.args and \
1635 tgt.proc == self.proc and tgt.pid == self.pid and \
1636 tgt.ret == self.ret and dt >= 0 and \
1637 dt <= sysvals.callloopmaxgap and \
1638 self.length < sysvals.callloopmaxlen:
1644 # A container for a single line of ftrace data. There are six basic types:
1646 # call: " dpm_run_callback() {"
1648 # leaf: " dpm_run_callback();"
1650 # tracing_mark_write: SUSPEND START or RESUME COMPLETE
1651 # suspend_resume: phase or custom exec block data
1652 # device_pm_callback: device callback info
1654 def __init__(self, t, m='', d=''):
1657 self.freturn = False
1659 self.fkprobe = False
1663 self.time = float(t)
1666 # is this a trace event
1667 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
1668 if(d == 'traceevent'):
1669 # nop format trace event
1672 # function_graph format trace event
1673 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
1674 msg = em.group('msg')
1676 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
1678 self.name = emm.group('msg')
1679 self.type = emm.group('call')
1682 km = re.match('^(?P<n>.*)_cal$', self.type)
1686 self.type = km.group('n')
1688 km = re.match('^(?P<n>.*)_ret$', self.type)
1692 self.type = km.group('n')
1696 # convert the duration to seconds
1698 self.length = float(d)/1000000
1699 # the indentation determines the depth
1700 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
1703 self.depth = self.getDepth(match.group('d'))
1704 m = match.group('o')
1709 # includes comment with function name
1710 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
1712 self.name = match.group('n').strip()
1716 # function call with children
1718 match = re.match('^(?P<n>.*) *\(.*', m)
1720 self.name = match.group('n').strip()
1721 # function call with no children (leaf)
1724 match = re.match('^(?P<n>.*) *\(.*', m)
1726 self.name = match.group('n').strip()
1727 # something else (possibly a trace marker)
1731 return self.fcall and not self.freturn
1733 return self.freturn and not self.fcall
1735 return self.fcall and self.freturn
1736 def getDepth(self, str):
1738 def debugPrint(self, info=''):
1740 pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
1741 self.depth, self.name, self.length*1000000, info))
1743 pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
1744 self.depth, self.name, self.length*1000000, info))
1746 pprint(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
1747 self.depth, self.name, self.length*1000000, info))
1748 def startMarker(self):
1749 # Is this the starting line of a suspend?
1752 if sysvals.usetracemarkers:
1753 if(self.name == 'SUSPEND START'):
1757 if(self.type == 'suspend_resume' and
1758 re.match('suspend_enter\[.*\] begin', self.name)):
1761 def endMarker(self):
1762 # Is this the ending line of a resume?
1765 if sysvals.usetracemarkers:
1766 if(self.name == 'RESUME COMPLETE'):
1770 if(self.type == 'suspend_resume' and
1771 re.match('thaw_processes\[.*\] end', self.name)):
1775 # Class: FTraceCallGraph
1777 # A container for the ftrace callgraph of a single recursive function.
1778 # This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
1779 # Each instance is tied to a single device in a single phase, and is
1780 # comprised of an ordered list of FTraceLine objects
1781 class FTraceCallGraph:
1782 vfname = 'missing_function_name'
1783 def __init__(self, pid, sv):
1785 self.invalid = False
1787 self.partial = False
1795 def addLine(self, line):
1796 # if this is already invalid, just leave
1798 if(line.depth == 0 and line.freturn):
1801 # invalidate on bad depth
1803 self.invalidate(line)
1805 # ignore data til we return to the current depth
1807 if line.depth > self.depth:
1810 self.list[-1].freturn = True
1811 self.list[-1].length = line.time - self.list[-1].time
1813 # if this is a return at self.depth, no more work is needed
1814 if line.depth == self.depth and line.isReturn():
1816 self.end = line.time
1819 # compare current depth with this lines pre-call depth
1820 prelinedep = line.depth
1824 lasttime = line.time
1825 if len(self.list) > 0:
1826 last = self.list[-1]
1827 lasttime = last.time
1829 lasttime += last.length
1830 # handle low misalignments by inserting returns
1831 mismatch = prelinedep - self.depth
1832 warning = self.sv.verbose and abs(mismatch) > 1
1836 # add return calls to get the depth down
1837 while prelinedep < self.depth:
1839 if idx == 0 and last and last.isCall():
1840 # special case, turn last call into a leaf
1841 last.depth = self.depth
1843 last.length = line.time - last.time
1845 info.append(('[make leaf]', last))
1847 vline = FTraceLine(lasttime)
1848 vline.depth = self.depth
1849 vline.name = self.vfname
1850 vline.freturn = True
1851 self.list.append(vline)
1854 info.append(('', last))
1855 info.append(('[add return]', vline))
1858 info.append(('', line))
1859 # handle high misalignments by inserting calls
1863 info.append(('', last))
1864 # add calls to get the depth up
1865 while prelinedep > self.depth:
1866 if idx == 0 and line.isReturn():
1867 # special case, turn this return into a leaf
1871 info.append(('[make leaf]', line))
1873 vline = FTraceLine(lasttime)
1874 vline.depth = self.depth
1875 vline.name = self.vfname
1877 self.list.append(vline)
1880 self.start = vline.time
1882 info.append(('[add call]', vline))
1884 if warning and ('[make leaf]', line) not in info:
1885 info.append(('', line))
1887 pprint('WARNING: ftrace data missing, corrections made:')
1892 # process the call and set the new depth
1894 md = self.sv.max_graph_depth
1896 # ignore blacklisted/overdepth funcs
1897 if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):
1901 elif line.isReturn():
1903 # remove blacklisted/overdepth/empty funcs that slipped through
1904 if (last and last.isCall() and last.depth == line.depth) or \
1905 (md and last and last.depth >= md) or \
1906 (line.name in self.sv.cgblacklist):
1907 while len(self.list) > 0 and self.list[-1].depth > line.depth:
1909 if len(self.list) == 0:
1912 self.list[-1].freturn = True
1913 self.list[-1].length = line.time - self.list[-1].time
1914 self.list[-1].name = line.name
1916 if len(self.list) < 1:
1917 self.start = line.time
1918 # check for a mismatch that returned all the way to callgraph end
1920 if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn:
1921 line = self.list[-1]
1925 self.list.append(line)
1926 if(line.depth == 0 and line.freturn):
1928 self.start = line.time
1929 self.end = line.time
1931 self.end += line.length
1932 if self.list[0].name == self.vfname:
1938 def invalidate(self, line):
1939 if(len(self.list) > 0):
1940 first = self.list[0]
1942 self.list.append(first)
1944 id = 'task %s' % (self.pid)
1945 window = '(%f - %f)' % (self.start, line.time)
1947 pprint('Data misalignment for '+id+\
1948 ' (buffer overflow), ignoring this callback')
1950 pprint('Too much data for '+id+\
1951 ' '+window+', ignoring this callback')
1952 def slice(self, dev):
1953 minicg = FTraceCallGraph(dev['pid'], self.sv)
1954 minicg.name = self.name
1958 if(l.time < dev['start'] or l.time > dev['end']):
1961 if l.name == 'mutex_lock' and l.freturn:
1964 elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall:
1969 if not good or len(minicg.list) < 1:
1972 def repair(self, enddepth):
1973 # bring the depth back to 0 with additional returns
1975 last = self.list[-1]
1976 for i in reversed(range(enddepth)):
1977 t = FTraceLine(last.time)
1980 fixed = self.addLine(t)
1982 self.end = last.time
1985 def postProcess(self):
1986 if len(self.list) > 0:
1987 self.name = self.list[0].name
1992 # ftrace bug: reported duration is not reliable
1993 # check each leaf and clip it at max possible length
1994 if last and last.isLeaf():
1995 if last.length > l.time - last.time:
1996 last.length = l.time - last.time
2001 if(l.depth not in stack):
2003 pprint('Post Process Error: Depth missing')
2006 # calculate call length from call/return lines
2008 cl.length = l.time - cl.time
2009 if cl.name == self.vfname:
2016 # trace caught the whole call tree
2020 pprint('Post Process Error: Depth is less than 0')
2022 # trace ended before call tree finished
2023 return self.repair(cnt)
2024 def deviceMatch(self, pid, data):
2026 # add the callgraph data to the device hierarchy
2028 'dpm_prepare': 'suspend_prepare',
2029 'dpm_complete': 'resume_complete'
2031 if(self.name in borderphase):
2032 p = borderphase[self.name]
2033 list = data.dmesg[p]['list']
2034 for devname in list:
2036 if(pid == dev['pid'] and
2037 self.start <= dev['start'] and
2038 self.end >= dev['end']):
2039 cg = self.slice(dev)
2044 for p in data.sortedPhases():
2045 if(data.dmesg[p]['start'] <= self.start and
2046 self.start <= data.dmesg[p]['end']):
2047 list = data.dmesg[p]['list']
2048 for devname in list:
2050 if(pid == dev['pid'] and
2051 self.start <= dev['start'] and
2052 self.end >= dev['end']):
2053 dev['ftrace'] = self
2058 def newActionFromFunction(self, data):
2060 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
2064 if fs < data.start or fe > data.end:
2067 for p in data.sortedPhases():
2068 if(data.dmesg[p]['start'] <= self.start and
2069 self.start < data.dmesg[p]['end']):
2074 out = data.newActionGlobal(name, fs, fe, -2)
2077 data.dmesg[phase]['list'][myname]['ftrace'] = self
2078 def debugPrint(self, info=''):
2079 pprint('%s pid=%d [%f - %f] %.3f us' % \
2080 (self.name, self.pid, self.start, self.end,
2081 (self.end - self.start)*1000000))
2084 pprint('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
2085 l.depth, l.name, l.length*1000000, info))
2087 pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \
2088 l.depth, l.name, l.length*1000000, info))
2090 pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
2091 l.depth, l.name, l.length*1000000, info))
2095 def __init__(self, test, phase, dev):
2100 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:
2106 # A container for a device timeline which calculates
2107 # all the html properties to display it correctly
2109 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
2110 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'
2111 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'
2112 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
2113 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}"> {2}</div>\n'
2114 def __init__(self, rowheight, scaleheight):
2116 self.height = 0 # total timeline height
2117 self.scaleH = scaleheight # timescale (top) row height
2118 self.rowH = rowheight # device row height
2119 self.bodyH = 0 # body height
2120 self.rows = 0 # total timeline rows
2121 self.rowlines = dict()
2122 self.rowheight = dict()
2123 def createHeader(self, sv, stamp):
2124 if(not stamp['time']):
2126 self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \
2127 % (sv.title, sv.version)
2128 if sv.logmsg and sv.testlog:
2129 self.html += '<button id="showtest" class="logbtn btnfmt">log</button>'
2131 self.html += '<button id="showdmesg" class="logbtn btnfmt">dmesg</button>'
2133 self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>'
2134 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
2135 self.html += headline_stamp.format(stamp['host'], stamp['kernel'],
2136 stamp['mode'], stamp['time'])
2137 if 'man' in stamp and 'plat' in stamp and 'cpu' in stamp and \
2138 stamp['man'] and stamp['plat'] and stamp['cpu']:
2139 headline_sysinfo = '<div class="stamp sysinfo">{0} {1} <i>with</i> {2}</div>\n'
2140 self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu'])
2142 # Function: getDeviceRows
2144 # determine how may rows the device funcs will take
2146 # rawlist: the list of devices/actions for a single phase
2148 # The total number of rows needed to display this phase of the timeline
2149 def getDeviceRows(self, rawlist):
2150 # clear all rows and set them to undefined
2152 for item in rawlist:
2154 sortdict[item] = item.length
2155 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
2156 remaining = len(sortlist)
2159 # try to pack each row with as many ranges as possible
2160 while(remaining > 0):
2161 if(row not in rowdata):
2167 e = i.time + i.length
2169 for ritem in rowdata[row]:
2171 re = ritem.time + ritem.length
2172 if(not (((s <= rs) and (e <= rs)) or
2173 ((s >= re) and (e >= re)))):
2177 rowdata[row].append(i)
2182 # Function: getPhaseRows
2184 # Organize the timeline entries into the smallest
2185 # number of rows possible, with no entry overlapping
2187 # devlist: the list of devices/actions in a group of contiguous phases
2189 # The total number of rows needed to display this phase of the timeline
2190 def getPhaseRows(self, devlist, row=0, sortby='length'):
2191 # clear all rows and set them to undefined
2192 remaining = len(devlist)
2196 # initialize all device rows to -1 and calculate devrows
2197 for item in devlist:
2199 tp = (item.test, item.phase)
2200 if tp not in myphases:
2203 if sortby == 'start':
2204 # sort by start 1st, then length 2nd
2205 sortdict[item] = (-1*float(dev['start']), float(dev['end']) - float(dev['start']))
2207 # sort by length 1st, then name 2nd
2208 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])
2210 dev['devrows'] = self.getDeviceRows(dev['src'])
2211 # sort the devlist by length so that large items graph on top
2212 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
2214 for item in sortlist:
2215 if item.dev['pid'] == -2:
2216 orderedlist.append(item)
2217 for item in sortlist:
2218 if item not in orderedlist:
2219 orderedlist.append(item)
2220 # try to pack each row with as many devices as possible
2221 while(remaining > 0):
2223 if(row not in rowdata):
2225 for item in orderedlist:
2231 for ritem in rowdata[row]:
2232 rs = ritem.dev['start']
2233 re = ritem.dev['end']
2234 if(not (((s <= rs) and (e <= rs)) or
2235 ((s >= re) and (e >= re)))):
2239 rowdata[row].append(item)
2242 if 'devrows' in dev and dev['devrows'] > rowheight:
2243 rowheight = dev['devrows']
2244 for t, p in myphases:
2245 if t not in self.rowlines or t not in self.rowheight:
2246 self.rowlines[t] = dict()
2247 self.rowheight[t] = dict()
2248 if p not in self.rowlines[t] or p not in self.rowheight[t]:
2249 self.rowlines[t][p] = dict()
2250 self.rowheight[t][p] = dict()
2252 # section headers should use a different row height
2253 if len(rowdata[row]) == 1 and \
2254 'htmlclass' in rowdata[row][0].dev and \
2255 'sec' in rowdata[row][0].dev['htmlclass']:
2257 self.rowlines[t][p][row] = rowheight
2258 self.rowheight[t][p][row] = rowheight * rh
2260 if(row > self.rows):
2261 self.rows = int(row)
2263 def phaseRowHeight(self, test, phase, row):
2264 return self.rowheight[test][phase][row]
2265 def phaseRowTop(self, test, phase, row):
2267 for i in sorted(self.rowheight[test][phase]):
2270 top += self.rowheight[test][phase][i]
2272 def calcTotalRows(self):
2273 # Calculate the heights and offsets for the header and rows
2276 for t in self.rowlines:
2277 for p in self.rowlines[t]:
2279 for i in sorted(self.rowlines[t][p]):
2280 total += self.rowlines[t][p][i]
2283 if total == len(self.rowlines[t][p]):
2284 standardphases.append((t, p))
2285 self.height = self.scaleH + (maxrows*self.rowH)
2286 self.bodyH = self.height - self.scaleH
2287 # if there is 1 line per row, draw them the standard way
2288 for t, p in standardphases:
2289 for i in sorted(self.rowheight[t][p]):
2290 self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p])
2291 def createZoomBox(self, mode='command', testcount=1):
2292 # Create bounding box, add buttons
2293 html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
2294 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
2295 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail{0}</button>'
2296 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
2297 if mode != 'command':
2299 self.html += html_devlist2
2300 self.html += html_devlist1.format('1')
2302 self.html += html_devlist1.format('')
2303 self.html += html_zoombox
2304 self.html += html_timeline.format('dmesg', self.height)
2305 # Function: createTimeScale
2307 # Create the timescale for a timeline block
2309 # m0: start time (mode begin)
2310 # mMax: end time (mode end)
2311 # tTotal: total timeline time
2312 # mode: suspend or resume
2314 # The html code needed to display the time scale
2315 def createTimeScale(self, m0, mMax, tTotal, mode):
2316 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
2317 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">{0}</div>\n'
2318 output = '<div class="timescale">\n'
2319 # set scale for timeline
2323 return output+'</div>\n'
2326 divTotal = int(mTotal/tS) + 1
2327 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
2328 for i in range(divTotal):
2330 if(mode == 'suspend'):
2331 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
2332 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
2333 if(i == divTotal - 1):
2335 htmlline = timescale.format(pos, val)
2337 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
2338 val = '%0.fms' % (float(i)*tS*1000)
2339 htmlline = timescale.format(pos, val)
2341 htmlline = rline.format(mode)
2343 self.html += output+'</div>\n'
2347 # A list of values describing the properties of these test runs
2349 stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
2350 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
2351 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
2352 batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)'
2353 testerrfmt = '^# enter_sleep_error (?P<e>.*)'
2354 sysinfofmt = '^# sysinfo .*'
2355 cmdlinefmt = '^# command \| (?P<cmd>.*)'
2356 kparamsfmt = '^# kparams \| (?P<kp>.*)'
2357 devpropfmt = '# Device Properties: .*'
2358 tracertypefmt = '# tracer: (?P<t>.*)'
2359 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
2360 procexecfmt = 'ps - (?P<ps>.*)$'
2361 ftrace_line_fmt_fg = \
2362 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
2363 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
2364 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
2365 ftrace_line_fmt_nop = \
2366 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
2367 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
2377 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2378 self.cgformat = False
2381 def setTracerType(self, tracer):
2382 if(tracer == 'function_graph'):
2383 self.cgformat = True
2384 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
2385 elif(tracer == 'nop'):
2386 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2388 doError('Invalid tracer format: [%s]' % tracer)
2389 def parseStamp(self, data, sv):
2391 m = re.match(self.stampfmt, self.stamp)
2392 data.stamp = {'time': '', 'host': '', 'mode': ''}
2393 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
2394 int(m.group('d')), int(m.group('H')), int(m.group('M')),
2396 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
2397 data.stamp['host'] = m.group('host')
2398 data.stamp['mode'] = m.group('mode')
2399 data.stamp['kernel'] = m.group('kernel')
2400 if re.match(self.sysinfofmt, self.sysinfo):
2401 for f in self.sysinfo.split('|'):
2404 tmp = f.strip().split(':', 1)
2407 data.stamp[key] = val
2408 sv.hostname = data.stamp['host']
2409 sv.suspendmode = data.stamp['mode']
2410 if sv.suspendmode == 'command' and sv.ftracefile != '':
2411 modes = ['on', 'freeze', 'standby', 'mem', 'disk']
2412 fp = sysvals.openlog(sv.ftracefile, 'r')
2414 m = re.match('.* machine_suspend\[(?P<mode>.*)\]', line)
2415 if m and m.group('mode') in ['1', '2', '3', '4']:
2416 sv.suspendmode = modes[int(m.group('mode'))]
2417 data.stamp['mode'] = sv.suspendmode
2420 m = re.match(self.cmdlinefmt, self.cmdline)
2422 sv.cmdline = m.group('cmd')
2424 m = re.match(self.kparamsfmt, self.kparams)
2426 sv.kparams = m.group('kp')
2428 sv.stamp = data.stamp
2430 if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber:
2431 data.fwSuspend, data.fwResume = self.fwdata[data.testnumber]
2432 if(data.fwSuspend > 0 or data.fwResume > 0):
2435 if len(self.battery) > data.testnumber:
2436 m = re.match(self.batteryfmt, self.battery[data.testnumber])
2438 data.battery = m.groups()
2439 # sleep mode enter errors
2440 if len(self.testerror) > data.testnumber:
2441 m = re.match(self.testerrfmt, self.testerror[data.testnumber])
2443 data.enterfail = m.group('e')
2447 # A container for a suspend/resume test run. This is necessary as
2448 # there could be more than one, and they need to be separate.
2450 def __init__(self, dataobj):
2455 class ProcessMonitor:
2457 self.proclist = dict()
2458 self.running = False
2460 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
2461 process = Popen(c, shell=True, stdout=PIPE)
2463 for line in process.stdout:
2466 name = re.sub('[()]', '', data[1])
2467 user = int(data[13])
2468 kern = int(data[14])
2470 if pid not in self.proclist:
2471 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern}
2473 val = self.proclist[pid]
2474 ujiff = user - val['user']
2475 kjiff = kern - val['kern']
2478 if ujiff > 0 or kjiff > 0:
2479 running[pid] = ujiff + kjiff
2483 jiffies = running[pid]
2484 val = self.proclist[pid]
2487 out += '%s-%s %d' % (val['name'], pid, jiffies)
2489 def processMonitor(self, tid):
2491 out = self.procstat()
2493 sysvals.fsetVal(out, 'trace_marker')
2495 self.thread = Thread(target=self.processMonitor, args=(0,))
2499 self.running = False
2501 # ----------------- FUNCTIONS --------------------
2503 # Function: doesTraceLogHaveTraceEvents
2505 # Quickly determine if the ftrace log has all of the trace events,
2506 # markers, and/or kprobes required for primary parsing.
2507 def doesTraceLogHaveTraceEvents():
2508 kpcheck = ['_cal: (', '_cpu_down()']
2509 techeck = ['suspend_resume', 'device_pm_callback']
2510 tmcheck = ['tracing_mark_write']
2511 sysvals.usekprobes = False
2512 fp = sysvals.openlog(sysvals.ftracefile, 'r')
2515 if not sysvals.usekprobes:
2518 sysvals.usekprobes = True
2519 # check for all necessary trace events
2525 # check for all necessary trace markers
2532 sysvals.usetraceevents = True if len(techeck) < 2 else False
2533 sysvals.usetracemarkers = True if len(tmcheck) == 0 else False
2535 # Function: appendIncompleteTraceLog
2537 # [deprecated for kernel 3.15 or newer]
2538 # Adds callgraph data which lacks trace event data. This is only
2539 # for timelines generated from 3.15 or older
2541 # testruns: the array of Data objects obtained from parseKernelLog
2542 def appendIncompleteTraceLog(testruns):
2543 # create TestRun vessels for ftrace parsing
2544 testcnt = len(testruns)
2547 for data in testruns:
2548 testrun.append(TestRun(data))
2550 # extract the callgraph and traceevent data
2551 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
2552 os.path.basename(sysvals.ftracefile))
2554 tf = sysvals.openlog(sysvals.ftracefile, 'r')
2557 # remove any latent carriage returns
2558 line = line.replace('\r\n', '')
2559 # grab the stamp and sysinfo
2560 if re.match(tp.stampfmt, line):
2563 elif re.match(tp.sysinfofmt, line):
2566 elif re.match(tp.cmdlinefmt, line):
2569 elif re.match(tp.batteryfmt, line):
2570 tp.battery.append(line)
2572 elif re.match(tp.testerrfmt, line):
2573 tp.testerror.append(line)
2575 # determine the trace data type (required for further parsing)
2576 m = re.match(tp.tracertypefmt, line)
2578 tp.setTracerType(m.group('t'))
2580 # device properties line
2581 if(re.match(tp.devpropfmt, line)):
2584 # parse only valid lines, if this is not one move on
2585 m = re.match(tp.ftrace_line_fmt, line)
2588 # gather the basic message data from the line
2589 m_time = m.group('time')
2590 m_pid = m.group('pid')
2591 m_msg = m.group('msg')
2593 m_param3 = m.group('dur')
2595 m_param3 = 'traceevent'
2596 if(m_time and m_pid and m_msg):
2597 t = FTraceLine(m_time, m_msg, m_param3)
2601 # the line should be a call, return, or event
2602 if(not t.fcall and not t.freturn and not t.fevent):
2604 # look for the suspend start marker
2605 if(t.startMarker()):
2606 data = testrun[testidx].data
2607 tp.parseStamp(data, sysvals)
2608 data.setStart(t.time)
2612 # find the end of resume
2616 if(testidx >= testcnt):
2619 # trace event processing
2622 # call/return processing
2623 elif sysvals.usecallgraph:
2624 # create a callgraph object for the data
2625 if(pid not in testrun[testidx].ftemp):
2626 testrun[testidx].ftemp[pid] = []
2627 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
2628 # when the call is finished, see which device matches it
2629 cg = testrun[testidx].ftemp[pid][-1]
2632 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
2634 testrun[testidx].ftemp[pid][-1].addLine(t)
2637 for test in testrun:
2638 # add the callgraph data to the device hierarchy
2639 for pid in test.ftemp:
2640 for cg in test.ftemp[pid]:
2641 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
2643 if(not cg.postProcess()):
2644 id = 'task %s cpu %s' % (pid, m.group('cpu'))
2645 sysvals.vprint('Sanity check failed for '+\
2646 id+', ignoring this callback')
2648 callstart = cg.start
2650 for p in test.data.sortedPhases():
2651 if(test.data.dmesg[p]['start'] <= callstart and
2652 callstart <= test.data.dmesg[p]['end']):
2653 list = test.data.dmesg[p]['list']
2654 for devname in list:
2656 if(pid == dev['pid'] and
2657 callstart <= dev['start'] and
2658 callend >= dev['end']):
2662 # Function: parseTraceLog
2664 # Analyze an ftrace log output file generated from this app during
2665 # the execution phase. Used when the ftrace log is the primary data source
2666 # and includes the suspend_resume and device_pm_callback trace events
2667 # The ftrace filename is taken from sysvals
2669 # An array of Data objects
2670 def parseTraceLog(live=False):
2671 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
2672 os.path.basename(sysvals.ftracefile))
2673 if(os.path.exists(sysvals.ftracefile) == False):
2674 doError('%s does not exist' % sysvals.ftracefile)
2676 sysvals.setupAllKprobes()
2677 ksuscalls = ['pm_prepare_console']
2678 krescalls = ['pm_restore_console']
2680 if sysvals.usekprobes:
2681 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2682 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON',
2683 'CPU_OFF', 'timekeeping_freeze', 'acpi_suspend']
2685 # extract the callgraph and traceevent data
2691 tf = sysvals.openlog(sysvals.ftracefile, 'r')
2692 phase = 'suspend_prepare'
2694 # remove any latent carriage returns
2695 line = line.replace('\r\n', '')
2696 # stamp and sysinfo lines
2697 if re.match(tp.stampfmt, line):
2700 elif re.match(tp.sysinfofmt, line):
2703 elif re.match(tp.cmdlinefmt, line):
2706 elif re.match(tp.batteryfmt, line):
2707 tp.battery.append(line)
2709 elif re.match(tp.testerrfmt, line):
2710 tp.testerror.append(line)
2712 # firmware line: pull out any firmware data
2713 m = re.match(tp.firmwarefmt, line)
2715 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2717 # tracer type line: determine the trace data type
2718 m = re.match(tp.tracertypefmt, line)
2720 tp.setTracerType(m.group('t'))
2722 # device properties line
2723 if(re.match(tp.devpropfmt, line)):
2726 # ignore all other commented lines
2729 # ftrace line: parse only valid lines
2730 m = re.match(tp.ftrace_line_fmt, line)
2733 # gather the basic message data from the line
2734 m_time = m.group('time')
2735 m_proc = m.group('proc')
2736 m_pid = m.group('pid')
2737 m_msg = m.group('msg')
2739 m_param3 = m.group('dur')
2741 m_param3 = 'traceevent'
2742 if(m_time and m_pid and m_msg):
2743 t = FTraceLine(m_time, m_msg, m_param3)
2747 # the line should be a call, return, or event
2748 if(not t.fcall and not t.freturn and not t.fevent):
2750 # find the start of suspend
2751 if(t.startMarker()):
2752 data = Data(len(testdata))
2753 testdata.append(data)
2754 testrun = TestRun(data)
2755 testruns.append(testrun)
2756 tp.parseStamp(data, sysvals)
2757 data.setStart(t.time)
2758 data.first_suspend_prepare = True
2759 phase = data.setPhase('suspend_prepare', t.time, True)
2763 # process cpu exec line
2764 if t.type == 'tracing_mark_write':
2765 m = re.match(tp.procexecfmt, t.name)
2768 for ps in m.group('ps').split(','):
2772 name = val[0].replace('--', '-')
2773 proclist[name] = int(val[1])
2774 data.pstl[t.time] = proclist
2776 # find the end of resume
2778 data.handleEndMarker(t.time)
2779 if(not sysvals.usetracemarkers):
2780 # no trace markers? then quit and be sure to finish recording
2781 # the event we used to trigger resume end
2782 if('thaw_processes' in testrun.ttemp and len(testrun.ttemp['thaw_processes']) > 0):
2783 # if an entry exists, assume this is its end
2784 testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2787 # trace event processing
2789 if(t.type == 'suspend_resume'):
2790 # suspend_resume trace events have two types, begin and end
2791 if(re.match('(?P<name>.*) begin$', t.name)):
2793 elif(re.match('(?P<name>.*) end$', t.name)):
2797 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2799 val = m.group('val')
2801 name = m.group('name')
2803 name = m.group('name')+'['+val+']'
2805 m = re.match('(?P<name>.*) .*', t.name)
2806 name = m.group('name')
2807 # ignore these events
2808 if(name.split('[')[0] in tracewatch):
2810 # -- phase changes --
2811 # start of kernel suspend
2812 if(re.match('suspend_enter\[.*', t.name)):
2814 data.tKernSus = t.time
2816 # suspend_prepare start
2817 elif(re.match('dpm_prepare\[.*', t.name)):
2818 if isbegin and data.first_suspend_prepare:
2819 data.first_suspend_prepare = False
2820 if data.tKernSus == 0:
2821 data.tKernSus = t.time
2823 phase = data.setPhase('suspend_prepare', t.time, isbegin)
2826 elif(re.match('dpm_suspend\[.*', t.name)):
2827 phase = data.setPhase('suspend', t.time, isbegin)
2829 # suspend_late start
2830 elif(re.match('dpm_suspend_late\[.*', t.name)):
2831 phase = data.setPhase('suspend_late', t.time, isbegin)
2833 # suspend_noirq start
2834 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2835 phase = data.setPhase('suspend_noirq', t.time, isbegin)
2837 # suspend_machine/resume_machine
2838 elif(re.match('machine_suspend\[.*', t.name)):
2840 lp = data.lastPhase()
2841 phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True)
2842 data.setPhase(phase, t.time, False)
2843 if data.tSuspended == 0:
2844 data.tSuspended = t.time
2846 phase = data.setPhase('resume_machine', t.time, True)
2847 if(sysvals.suspendmode in ['mem', 'disk']):
2848 susp = phase.replace('resume', 'suspend')
2849 if susp in data.dmesg:
2850 data.dmesg[susp]['end'] = t.time
2851 data.tSuspended = t.time
2852 data.tResumed = t.time
2854 # resume_noirq start
2855 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2856 phase = data.setPhase('resume_noirq', t.time, isbegin)
2858 # resume_early start
2859 elif(re.match('dpm_resume_early\[.*', t.name)):
2860 phase = data.setPhase('resume_early', t.time, isbegin)
2863 elif(re.match('dpm_resume\[.*', t.name)):
2864 phase = data.setPhase('resume', t.time, isbegin)
2866 # resume complete start
2867 elif(re.match('dpm_complete\[.*', t.name)):
2868 phase = data.setPhase('resume_complete', t.time, isbegin)
2870 # skip trace events inside devices calls
2871 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2873 # global events (outside device calls) are graphed
2874 if(name not in testrun.ttemp):
2875 testrun.ttemp[name] = []
2877 # create a new list entry
2878 testrun.ttemp[name].append(\
2879 {'begin': t.time, 'end': t.time, 'pid': pid})
2881 if(len(testrun.ttemp[name]) > 0):
2882 # if an entry exists, assume this is its end
2883 testrun.ttemp[name][-1]['end'] = t.time
2884 # device callback start
2885 elif(t.type == 'device_pm_callback_start'):
2886 if phase not in data.dmesg:
2888 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2892 drv = m.group('drv')
2896 data.newAction(phase, n, pid, p, t.time, -1, drv)
2897 if pid not in data.devpids:
2898 data.devpids.append(pid)
2899 # device callback finish
2900 elif(t.type == 'device_pm_callback_end'):
2901 if phase not in data.dmesg:
2903 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2907 list = data.dmesg[phase]['list']
2910 dev['length'] = t.time - dev['start']
2912 # kprobe event processing
2916 key = (kprobename, pid)
2917 # displayname is generated from kprobe data
2920 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2923 if(key not in tp.ktemp):
2925 tp.ktemp[key].append({
2929 'name': displayname,
2930 'cdata': kprobedata,
2933 # start of kernel resume
2934 if(phase == 'suspend_prepare' and kprobename in ksuscalls):
2935 data.tKernSus = t.time
2937 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2939 e = tp.ktemp[key][-1]
2940 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2944 e['rdata'] = kprobedata
2945 # end of kernel resume
2946 if(phase != 'suspend_prepare' and kprobename in krescalls):
2947 if phase in data.dmesg:
2948 data.dmesg[phase]['end'] = t.time
2949 data.tKernRes = t.time
2951 # callgraph processing
2952 elif sysvals.usecallgraph:
2953 # create a callgraph object for the data
2955 if(key not in testrun.ftemp):
2956 testrun.ftemp[key] = []
2957 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
2958 # when the call is finished, see which device matches it
2959 cg = testrun.ftemp[key][-1]
2962 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
2964 testrun.ftemp[key][-1].addLine(t)
2966 if data and not data.devicegroups:
2967 sysvals.vprint('WARNING: end marker is missing')
2968 data.handleEndMarker(t.time)
2970 if sysvals.suspendmode == 'command':
2971 for test in testruns:
2972 for p in test.data.sortedPhases():
2973 if p == 'suspend_prepare':
2974 test.data.dmesg[p]['start'] = test.data.start
2975 test.data.dmesg[p]['end'] = test.data.end
2977 test.data.dmesg[p]['start'] = test.data.end
2978 test.data.dmesg[p]['end'] = test.data.end
2979 test.data.tSuspended = test.data.end
2980 test.data.tResumed = test.data.end
2981 test.data.fwValid = False
2983 # dev source and procmon events can be unreadable with mixed phase height
2984 if sysvals.usedevsrc or sysvals.useprocmon:
2985 sysvals.mixedphaseheight = False
2987 # expand phase boundaries so there are no gaps
2988 for data in testdata:
2989 lp = data.sortedPhases()[0]
2990 for p in data.sortedPhases():
2991 if(p != lp and not ('machine' in p and 'machine' in lp)):
2992 data.dmesg[lp]['end'] = data.dmesg[p]['start']
2995 for i in range(len(testruns)):
2998 # find the total time range for this test (begin, end)
2999 tlb, tle = data.start, data.end
3000 if i < len(testruns) - 1:
3001 tle = testruns[i+1].data.start
3002 # add the process usage data to the timeline
3003 if sysvals.useprocmon:
3004 data.createProcessUsageEvents()
3005 # add the traceevent data to the device hierarchy
3006 if(sysvals.usetraceevents):
3007 # add actual trace funcs
3008 for name in test.ttemp:
3009 for event in test.ttemp[name]:
3010 data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
3011 # add the kprobe based virtual tracefuncs as actual devices
3012 for key in tp.ktemp:
3014 if name not in sysvals.tracefuncs:
3016 for e in tp.ktemp[key]:
3017 kb, ke = e['begin'], e['end']
3018 if kb == ke or tlb > kb or tle <= kb:
3020 color = sysvals.kprobeColor(name)
3021 data.newActionGlobal(e['name'], kb, ke, pid, color)
3022 # add config base kprobes and dev kprobes
3023 if sysvals.usedevsrc:
3024 for key in tp.ktemp:
3026 if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs:
3028 for e in tp.ktemp[key]:
3029 kb, ke = e['begin'], e['end']
3030 if kb == ke or tlb > kb or tle <= kb:
3032 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
3033 ke, e['cdata'], e['rdata'])
3034 if sysvals.usecallgraph:
3035 # add the callgraph data to the device hierarchy
3037 for key in test.ftemp:
3039 for cg in test.ftemp[key]:
3040 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
3042 if(not cg.postProcess()):
3043 id = 'task %s' % (pid)
3044 sysvals.vprint('Sanity check failed for '+\
3045 id+', ignoring this callback')
3047 # match cg data to devices
3049 if sysvals.suspendmode != 'command':
3050 devname = cg.deviceMatch(pid, data)
3052 sortkey = '%f%f%d' % (cg.start, cg.end, pid)
3053 sortlist[sortkey] = cg
3054 elif len(cg.list) > 1000000:
3055 sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\
3056 (devname, len(cg.list)))
3057 # create blocks for orphan cg data
3058 for sortkey in sorted(sortlist):
3059 cg = sortlist[sortkey]
3061 if sysvals.isCallgraphFunc(name):
3062 sysvals.vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
3063 cg.newActionFromFunction(data)
3064 if sysvals.suspendmode == 'command':
3065 return (testdata, '')
3067 # fill in any missing phases
3069 for data in testdata:
3070 tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))
3072 phasedef = data.phasedef
3073 lp = 'suspend_prepare'
3074 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
3075 if p not in data.dmesg:
3077 pprint('TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp))
3078 terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp)
3080 if data.tSuspended == 0:
3081 data.tSuspended = data.dmesg[lp]['end']
3082 if data.tResumed == 0:
3083 data.tResumed = data.dmesg[lp]['end']
3084 data.fwValid = False
3085 sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3087 if not terr and data.enterfail:
3088 pprint('test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail))
3089 terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode)
3091 if data.tSuspended == 0:
3092 data.tSuspended = data.tKernRes
3093 if data.tResumed == 0:
3094 data.tResumed = data.tSuspended
3096 if(len(sysvals.devicefilter) > 0):
3097 data.deviceFilter(sysvals.devicefilter)
3098 data.fixupInitcallsThatDidntReturn()
3099 if sysvals.usedevsrc:
3100 data.optimizeDevSrc()
3102 # x2: merge any overlapping devices between test runs
3103 if sysvals.usedevsrc and len(testdata) > 1:
3105 for i in range(tc - 1):
3106 devlist = testdata[i].overflowDevices()
3107 for j in range(i + 1, tc):
3108 testdata[j].mergeOverlapDevices(devlist)
3109 testdata[0].stitchTouchingThreads(testdata[1:])
3110 return (testdata, ', '.join(error))
3112 # Function: loadKernelLog
3114 # [deprecated for kernel 3.15.0 or newer]
3115 # load the dmesg file into memory and fix up any ordering issues
3116 # The dmesg filename is taken from sysvals
3118 # An array of empty Data objects with only their dmesgtext attributes set
3119 def loadKernelLog():
3120 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
3121 os.path.basename(sysvals.dmesgfile))
3122 if(os.path.exists(sysvals.dmesgfile) == False):
3123 doError('%s does not exist' % sysvals.dmesgfile)
3125 # there can be multiple test runs in a single file
3127 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
3130 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
3132 line = line.replace('\r\n', '')
3133 idx = line.find('[')
3136 # grab the stamp and sysinfo
3137 if re.match(tp.stampfmt, line):
3140 elif re.match(tp.sysinfofmt, line):
3143 elif re.match(tp.cmdlinefmt, line):
3146 elif re.match(tp.batteryfmt, line):
3147 tp.battery.append(line)
3149 elif re.match(tp.testerrfmt, line):
3150 tp.testerror.append(line)
3152 m = re.match(tp.firmwarefmt, line)
3154 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
3156 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
3159 msg = m.group("msg")
3160 if(re.match('PM: Syncing filesystems.*', msg)):
3162 testruns.append(data)
3163 data = Data(len(testruns))
3164 tp.parseStamp(data, sysvals)
3167 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
3169 sysvals.stamp['kernel'] = m.group('k')
3170 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
3172 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')
3173 data.dmesgtext.append(line)
3177 testruns.append(data)
3178 if len(testruns) < 1:
3179 pprint('ERROR: dmesg log has no suspend/resume data: %s' \
3180 % sysvals.dmesgfile)
3182 # fix lines with same timestamp/function with the call and return swapped
3183 for data in testruns:
3185 for line in data.dmesgtext:
3186 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
3187 '(?P<f>.*)\+ @ .*, parent: .*', line)
3188 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
3189 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
3190 if(mc and mr and (mc.group('t') == mr.group('t')) and
3191 (mc.group('f') == mr.group('f'))):
3192 i = data.dmesgtext.index(last)
3193 j = data.dmesgtext.index(line)
3194 data.dmesgtext[i] = line
3195 data.dmesgtext[j] = last
3199 # Function: parseKernelLog
3201 # [deprecated for kernel 3.15.0 or newer]
3202 # Analyse a dmesg log output file generated from this app during
3203 # the execution phase. Create a set of device structures in memory
3204 # for subsequent formatting in the html output file
3205 # This call is only for legacy support on kernels where the ftrace
3206 # data lacks the suspend_resume or device_pm_callbacks trace events.
3208 # data: an empty Data object (with dmesgtext) obtained from loadKernelLog
3210 # The filled Data object
3211 def parseKernelLog(data):
3212 phase = 'suspend_runtime'
3215 sysvals.vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
3216 (data.fwSuspend, data.fwResume))
3218 # dmesg phase match table
3220 'suspend_prepare': ['PM: Syncing filesystems.*'],
3221 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*'],
3222 'suspend_late': ['PM: suspend of devices complete after.*'],
3223 'suspend_noirq': ['PM: late suspend of devices complete after.*'],
3224 'suspend_machine': ['PM: noirq suspend of devices complete after.*'],
3225 'resume_machine': ['ACPI: Low-level resume complete.*'],
3226 'resume_noirq': ['ACPI: Waking up from system sleep state.*'],
3227 'resume_early': ['PM: noirq resume of devices complete after.*'],
3228 'resume': ['PM: early resume of devices complete after.*'],
3229 'resume_complete': ['PM: resume of devices complete after.*'],
3230 'post_resume': ['.*Restarting tasks \.\.\..*'],
3232 if(sysvals.suspendmode == 'standby'):
3233 dm['resume_machine'] = ['PM: Restoring platform NVS memory']
3234 elif(sysvals.suspendmode == 'disk'):
3235 dm['suspend_late'] = ['PM: freeze of devices complete after.*']
3236 dm['suspend_noirq'] = ['PM: late freeze of devices complete after.*']
3237 dm['suspend_machine'] = ['PM: noirq freeze of devices complete after.*']
3238 dm['resume_machine'] = ['PM: Restoring platform NVS memory']
3239 dm['resume_early'] = ['PM: noirq restore of devices complete after.*']
3240 dm['resume'] = ['PM: early restore of devices complete after.*']
3241 dm['resume_complete'] = ['PM: restore of devices complete after.*']
3242 elif(sysvals.suspendmode == 'freeze'):
3243 dm['resume_machine'] = ['ACPI: resume from mwait']
3245 # action table (expected events that occur and show up in dmesg)
3247 'sync_filesystems': {
3248 'smsg': 'PM: Syncing filesystems.*',
3249 'emsg': 'PM: Preparing system for mem sleep.*' },
3250 'freeze_user_processes': {
3251 'smsg': 'Freezing user space processes .*',
3252 'emsg': 'Freezing remaining freezable tasks.*' },
3254 'smsg': 'Freezing remaining freezable tasks.*',
3255 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
3257 'smsg': 'ACPI: Preparing to enter system sleep state.*',
3258 'emsg': 'PM: Saving platform NVS memory.*' },
3260 'smsg': 'PM: Saving platform NVS memory.*',
3261 'emsg': 'Disabling non-boot CPUs .*' },
3268 for line in data.dmesgtext:
3269 # parse each dmesg line into the time and message
3270 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
3272 val = m.group('ktime')
3277 msg = m.group('msg')
3278 # initialize data start to first line time
3280 data.setStart(ktime)
3285 # check for a phase change line
3289 if(re.match(s, msg)):
3290 phasechange, phase = True, p
3293 # hack for determining resume_machine end for freeze
3294 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
3295 and phase == 'resume_machine' and \
3296 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3297 data.setPhase(phase, ktime, False)
3298 phase = 'resume_noirq'
3299 data.setPhase(phase, ktime, True)
3302 if phase == 'suspend_prepare':
3303 data.setPhase(phase, ktime, True)
3304 data.setStart(ktime)
3305 data.tKernSus = ktime
3306 elif phase == 'suspend':
3307 lp = data.lastPhase()
3309 data.setPhase(lp, ktime, False)
3310 data.setPhase(phase, ktime, True)
3311 elif phase == 'suspend_late':
3312 lp = data.lastPhase()
3314 data.setPhase(lp, ktime, False)
3315 data.setPhase(phase, ktime, True)
3316 elif phase == 'suspend_noirq':
3317 lp = data.lastPhase()
3319 data.setPhase(lp, ktime, False)
3320 data.setPhase(phase, ktime, True)
3321 elif phase == 'suspend_machine':
3322 lp = data.lastPhase()
3324 data.setPhase(lp, ktime, False)
3325 data.setPhase(phase, ktime, True)
3326 elif phase == 'resume_machine':
3327 lp = data.lastPhase()
3328 if(sysvals.suspendmode in ['freeze', 'standby']):
3329 data.tSuspended = prevktime
3331 data.setPhase(lp, prevktime, False)
3333 data.tSuspended = ktime
3335 data.setPhase(lp, prevktime, False)
3336 data.tResumed = ktime
3337 data.setPhase(phase, ktime, True)
3338 elif phase == 'resume_noirq':
3339 lp = data.lastPhase()
3341 data.setPhase(lp, ktime, False)
3342 data.setPhase(phase, ktime, True)
3343 elif phase == 'resume_early':
3344 lp = data.lastPhase()
3346 data.setPhase(lp, ktime, False)
3347 data.setPhase(phase, ktime, True)
3348 elif phase == 'resume':
3349 lp = data.lastPhase()
3351 data.setPhase(lp, ktime, False)
3352 data.setPhase(phase, ktime, True)
3353 elif phase == 'resume_complete':
3354 lp = data.lastPhase()
3356 data.setPhase(lp, ktime, False)
3357 data.setPhase(phase, ktime, True)
3358 elif phase == 'post_resume':
3359 lp = data.lastPhase()
3361 data.setPhase(lp, ktime, False)
3363 data.tKernRes = ktime
3366 # -- device callbacks --
3367 if(phase in data.sortedPhases()):
3369 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3370 sm = re.match('calling (?P<f>.*)\+ @ '+\
3371 '(?P<n>.*), parent: (?P<p>.*)', msg);
3376 data.newAction(phase, f, int(n), p, ktime, -1, '')
3377 # device init return
3378 elif(re.match('call (?P<f>.*)\+ returned .* after '+\
3379 '(?P<t>.*) usecs', msg)):
3380 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
3381 '(?P<t>.*) usecs(?P<a>.*)', msg);
3384 list = data.dmesg[phase]['list']
3387 dev['length'] = int(t)
3390 # if trace events are not available, these are better than nothing
3391 if(not sysvals.usetraceevents):
3392 # look for known actions
3394 if(re.match(at[a]['smsg'], msg)):
3395 if(a not in actions):
3397 actions[a].append({'begin': ktime, 'end': ktime})
3398 if(re.match(at[a]['emsg'], msg)):
3400 actions[a][-1]['end'] = ktime
3401 # now look for CPU on/off events
3402 if(re.match('Disabling non-boot CPUs .*', msg)):
3403 # start of first cpu suspend
3405 elif(re.match('Enabling non-boot CPUs .*', msg)):
3406 # start of first cpu resume
3408 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
3409 # end of a cpu suspend, start of the next
3410 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
3411 cpu = 'CPU'+m.group('cpu')
3412 if(cpu not in actions):
3414 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3416 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
3417 # end of a cpu resume, start of the next
3418 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
3419 cpu = 'CPU'+m.group('cpu')
3420 if(cpu not in actions):
3422 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3425 data.initDevicegroups()
3427 # fill in any missing phases
3428 phasedef = data.phasedef
3429 terr, lp = '', 'suspend_prepare'
3430 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
3431 if p not in data.dmesg:
3433 pprint('TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp))
3434 terr = '%s failed in %s phase' % (sysvals.suspendmode, lp)
3435 if data.tSuspended == 0:
3436 data.tSuspended = data.dmesg[lp]['end']
3437 if data.tResumed == 0:
3438 data.tResumed = data.dmesg[lp]['end']
3439 sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3441 lp = data.sortedPhases()[0]
3442 for p in data.sortedPhases():
3443 if(p != lp and not ('machine' in p and 'machine' in lp)):
3444 data.dmesg[lp]['end'] = data.dmesg[p]['start']
3446 if data.tSuspended == 0:
3447 data.tSuspended = data.tKernRes
3448 if data.tResumed == 0:
3449 data.tResumed = data.tSuspended
3451 # fill in any actions we've found
3452 for name in actions:
3453 for event in actions[name]:
3454 data.newActionGlobal(name, event['begin'], event['end'])
3456 if(len(sysvals.devicefilter) > 0):
3457 data.deviceFilter(sysvals.devicefilter)
3458 data.fixupInitcallsThatDidntReturn()
3461 def callgraphHTML(sv, hf, num, cg, title, color, devid):
3462 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'
3463 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
3464 html_func_end = '</article>\n'
3465 html_func_leaf = '<article>{0} {1}</article>\n'
3470 cglen = (cg.end - cg.start) * 1000
3471 if cglen < sv.mincglen:
3474 fmt = '<r>(%.3f ms @ '+sv.timeformat+' to '+sv.timeformat+')</r>'
3475 flen = fmt % (cglen, cg.start, cg.end)
3476 hf.write(html_func_top.format(cgid, color, num, title, flen))
3478 for line in cg.list:
3479 if(line.length < 0.000000001):
3482 fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'
3483 flen = fmt % (line.length*1000, line.time)
3485 hf.write(html_func_leaf.format(line.name, flen))
3487 hf.write(html_func_end)
3489 hf.write(html_func_start.format(num, line.name, flen))
3491 hf.write(html_func_end)
3494 def addCallgraphs(sv, hf, data):
3495 hf.write('<section id="callgraphs" class="callgraph">\n')
3496 # write out the ftrace data converted to html
3498 for p in data.sortedPhases():
3499 if sv.cgphase and p != sv.cgphase:
3501 list = data.dmesg[p]['list']
3502 for devname in data.sortedDevices(p):
3503 if len(sv.cgfilter) > 0 and devname not in sv.cgfilter:
3507 if 'color' in data.dmesg[p]:
3508 color = data.dmesg[p]['color']
3510 color = dev['color']
3512 if(devname in sv.devprops):
3513 name = sv.devprops[devname].altName(devname)
3514 if sv.suspendmode in suspendmodename:
3516 if('ftrace' in dev):
3518 num = callgraphHTML(sv, hf, num, cg,
3519 name, color, dev['id'])
3520 if('ftraces' in dev):
3521 for cg in dev['ftraces']:
3522 num = callgraphHTML(sv, hf, num, cg,
3523 name+' → '+cg.name, color, dev['id'])
3524 hf.write('\n\n </section>\n')
3526 # Function: createHTMLSummarySimple
3528 # Create summary html file for a series of tests
3530 # testruns: array of Data objects from parseTraceLog
3531 def createHTMLSummarySimple(testruns, htmlfile, title):
3532 # write the html header first (html head, css code, up to body start)
3533 html = '<!DOCTYPE html>\n<html>\n<head>\n\
3534 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3535 <title>SleepGraph Summary</title>\n\
3536 <style type=\'text/css\'>\n\
3537 .stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\
3538 table {width:100%;border-collapse: collapse;}\n\
3539 .summary {border:1px solid;}\n\
3540 th {border: 1px solid black;background:#222;color:white;}\n\
3541 td {font: 14px "Times New Roman";text-align: center;}\n\
3542 tr.head td {border: 1px solid black;background:#aaa;}\n\
3543 tr.alt {background-color:#ddd;}\n\
3544 tr.notice {color:red;}\n\
3545 .minval {background-color:#BBFFBB;}\n\
3546 .medval {background-color:#BBBBFF;}\n\
3547 .maxval {background-color:#FFBBBB;}\n\
3548 .head a {color:#000;text-decoration: none;}\n\
3549 </style>\n</head>\n<body>\n'
3551 # extract the test data into list
3553 tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
3554 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3558 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
3560 if mode not in list:
3561 list[mode] = {'data': [], 'avg': [0,0], 'min': [0,0], 'max': [0,0], 'med': [0,0]}
3562 if lastmode and lastmode != mode and num > 0:
3565 list[lastmode]['med'][i] = s[int(len(s)/2)]
3566 iMed[i] = tMed[i].index(list[lastmode]['med'][i])
3567 list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
3568 list[lastmode]['min'] = tMin
3569 list[lastmode]['max'] = tMax
3570 list[lastmode]['idx'] = (iMin, iMed, iMax)
3571 tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
3572 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3574 tVal = [float(data['suspend']), float(data['resume'])]
3575 list[mode]['data'].append([data['host'], data['kernel'],
3576 data['time'], tVal[0], tVal[1], data['url'], data['result'],
3577 data['issues'], data['sus_worst'], data['sus_worsttime'],
3578 data['res_worst'], data['res_worsttime']])
3579 idx = len(list[mode]['data']) - 1
3580 if data['result'] not in cnt:
3581 cnt[data['result']] = 1
3583 cnt[data['result']] += 1
3584 if data['result'] == 'pass':
3586 tMed[i].append(tVal[i])
3588 if tMin[i] == 0 or tVal[i] < tMin[i]:
3591 if tMax[i] == 0 or tVal[i] > tMax[i]:
3596 if lastmode and num > 0:
3599 list[lastmode]['med'][i] = s[int(len(s)/2)]
3600 iMed[i] = tMed[i].index(list[lastmode]['med'][i])
3601 list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
3602 list[lastmode]['min'] = tMin
3603 list[lastmode]['max'] = tMax
3604 list[lastmode]['idx'] = (iMin, iMed, iMax)
3608 for ilk in sorted(cnt, reverse=True):
3610 desc.append('%d %s' % (cnt[ilk], ilk))
3611 html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (title, len(testruns), ', '.join(desc))
3612 th = '\t<th>{0}</th>\n'
3613 td = '\t<td>{0}</td>\n'
3614 tdh = '\t<td{1}>{0}</td>\n'
3615 tdlink = '\t<td><a href="{0}">html</a></td>\n'
3618 html += '<table class="summary">\n<tr>\n' + th.format('#') +\
3619 th.format('Mode') + th.format('Host') + th.format('Kernel') +\
3620 th.format('Test Time') + th.format('Result') + th.format('Issues') +\
3621 th.format('Suspend') + th.format('Resume') +\
3622 th.format('Worst Suspend Device') + th.format('SD Time') +\
3623 th.format('Worst Resume Device') + th.format('RD Time') +\
3624 th.format('Detail') + '</tr>\n'
3626 # export list into html
3627 head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\
3628 '<td colspan=12 class="sus">Suspend Avg={2} '+\
3629 '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\
3630 '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\
3631 '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\
3633 '<span class=minval><a href="#r{10}min">Min={7}</a></span> '+\
3634 '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\
3635 '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\
3637 headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=12></td></tr>\n'
3639 # header line for each suspend mode
3641 tAvg, tMin, tMax, tMed = list[mode]['avg'], list[mode]['min'],\
3642 list[mode]['max'], list[mode]['med']
3643 count = len(list[mode]['data'])
3644 if 'idx' in list[mode]:
3645 iMin, iMed, iMax = list[mode]['idx']
3646 html += head.format('%d' % count, mode.upper(),
3647 '%.3f' % tAvg[0], '%.3f' % tMin[0], '%.3f' % tMed[0], '%.3f' % tMax[0],
3648 '%.3f' % tAvg[1], '%.3f' % tMin[1], '%.3f' % tMed[1], '%.3f' % tMax[1],
3652 iMin = iMed = iMax = [-1, -1, -1]
3653 html += headnone.format('%d' % count, mode.upper())
3654 for d in list[mode]['data']:
3655 # row classes - alternate row color
3656 rcls = ['alt'] if num % 2 == 1 else []
3658 rcls.append('notice')
3659 html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
3660 # figure out if the line has sus or res highlighted
3661 idx = list[mode]['data'].index(d)
3664 tag = 's%s' % mode if i == 0 else 'r%s' % mode
3666 tHigh[i] = ' id="%smin" class=minval title="Minimum"' % tag
3667 elif idx == iMax[i]:
3668 tHigh[i] = ' id="%smax" class=maxval title="Maximum"' % tag
3669 elif idx == iMed[i]:
3670 tHigh[i] = ' id="%smed" class=medval title="Median"' % tag
3671 html += td.format("%d" % (list[mode]['data'].index(d) + 1)) # row
3672 html += td.format(mode) # mode
3673 html += td.format(d[0]) # host
3674 html += td.format(d[1]) # kernel
3675 html += td.format(d[2]) # time
3676 html += td.format(d[6]) # result
3677 html += td.format(d[7]) # issues
3678 html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend
3679 html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume
3680 html += td.format(d[8]) # sus_worst
3681 html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time
3682 html += td.format(d[10]) # res_worst
3683 html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time
3684 html += tdlink.format(d[5]) if d[5] else td.format('') # url
3688 # flush the data to file
3689 hf = open(htmlfile, 'w')
3690 hf.write(html+'</table>\n</body>\n</html>\n')
3695 if value < 10 or value > 19:
3698 elif value % 10 == 2:
3700 elif value % 10 == 3:
3702 return '%d%s' % (value, suffix)
3704 # Function: createHTML
3706 # Create the output html file from the resident test data
3708 # testruns: array of Data objects from parseKernelLog or parseTraceLog
3710 # True if the html file was created, false if it failed
3711 def createHTML(testruns, testfail):
3712 if len(testruns) < 1:
3713 pprint('ERROR: Not enough test data to build a timeline')
3717 for data in testruns:
3720 if(sysvals.suspendmode in ['freeze', 'standby']):
3721 data.trimFreezeTime(testruns[-1].tSuspended)
3723 # html function templates
3724 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</div>\n'
3725 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'
3726 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
3727 html_timetotal = '<table class="time1">\n<tr>'\
3728 '<td class="green" title="{3}">{2} Suspend Time: <b>{0} ms</b></td>'\
3729 '<td class="yellow" title="{4}">{2} Resume Time: <b>{1} ms</b></td>'\
3731 html_timetotal2 = '<table class="time1">\n<tr>'\
3732 '<td class="green" title="{4}">{3} Suspend Time: <b>{0} ms</b></td>'\
3733 '<td class="gray" title="time spent in low-power mode with clock running">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
3734 '<td class="yellow" title="{5}">{3} Resume Time: <b>{2} ms</b></td>'\
3736 html_timetotal3 = '<table class="time1">\n<tr>'\
3737 '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3738 '<td class="yellow">Command: <b>{1}</b></td>'\
3740 html_timegroups = '<table class="time2">\n<tr>'\
3741 '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\
3742 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3743 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
3744 '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\
3746 html_fail = '<table class="testfail"><tr><td>{0}</td></tr></table>\n'
3748 # html format variables
3754 devtl = Timeline(30, scaleH)
3756 # write the test title and general info header
3757 devtl.createHeader(sysvals, testruns[0].stamp)
3759 # Generate the header for this timeline
3760 for data in testruns:
3761 tTotal = data.end - data.start
3762 sktime, rktime = data.getTimeValues()
3764 doError('No timeline data')
3765 if(len(data.tLow) > 0):
3766 low_time = '|'.join(data.tLow)
3767 if sysvals.suspendmode == 'command':
3768 run_time = '%.0f'%((data.end-data.start)*1000)
3769 if sysvals.testcommand:
3770 testdesc = sysvals.testcommand
3772 testdesc = 'unknown'
3773 if(len(testruns) > 1):
3774 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3775 thtml = html_timetotal3.format(run_time, testdesc)
3778 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3779 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
3782 stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode
3783 rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode
3784 if(len(testruns) > 1):
3785 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3787 if(len(data.tLow) == 0):
3788 thtml = html_timetotal.format(suspend_time, \
3789 resume_time, testdesc1, stitle, rtitle)
3791 thtml = html_timetotal2.format(suspend_time, low_time, \
3792 resume_time, testdesc1, stitle, rtitle)
3794 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3795 rftime = '%.3f'%(data.fwResume / 1000000.0)
3796 devtl.html += html_timegroups.format('%.3f'%sktime, \
3797 sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode)
3799 suspend_time = '%.3f' % sktime
3800 resume_time = '%.3f' % rktime
3802 stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode
3803 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode
3804 if(len(testruns) > 1):
3805 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3806 if(len(data.tLow) == 0):
3807 thtml = html_timetotal.format(suspend_time, \
3808 resume_time, testdesc, stitle, rtitle)
3810 thtml = html_timetotal2.format(suspend_time, low_time, \
3811 resume_time, testdesc, stitle, rtitle)
3815 devtl.html += html_fail.format(testfail)
3817 # time scale for potentially multiple datasets
3818 t0 = testruns[0].start
3819 tMax = testruns[-1].end
3822 # determine the maximum number of rows we need to draw
3827 for data in testruns:
3828 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
3829 for group in data.devicegroups:
3832 for devname in data.tdevlist[phase]:
3833 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3836 threadlist.append(d)
3843 if sysvals.mixedphaseheight:
3844 devtl.getPhaseRows(devlist)
3845 if not sysvals.mixedphaseheight:
3846 if len(threadlist) > 0 and len(fulllist) > 0:
3847 if pscnt > 0 and devcnt > 0:
3848 msg = 'user processes & device pm callbacks'
3850 msg = 'user processes'
3852 msg = 'device pm callbacks'
3853 d = testruns[0].addHorizontalDivider(msg, testruns[-1].end)
3854 fulllist.insert(0, d)
3855 devtl.getPhaseRows(fulllist)
3856 if len(threadlist) > 0:
3857 d = testruns[0].addHorizontalDivider('asynchronous kernel threads', testruns[-1].end)
3858 threadlist.insert(0, d)
3859 devtl.getPhaseRows(threadlist, devtl.rows)
3860 devtl.calcTotalRows()
3862 # draw the full timeline
3863 devtl.createZoomBox(sysvals.suspendmode, len(testruns))
3864 for data in testruns:
3865 # draw each test run and block chronologically
3866 phases = {'suspend':[],'resume':[]}
3867 for phase in data.sortedPhases():
3868 if data.dmesg[phase]['start'] >= data.tSuspended:
3869 phases['resume'].append(phase)
3871 phases['suspend'].append(phase)
3872 # now draw the actual timeline blocks
3874 # draw suspend and resume blocks separately
3875 bname = '%s%d' % (dir[0], data.testnumber)
3876 if dir == 'suspend':
3878 mMax = data.tSuspended
3879 left = '%f' % (((m0-t0)*100.0)/tTotal)
3881 m0 = data.tSuspended
3883 # in an x2 run, remove any gap between blocks
3884 if len(testruns) > 1 and data.testnumber == 0:
3885 mMax = testruns[1].start
3886 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
3888 # if a timeline block is 0 length, skip altogether
3891 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3892 devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)
3893 for b in phases[dir]:
3894 # draw the phase color background
3895 phase = data.dmesg[b]
3896 length = phase['end']-phase['start']
3897 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
3898 width = '%f' % ((length*100.0)/mTotal)
3899 devtl.html += devtl.html_phase.format(left, width, \
3900 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
3901 data.dmesg[b]['color'], '')
3902 for e in data.errorinfo[dir]:
3903 # draw red lines for any kernel errors found
3904 type, t, idx1, idx2 = e
3905 id = '%d_%d' % (idx1, idx2)
3906 right = '%f' % (((mMax-t)*100.0)/mTotal)
3907 devtl.html += html_error.format(right, id, type)
3908 for b in phases[dir]:
3909 # draw the devices for this phase
3910 phaselist = data.dmesg[b]['list']
3911 for d in data.tdevlist[b]:
3918 if 'htmlclass' in dev:
3919 xtraclass = dev['htmlclass']
3921 xtrastyle = 'background:%s;' % dev['color']
3922 if(d in sysvals.devprops):
3923 name = sysvals.devprops[d].altName(d)
3924 xtraclass = sysvals.devprops[d].xtraClass()
3925 xtrainfo = sysvals.devprops[d].xtraInfo()
3926 elif xtraclass == ' kth':
3927 xtrainfo = ' kernel_thread'
3928 if('drv' in dev and dev['drv']):
3929 drv = ' {%s}' % dev['drv']
3930 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row'])
3931 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row'])
3932 top = '%.3f' % (rowtop + devtl.scaleH)
3933 left = '%f' % (((dev['start']-m0)*100)/mTotal)
3934 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
3935 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
3936 title = name+drv+xtrainfo+length
3937 if sysvals.suspendmode == 'command':
3938 title += sysvals.testcommand
3939 elif xtraclass == ' ps':
3941 title += 'pre_suspend_process'
3943 title += 'post_resume_process'
3946 devtl.html += devtl.html_device.format(dev['id'], \
3947 title, left, top, '%.3f'%rowheight, width, \
3948 d+drv, xtraclass, xtrastyle)
3949 if('cpuexec' in dev):
3950 for t in sorted(dev['cpuexec']):
3952 j = float(dev['cpuexec'][t]) / 5
3955 height = '%.3f' % (rowheight/3)
3956 top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3)
3957 left = '%f' % (((start-m0)*100)/mTotal)
3958 width = '%f' % ((end-start)*100/mTotal)
3959 color = 'rgba(255, 0, 0, %f)' % j
3961 html_cpuexec.format(left, top, height, width, color)
3962 if('src' not in dev):
3964 # draw any trace events for this device
3965 for e in dev['src']:
3966 height = '%.3f' % devtl.rowH
3967 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
3968 left = '%f' % (((e.time-m0)*100)/mTotal)
3969 width = '%f' % (e.length*100/mTotal)
3972 xtrastyle = 'background:%s;' % e.color
3974 html_traceevent.format(e.title(), \
3975 left, top, height, width, e.text(), '', xtrastyle)
3976 # draw the time scale, try to make the number of labels readable
3977 devtl.createTimeScale(m0, mMax, tTotal, dir)
3978 devtl.html += '</div>\n'
3980 # timeline is finished
3981 devtl.html += '</div>\n</div>\n'
3983 # draw a legend which describes the phases by color
3984 if sysvals.suspendmode != 'command':
3985 phasedef = testruns[-1].phasedef
3986 devtl.html += '<div class="legend">\n'
3987 pdelta = 100.0/len(phasedef.keys())
3988 pmargin = pdelta / 4.0
3989 for phase in sorted(phasedef, key=lambda k:phasedef[k]['order']):
3990 id, p = '', phasedef[phase]
3991 for word in phase.split('_'):
3993 order = '%.2f' % ((p['order'] * pdelta) + pmargin)
3994 name = string.replace(phase, '_', ' ')
3995 devtl.html += devtl.html_legend.format(order, p['color'], name, id)
3996 devtl.html += '</div>\n'
3998 hf = open(sysvals.htmlfile, 'w')
3999 addCSS(hf, sysvals, len(testruns), kerror)
4001 # write the device timeline
4002 hf.write(devtl.html)
4003 hf.write('<div id="devicedetailtitle"></div>\n')
4004 hf.write('<div id="devicedetail" style="display:none;">\n')
4005 # draw the colored boxes for the device detail section
4006 for data in testruns:
4007 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
4008 pscolor = 'linear-gradient(to top left, #ccc, #eee)'
4009 hf.write(devtl.html_phaselet.format('pre_suspend_process', \
4011 for b in data.sortedPhases():
4012 phase = data.dmesg[b]
4013 length = phase['end']-phase['start']
4014 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
4015 width = '%.3f' % ((length*100.0)/tTotal)
4016 hf.write(devtl.html_phaselet.format(b, left, width, \
4017 data.dmesg[b]['color']))
4018 hf.write(devtl.html_phaselet.format('post_resume_process', \
4020 if sysvals.suspendmode == 'command':
4021 hf.write(devtl.html_phaselet.format('cmdexec', '0', '0', pscolor))
4022 hf.write('</div>\n')
4023 hf.write('</div>\n')
4025 # write the ftrace data (callgraph)
4026 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
4027 data = testruns[sysvals.cgtest]
4030 if sysvals.usecallgraph:
4031 addCallgraphs(sysvals, hf, data)
4033 # add the test log as a hidden div
4034 if sysvals.testlog and sysvals.logmsg:
4035 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
4036 # add the dmesg log as a hidden div
4037 if sysvals.dmesglog and sysvals.dmesgfile:
4038 hf.write('<div id="dmesglog" style="display:none;">\n')
4039 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
4041 line = line.replace('<', '<').replace('>', '>')
4044 hf.write('</div>\n')
4045 # add the ftrace log as a hidden div
4046 if sysvals.ftracelog and sysvals.ftracefile:
4047 hf.write('<div id="ftracelog" style="display:none;">\n')
4048 lf = sysvals.openlog(sysvals.ftracefile, 'r')
4052 hf.write('</div>\n')
4054 # write the footer and close
4055 addScriptCode(hf, testruns)
4056 hf.write('</body>\n</html>\n')
4060 def addCSS(hf, sv, testcount=1, kerror=False, extra=''):
4061 kernel = sv.stamp['kernel']
4062 host = sv.hostname[0].upper()+sv.hostname[1:]
4063 mode = sv.suspendmode
4064 if sv.suspendmode in suspendmodename:
4065 mode = suspendmodename[sv.suspendmode]
4066 title = host+' '+mode+' '+kernel
4068 # various format changes by flags
4070 cgnchk = 'not(:checked)'
4072 cgchk = 'not(:checked)'
4075 hoverZ = 'z-index:8;'
4079 devlistpos = 'absolute'
4081 devlistpos = 'relative'
4087 # write the html header first (html head, css code, up to body start)
4088 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
4089 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
4090 <title>'+title+'</title>\n\
4091 <style type=\'text/css\'>\n\
4092 body {overflow-y:scroll;}\n\
4093 .stamp {width:100%;text-align:center;background:gray;line-height:30px;color:white;font:25px Arial;}\n\
4094 .stamp.sysinfo {font:10px Arial;}\n\
4095 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
4096 .callgraph article * {padding-left:28px;}\n\
4097 h1 {color:black;font:bold 30px Times;}\n\
4098 t0 {color:black;font:bold 30px Times;}\n\
4099 t1 {color:black;font:30px Times;}\n\
4100 t2 {color:black;font:25px Times;}\n\
4101 t3 {color:black;font:20px Times;white-space:nowrap;}\n\
4102 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
4103 cS {font:bold 13px Times;}\n\
4104 table {width:100%;}\n\
4105 .gray {background:rgba(80,80,80,0.1);}\n\
4106 .green {background:rgba(204,255,204,0.4);}\n\
4107 .purple {background:rgba(128,0,128,0.2);}\n\
4108 .yellow {background:rgba(255,255,204,0.4);}\n\
4109 .blue {background:rgba(169,208,245,0.4);}\n\
4110 .time1 {font:22px Arial;border:1px solid;}\n\
4111 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
4112 .testfail {font:bold 22px Arial;color:red;border:1px dashed;}\n\
4113 td {text-align:center;}\n\
4114 r {color:#500000;font:15px Tahoma;}\n\
4115 n {color:#505050;font:15px Tahoma;}\n\
4116 .tdhl {color:red;}\n\
4117 .hide {display:none;}\n\
4118 .pf {display:none;}\n\
4119 .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\
4120 .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\
4121 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
4122 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\
4123 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
4124 .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\
4125 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\
4126 .thread:hover {background:white;border:1px solid red;'+hoverZ+'}\n\
4127 .thread.sec,.thread.sec:hover {background:black;border:0;color:white;line-height:15px;font-size:10px;}\n\
4128 .hover {background:white;border:1px solid red;'+hoverZ+'}\n\
4129 .hover.sync {background:white;}\n\
4130 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background:white;}\n\
4131 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\
4132 .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\
4133 .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\
4134 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
4135 .phaselet {float:left;overflow:hidden;border:0px;text-align:center;min-height:100px;font-size:24px;}\n\
4136 .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\
4137 .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\
4138 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
4139 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
4140 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
4141 .btnfmt {position:relative;float:right;height:25px;width:auto;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
4142 .devlist {position:'+devlistpos+';width:190px;}\n\
4143 a:link {color:white;text-decoration:none;}\n\
4144 a:visited {color:white;}\n\
4145 a:hover {color:white;}\n\
4146 a:active {color:white;}\n\
4147 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
4148 #devicedetail {min-height:100px;box-shadow:5px 5px 20px black;}\n\
4149 .tblock {position:absolute;height:100%;background:#ddd;}\n\
4150 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\
4153 </style>\n</head>\n<body>\n'
4154 hf.write(html_header)
4156 # Function: addScriptCode
4158 # Adds the javascript code to the output html
4160 # hf: the open html file pointer
4161 # testruns: array of Data objects from parseKernelLog or parseTraceLog
4162 def addScriptCode(hf, testruns):
4163 t0 = testruns[0].start * 1000
4164 tMax = testruns[-1].end * 1000
4165 # create an array in javascript memory with the device details
4166 detail = ' var devtable = [];\n'
4167 for data in testruns:
4168 topo = data.deviceTopology()
4169 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
4170 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
4171 # add the code which will manipulate the data in the browser
4173 '<script type="text/javascript">\n'+detail+\
4174 ' var resolution = -1;\n'\
4175 ' var dragval = [0, 0];\n'\
4176 ' function redrawTimescale(t0, tMax, tS) {\n'\
4177 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;">\';\n'\
4178 ' var tTotal = tMax - t0;\n'\
4179 ' var list = document.getElementsByClassName("tblock");\n'\
4180 ' for (var i = 0; i < list.length; i++) {\n'\
4181 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
4182 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
4183 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
4184 ' var mMax = m0 + mTotal;\n'\
4185 ' var html = "";\n'\
4186 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
4187 ' if(divTotal > 1000) continue;\n'\
4188 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
4189 ' var pos = 0.0, val = 0.0;\n'\
4190 ' for (var j = 0; j < divTotal; j++) {\n'\
4191 ' var htmlline = "";\n'\
4192 ' var mode = list[i].id[5];\n'\
4193 ' if(mode == "s") {\n'\
4194 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
4195 ' val = (j-divTotal+1)*tS;\n'\
4196 ' if(j == divTotal - 1)\n'\
4197 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S→</cS></div>\';\n'\
4199 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
4201 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
4203 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
4205 ' if(mode == "r")\n'\
4206 ' htmlline = rline+"<cS>←R</cS></div>";\n'\
4208 ' htmlline = rline+"<cS>0ms</div>";\n'\
4210 ' html += htmlline;\n'\
4212 ' timescale.innerHTML = html;\n'\
4215 ' function zoomTimeline() {\n'\
4216 ' var dmesg = document.getElementById("dmesg");\n'\
4217 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4218 ' var left = zoombox.scrollLeft;\n'\
4219 ' var val = parseFloat(dmesg.style.width);\n'\
4220 ' var newval = 100;\n'\
4221 ' var sh = window.outerWidth / 2;\n'\
4222 ' if(this.id == "zoomin") {\n'\
4223 ' newval = val * 1.2;\n'\
4224 ' if(newval > 910034) newval = 910034;\n'\
4225 ' dmesg.style.width = newval+"%";\n'\
4226 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
4227 ' } else if (this.id == "zoomout") {\n'\
4228 ' newval = val / 1.2;\n'\
4229 ' if(newval < 100) newval = 100;\n'\
4230 ' dmesg.style.width = newval+"%";\n'\
4231 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
4233 ' zoombox.scrollLeft = 0;\n'\
4234 ' dmesg.style.width = "100%";\n'\
4236 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
4237 ' var t0 = bounds[0];\n'\
4238 ' var tMax = bounds[1];\n'\
4239 ' var tTotal = tMax - t0;\n'\
4240 ' var wTotal = tTotal * 100.0 / newval;\n'\
4241 ' var idx = 7*window.innerWidth/1100;\n'\
4242 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
4243 ' if(i >= tS.length) i = tS.length - 1;\n'\
4244 ' if(tS[i] == resolution) return;\n'\
4245 ' resolution = tS[i];\n'\
4246 ' redrawTimescale(t0, tMax, tS[i]);\n'\
4248 ' function deviceName(title) {\n'\
4249 ' var name = title.slice(0, title.indexOf(" ("));\n'\
4252 ' function deviceHover() {\n'\
4253 ' var name = deviceName(this.title);\n'\
4254 ' var dmesg = document.getElementById("dmesg");\n'\
4255 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4257 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
4258 ' cpu = parseInt(name.slice(7));\n'\
4259 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
4260 ' cpu = parseInt(name.slice(8));\n'\
4261 ' for (var i = 0; i < dev.length; i++) {\n'\
4262 ' dname = deviceName(dev[i].title);\n'\
4263 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
4264 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
4265 ' (name == dname))\n'\
4267 ' dev[i].className = "hover "+cname;\n'\
4269 ' dev[i].className = cname;\n'\
4273 ' function deviceUnhover() {\n'\
4274 ' var dmesg = document.getElementById("dmesg");\n'\
4275 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4276 ' for (var i = 0; i < dev.length; i++) {\n'\
4277 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
4280 ' function deviceTitle(title, total, cpu) {\n'\
4281 ' var prefix = "Total";\n'\
4282 ' if(total.length > 3) {\n'\
4283 ' prefix = "Average";\n'\
4284 ' total[1] = (total[1]+total[3])/2;\n'\
4285 ' total[2] = (total[2]+total[4])/2;\n'\
4287 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
4288 ' var name = deviceName(title);\n'\
4289 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
4290 ' var driver = "";\n'\
4291 ' var tS = "<t2>(</t2>";\n'\
4292 ' var tR = "<t2>)</t2>";\n'\
4293 ' if(total[1] > 0)\n'\
4294 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
4295 ' if(total[2] > 0)\n'\
4296 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
4297 ' var s = title.indexOf("{");\n'\
4298 ' var e = title.indexOf("}");\n'\
4299 ' if((s >= 0) && (e >= 0))\n'\
4300 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
4301 ' if(total[1] > 0 && total[2] > 0)\n'\
4302 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
4304 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
4307 ' function deviceDetail() {\n'\
4308 ' var devinfo = document.getElementById("devicedetail");\n'\
4309 ' devinfo.style.display = "block";\n'\
4310 ' var name = deviceName(this.title);\n'\
4312 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
4313 ' cpu = parseInt(name.slice(7));\n'\
4314 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
4315 ' cpu = parseInt(name.slice(8));\n'\
4316 ' var dmesg = document.getElementById("dmesg");\n'\
4317 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4318 ' var idlist = [];\n'\
4319 ' var pdata = [[]];\n'\
4320 ' if(document.getElementById("devicedetail1"))\n'\
4321 ' pdata = [[], []];\n'\
4322 ' var pd = pdata[0];\n'\
4323 ' var total = [0.0, 0.0, 0.0];\n'\
4324 ' for (var i = 0; i < dev.length; i++) {\n'\
4325 ' dname = deviceName(dev[i].title);\n'\
4326 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
4327 ' (name == dname))\n'\
4329 ' idlist[idlist.length] = dev[i].id;\n'\
4331 ' if(dev[i].id[0] == "a") {\n'\
4332 ' pd = pdata[0];\n'\
4334 ' if(pdata.length == 1) pdata[1] = [];\n'\
4335 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
4336 ' pd = pdata[1];\n'\
4339 ' var info = dev[i].title.split(" ");\n'\
4340 ' var pname = info[info.length-1];\n'\
4341 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
4342 ' total[0] += pd[pname];\n'\
4343 ' if(pname.indexOf("suspend") >= 0)\n'\
4344 ' total[tidx] += pd[pname];\n'\
4346 ' total[tidx+1] += pd[pname];\n'\
4349 ' var devname = deviceTitle(this.title, total, cpu);\n'\
4350 ' var left = 0.0;\n'\
4351 ' for (var t = 0; t < pdata.length; t++) {\n'\
4352 ' pd = pdata[t];\n'\
4353 ' devinfo = document.getElementById("devicedetail"+t);\n'\
4354 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
4355 ' for (var i = 0; i < phases.length; i++) {\n'\
4356 ' if(phases[i].id in pd) {\n'\
4357 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
4359 ' if(w < 8) fs = 4*w | 0;\n'\
4360 ' var fs2 = fs*3/4;\n'\
4361 ' phases[i].style.width = w+"%";\n'\
4362 ' phases[i].style.left = left+"%";\n'\
4363 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
4365 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
4366 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\
4367 ' phases[i].innerHTML = time+pname;\n'\
4369 ' phases[i].style.width = "0%";\n'\
4370 ' phases[i].style.left = left+"%";\n'\
4374 ' if(typeof devstats !== \'undefined\')\n'\
4375 ' callDetail(this.id, this.title);\n'\
4376 ' var cglist = document.getElementById("callgraphs");\n'\
4377 ' if(!cglist) return;\n'\
4378 ' var cg = cglist.getElementsByClassName("atop");\n'\
4379 ' if(cg.length < 10) return;\n'\
4380 ' for (var i = 0; i < cg.length; i++) {\n'\
4381 ' cgid = cg[i].id.split("x")[0]\n'\
4382 ' if(idlist.indexOf(cgid) >= 0) {\n'\
4383 ' cg[i].style.display = "block";\n'\
4385 ' cg[i].style.display = "none";\n'\
4389 ' function callDetail(devid, devtitle) {\n'\
4390 ' if(!(devid in devstats) || devstats[devid].length < 1)\n'\
4392 ' var list = devstats[devid];\n'\
4393 ' var tmp = devtitle.split(" ");\n'\
4394 ' var name = tmp[0], phase = tmp[tmp.length-1];\n'\
4395 ' var dd = document.getElementById(phase);\n'\
4396 ' var total = parseFloat(tmp[1].slice(1));\n'\
4397 ' var mlist = [];\n'\
4398 ' var maxlen = 0;\n'\
4400 ' for(var i in list) {\n'\
4401 ' if(list[i][0] == "@") {\n'\
4402 ' info = list[i].split("|");\n'\
4405 ' var tmp = list[i].split("|");\n'\
4406 ' var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]);\n'\
4407 ' var p = (t*100.0/total).toFixed(2);\n'\
4408 ' mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"];\n'\
4409 ' if(f.length > maxlen)\n'\
4410 ' maxlen = f.length;\n'\
4413 ' if(mlist.length == 0) pad = 30;\n'\
4414 ' var html = \'<div style="padding-top:\'+pad+\'px"><t3> <b>\'+name+\':</b>\';\n'\
4415 ' if(info.length > 2)\n'\
4416 ' html += " start=<b>"+info[1]+"</b>, end=<b>"+info[2]+"</b>";\n'\
4417 ' if(info.length > 3)\n'\
4418 ' html += ", length<i>(w/o overhead)</i>=<b>"+info[3]+" ms</b>";\n'\
4419 ' if(info.length > 4)\n'\
4420 ' html += ", return=<b>"+info[4]+"</b>";\n'\
4421 ' html += "</t3></div>";\n'\
4422 ' if(mlist.length > 0) {\n'\
4423 ' html += \'<table class=fstat style="padding-top:\'+(maxlen*5)+\'px;"><tr><th>Function</th>\';\n'\
4424 ' for(var i in mlist)\n'\
4425 ' html += "<td class=vt>"+mlist[i][0]+"</td>";\n'\
4426 ' html += "</tr><tr><th>Calls</th>";\n'\
4427 ' for(var i in mlist)\n'\
4428 ' html += "<td>"+mlist[i][1]+"</td>";\n'\
4429 ' html += "</tr><tr><th>Time(ms)</th>";\n'\
4430 ' for(var i in mlist)\n'\
4431 ' html += "<td>"+mlist[i][2]+"</td>";\n'\
4432 ' html += "</tr><tr><th>Percent</th>";\n'\
4433 ' for(var i in mlist)\n'\
4434 ' html += "<td>"+mlist[i][3]+"</td>";\n'\
4435 ' html += "</tr></table>";\n'\
4437 ' dd.innerHTML = html;\n'\
4438 ' var height = (maxlen*5)+100;\n'\
4439 ' dd.style.height = height+"px";\n'\
4440 ' document.getElementById("devicedetail").style.height = height+"px";\n'\
4442 ' function callSelect() {\n'\
4443 ' var cglist = document.getElementById("callgraphs");\n'\
4444 ' if(!cglist) return;\n'\
4445 ' var cg = cglist.getElementsByClassName("atop");\n'\
4446 ' for (var i = 0; i < cg.length; i++) {\n'\
4447 ' if(this.id == cg[i].id) {\n'\
4448 ' cg[i].style.display = "block";\n'\
4450 ' cg[i].style.display = "none";\n'\
4454 ' function devListWindow(e) {\n'\
4455 ' var win = window.open();\n'\
4456 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
4457 ' "<style type=\\"text/css\\">"+\n'\
4458 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
4460 ' var dt = devtable[0];\n'\
4461 ' if(e.target.id != "devlist1")\n'\
4462 ' dt = devtable[1];\n'\
4463 ' win.document.write(html+dt);\n'\
4465 ' function errWindow() {\n'\
4466 ' var range = this.id.split("_");\n'\
4467 ' var idx1 = parseInt(range[0]);\n'\
4468 ' var idx2 = parseInt(range[1]);\n'\
4469 ' var win = window.open();\n'\
4470 ' var log = document.getElementById("dmesglog");\n'\
4471 ' var title = "<title>dmesg log</title>";\n'\
4472 ' var text = log.innerHTML.split("\\n");\n'\
4473 ' var html = "";\n'\
4474 ' for(var i = 0; i < text.length; i++) {\n'\
4475 ' if(i == idx1) {\n'\
4476 ' html += "<e id=target>"+text[i]+"</e>\\n";\n'\
4477 ' } else if(i > idx1 && i <= idx2) {\n'\
4478 ' html += "<e>"+text[i]+"</e>\\n";\n'\
4480 ' html += text[i]+"\\n";\n'\
4483 ' win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>");\n'\
4484 ' win.location.hash = "#target";\n'\
4485 ' win.document.close();\n'\
4487 ' function logWindow(e) {\n'\
4488 ' var name = e.target.id.slice(4);\n'\
4489 ' var win = window.open();\n'\
4490 ' var log = document.getElementById(name+"log");\n'\
4491 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
4492 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
4493 ' win.document.close();\n'\
4495 ' function onMouseDown(e) {\n'\
4496 ' dragval[0] = e.clientX;\n'\
4497 ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\
4498 ' document.onmousemove = onMouseMove;\n'\
4500 ' function onMouseMove(e) {\n'\
4501 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4502 ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\
4504 ' function onMouseUp(e) {\n'\
4505 ' document.onmousemove = null;\n'\
4507 ' function onKeyPress(e) {\n'\
4508 ' var c = e.charCode;\n'\
4509 ' if(c != 42 && c != 43 && c != 45) return;\n'\
4510 ' var click = document.createEvent("Events");\n'\
4511 ' click.initEvent("click", true, false);\n'\
4513 ' document.getElementById("zoomin").dispatchEvent(click);\n'\
4514 ' else if(c == 45)\n'\
4515 ' document.getElementById("zoomout").dispatchEvent(click);\n'\
4516 ' else if(c == 42)\n'\
4517 ' document.getElementById("zoomdef").dispatchEvent(click);\n'\
4519 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
4520 ' window.addEventListener("load", function () {\n'\
4521 ' var dmesg = document.getElementById("dmesg");\n'\
4522 ' dmesg.style.width = "100%"\n'\
4523 ' dmesg.onmousedown = onMouseDown;\n'\
4524 ' document.onmouseup = onMouseUp;\n'\
4525 ' document.onkeypress = onKeyPress;\n'\
4526 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
4527 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
4528 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
4529 ' var list = document.getElementsByClassName("err");\n'\
4530 ' for (var i = 0; i < list.length; i++)\n'\
4531 ' list[i].onclick = errWindow;\n'\
4532 ' var list = document.getElementsByClassName("logbtn");\n'\
4533 ' for (var i = 0; i < list.length; i++)\n'\
4534 ' list[i].onclick = logWindow;\n'\
4535 ' list = document.getElementsByClassName("devlist");\n'\
4536 ' for (var i = 0; i < list.length; i++)\n'\
4537 ' list[i].onclick = devListWindow;\n'\
4538 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4539 ' for (var i = 0; i < dev.length; i++) {\n'\
4540 ' dev[i].onclick = deviceDetail;\n'\
4541 ' dev[i].onmouseover = deviceHover;\n'\
4542 ' dev[i].onmouseout = deviceUnhover;\n'\
4544 ' var dev = dmesg.getElementsByClassName("srccall");\n'\
4545 ' for (var i = 0; i < dev.length; i++)\n'\
4546 ' dev[i].onclick = callSelect;\n'\
4547 ' zoomTimeline();\n'\
4550 hf.write(script_code);
4552 def setRuntimeSuspend(before=True):
4558 # runtime suspend disable or enable
4560 sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled'
4562 sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled'
4563 pprint('CONFIGURING RUNTIME SUSPEND...')
4564 sv.rslist = deviceInfo(sv.rstgt)
4566 sv.setVal(sv.rsval, i)
4567 pprint('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist)))
4568 pprint('waiting 5 seconds...')
4571 # runtime suspend re-enable or re-disable
4573 sv.setVal(sv.rstgt, i)
4574 pprint('runtime suspend settings restored on %d devices' % len(sv.rslist))
4576 # Function: executeSuspend
4578 # Execute system suspend through the sysfs interface, then copy the output
4579 # dmesg and ftrace files to the test output directory.
4580 def executeSuspend():
4581 pm = ProcessMonitor()
4584 battery = True if getBattery() else False
4585 # run these commands to prepare the system for suspend
4587 pprint('SET DISPLAY TO %s' % sysvals.display.upper())
4588 displayControl(sysvals.display)
4591 pprint('SYNCING FILESYSTEMS')
4592 call('sync', shell=True)
4593 # mark the start point in the kernel ring buffer just as we start
4596 if(sysvals.usecallgraph or sysvals.usetraceevents):
4597 pprint('START TRACING')
4598 sysvals.fsetVal('1', 'tracing_on')
4599 if sysvals.useprocmon:
4601 # execute however many s/r runs requested
4602 for count in range(1,sysvals.execcount+1):
4603 # x2delay in between test runs
4604 if(count > 1 and sysvals.x2delay > 0):
4605 sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
4606 time.sleep(sysvals.x2delay/1000.0)
4607 sysvals.fsetVal('WAIT END', 'trace_marker')
4609 if sysvals.testcommand != '':
4610 pprint('COMMAND START')
4612 if(sysvals.rtcwake):
4613 pprint('SUSPEND START')
4615 pprint('SUSPEND START (press a key to resume)')
4616 bat1 = getBattery() if battery else False
4618 if(sysvals.rtcwake):
4619 pprint('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
4620 sysvals.rtcWakeAlarmOn()
4621 # start of suspend trace marker
4622 if(sysvals.usecallgraph or sysvals.usetraceevents):
4623 sysvals.fsetVal('SUSPEND START', 'trace_marker')
4625 if(count == 1 and sysvals.predelay > 0):
4626 sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
4627 time.sleep(sysvals.predelay/1000.0)
4628 sysvals.fsetVal('WAIT END', 'trace_marker')
4629 # initiate suspend or command
4630 tdata = {'error': ''}
4631 if sysvals.testcommand != '':
4632 res = call(sysvals.testcommand+' 2>&1', shell=True);
4634 tdata['error'] = 'cmd returned %d' % res
4636 mode = sysvals.suspendmode
4637 if sysvals.memmode and os.path.exists(sysvals.mempowerfile):
4639 pf = open(sysvals.mempowerfile, 'w')
4640 pf.write(sysvals.memmode)
4642 if sysvals.diskmode and os.path.exists(sysvals.diskpowerfile):
4644 pf = open(sysvals.diskpowerfile, 'w')
4645 pf.write(sysvals.diskmode)
4647 pf = open(sysvals.powerfile, 'w')
4649 # execution will pause here
4652 except Exception as e:
4653 tdata['error'] = str(e)
4654 if(sysvals.rtcwake):
4655 sysvals.rtcWakeAlarmOff()
4657 if(count == sysvals.execcount and sysvals.postdelay > 0):
4658 sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
4659 time.sleep(sysvals.postdelay/1000.0)
4660 sysvals.fsetVal('WAIT END', 'trace_marker')
4661 # return from suspend
4662 pprint('RESUME COMPLETE')
4663 if(sysvals.usecallgraph or sysvals.usetraceevents):
4664 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
4665 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4666 tdata['fw'] = getFPDT(False)
4667 bat2 = getBattery() if battery else False
4668 if battery and bat1 and bat2:
4669 tdata['bat'] = (bat1, bat2)
4670 testdata.append(tdata)
4672 if(sysvals.usecallgraph or sysvals.usetraceevents):
4673 if sysvals.useprocmon:
4675 sysvals.fsetVal('0', 'tracing_on')
4676 # grab a copy of the dmesg output
4677 pprint('CAPTURING DMESG')
4678 sysvals.getdmesg(testdata)
4679 # grab a copy of the ftrace output
4680 if(sysvals.usecallgraph or sysvals.usetraceevents):
4681 pprint('CAPTURING TRACE')
4682 op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata)
4683 fp = open(tp+'trace', 'r')
4687 sysvals.fsetVal('', 'trace')
4691 if os.path.islink(file):
4692 return os.readlink(file).split('/')[-1]
4694 return sysvals.getVal(file).strip()
4698 # Print out a very concise time string in minutes and seconds
4700 # The time string, e.g. "1901m16s"
4704 m = (val / 60000) % 60
4705 s = (val / 1000) % 60
4707 return '%d:%02d:%02d' % (h, m, s)
4709 return '%02d:%02d' % (m, s)
4713 list = {'enabled':'A', 'disabled':'S', 'auto':'E', 'on':'D',
4714 'active':'A', 'suspended':'S', 'suspending':'S'}
4719 # Function: deviceInfo
4721 # Detect all the USB hosts and devices currently connected and add
4722 # a list of USB device names to sysvals for better timeline readability
4723 def deviceInfo(output=''):
4726 '---------------------------------------------------------------------------------------------\n'\
4727 ' A = async/sync PM queue (A/S) C = runtime active children\n'\
4728 ' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)\n'\
4729 ' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)\n'\
4730 ' U = runtime usage count\n'\
4731 '---------------------------------------------------------------------------------------------\n'\
4732 'DEVICE NAME A R S U C rACTIVE rSUSPEND\n'\
4733 '---------------------------------------------------------------------------------------------')
4736 tgtval = 'runtime_status'
4738 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4739 if(not re.match('.*/power', dirname) or
4740 'control' not in filenames or
4741 tgtval not in filenames):
4744 dirname = dirname[:-6]
4745 device = dirname.split('/')[-1]
4747 power[tgtval] = readFile('%s/power/%s' % (dirname, tgtval))
4748 # only list devices which support runtime suspend
4749 if power[tgtval] not in ['active', 'suspended', 'suspending']:
4751 for i in ['product', 'driver', 'subsystem']:
4752 file = '%s/%s' % (dirname, i)
4753 if os.path.exists(file):
4754 name = readFile(file)
4756 for i in ['async', 'control', 'runtime_status', 'runtime_usage',
4757 'runtime_active_kids', 'runtime_active_time',
4758 'runtime_suspended_time']:
4760 power[i] = readFile('%s/power/%s' % (dirname, i))
4762 if power['control'] == output:
4763 res.append('%s/power/control' % dirname)
4765 lines[dirname] = '%-26s %-26s %1s %1s %1s %1s %1s %10s %10s' % \
4766 (device[:26], name[:26],
4767 yesno(power['async']), \
4768 yesno(power['control']), \
4769 yesno(power['runtime_status']), \
4770 power['runtime_usage'], \
4771 power['runtime_active_kids'], \
4772 ms2nice(power['runtime_active_time']), \
4773 ms2nice(power['runtime_suspended_time']))
4774 for i in sorted(lines):
4778 # Function: devProps
4780 # Retrieve a list of properties for all devices in the trace log
4781 def devProps(data=0):
4785 idx = data.index(': ') + 2
4786 if idx >= len(data):
4788 devlist = data[idx:].split(';')
4794 props[dev] = DevProps()
4795 props[dev].altname = f[1]
4797 props[dev].async = True
4799 props[dev].async = False
4800 sysvals.devprops = props
4801 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4802 sysvals.testcommand = props['testcommandstring'].altname
4805 if(os.path.exists(sysvals.ftracefile) == False):
4806 doError('%s does not exist' % sysvals.ftracefile)
4808 # first get the list of devices we need properties for
4809 msghead = 'Additional data added by AnalyzeSuspend'
4810 alreadystamped = False
4812 tf = sysvals.openlog(sysvals.ftracefile, 'r')
4815 alreadystamped = True
4817 # determine the trace data type (required for further parsing)
4818 m = re.match(tp.tracertypefmt, line)
4820 tp.setTracerType(m.group('t'))
4822 # parse only valid lines, if this is not one move on
4823 m = re.match(tp.ftrace_line_fmt, line)
4824 if(not m or 'device_pm_callback_start' not in line):
4826 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
4830 if dev not in props:
4831 props[dev] = DevProps()
4834 if not alreadystamped and sysvals.suspendmode == 'command':
4835 out = '#\n# '+msghead+'\n# Device Properties: '
4836 out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
4837 with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
4839 sysvals.devprops = props
4842 # now get the syspath for each of our target devices
4843 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4844 if(re.match('.*/power', dirname) and 'async' in filenames):
4845 dev = dirname.split('/')[-2]
4846 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
4847 props[dev].syspath = dirname[:-6]
4849 # now fill in the properties for our target devices
4851 dirname = props[dev].syspath
4852 if not dirname or not os.path.exists(dirname):
4854 with open(dirname+'/power/async') as fp:
4856 props[dev].async = False
4857 if 'enabled' in text:
4858 props[dev].async = True
4859 fields = os.listdir(dirname)
4860 if 'product' in fields:
4861 with open(dirname+'/product') as fp:
4862 props[dev].altname = fp.read()
4863 elif 'name' in fields:
4864 with open(dirname+'/name') as fp:
4865 props[dev].altname = fp.read()
4866 elif 'model' in fields:
4867 with open(dirname+'/model') as fp:
4868 props[dev].altname = fp.read()
4869 elif 'description' in fields:
4870 with open(dirname+'/description') as fp:
4871 props[dev].altname = fp.read()
4872 elif 'id' in fields:
4873 with open(dirname+'/id') as fp:
4874 props[dev].altname = fp.read()
4875 elif 'idVendor' in fields and 'idProduct' in fields:
4877 with open(dirname+'/idVendor') as fp:
4878 idv = fp.read().strip()
4879 with open(dirname+'/idProduct') as fp:
4880 idp = fp.read().strip()
4881 props[dev].altname = '%s:%s' % (idv, idp)
4883 if props[dev].altname:
4884 out = props[dev].altname.strip().replace('\n', ' ')
4885 out = out.replace(',', ' ')
4886 out = out.replace(';', ' ')
4887 props[dev].altname = out
4889 # and now write the data to the ftrace file
4890 if not alreadystamped:
4891 out = '#\n# '+msghead+'\n# Device Properties: '
4892 for dev in sorted(props):
4893 out += props[dev].out(dev)
4894 with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
4897 sysvals.devprops = props
4899 # Function: getModes
4901 # Determine the supported power modes on this system
4903 # A string list of the available modes
4906 if(os.path.exists(sysvals.powerfile)):
4907 fp = open(sysvals.powerfile, 'r')
4908 modes = string.split(fp.read())
4910 if(os.path.exists(sysvals.mempowerfile)):
4912 fp = open(sysvals.mempowerfile, 'r')
4913 for m in string.split(fp.read()):
4914 memmode = m.strip('[]')
4915 if memmode == 'deep':
4918 modes.append('mem-%s' % memmode)
4920 if 'mem' in modes and not deep:
4922 if('disk' in modes and os.path.exists(sysvals.diskpowerfile)):
4923 fp = open(sysvals.diskpowerfile, 'r')
4924 for m in string.split(fp.read()):
4925 modes.append('disk-%s' % m.strip('[]'))
4929 # Function: dmidecode
4931 # Read the bios tables and pull out system info
4933 # mempath: /dev/mem or custom mem path
4934 # fatal: True to exit on error, False to return empty dict
4936 # A dict object with all available key/values
4937 def dmidecode(mempath, fatal=False):
4940 # the list of values to retrieve, with hardcoded (type, idx)
4942 'bios-vendor': (0, 4),
4943 'bios-version': (0, 5),
4944 'bios-release-date': (0, 8),
4945 'system-manufacturer': (1, 4),
4946 'system-product-name': (1, 5),
4947 'system-version': (1, 6),
4948 'system-serial-number': (1, 7),
4949 'baseboard-manufacturer': (2, 4),
4950 'baseboard-product-name': (2, 5),
4951 'baseboard-version': (2, 6),
4952 'baseboard-serial-number': (2, 7),
4953 'chassis-manufacturer': (3, 4),
4954 'chassis-type': (3, 5),
4955 'chassis-version': (3, 6),
4956 'chassis-serial-number': (3, 7),
4957 'processor-manufacturer': (4, 7),
4958 'processor-version': (4, 16),
4960 if(not os.path.exists(mempath)):
4962 doError('file does not exist: %s' % mempath)
4964 if(not os.access(mempath, os.R_OK)):
4966 doError('file is not readable: %s' % mempath)
4969 # by default use legacy scan, but try to use EFI first
4972 for ep in ['/sys/firmware/efi/systab', '/proc/efi/systab']:
4973 if not os.path.exists(ep) or not os.access(ep, os.R_OK):
4978 i = buf.find('SMBIOS=')
4981 memaddr = int(buf[i+7:], 16)
4986 # read in the memory for scanning
4987 fp = open(mempath, 'rb')
4990 buf = fp.read(memsize)
4993 doError('DMI table is unreachable, sorry')
4998 # search for either an SM table or DMI table
4999 i = base = length = num = 0
5001 if buf[i:i+4] == '_SM_' and i < memsize - 16:
5002 length = struct.unpack('H', buf[i+22:i+24])[0]
5003 base, num = struct.unpack('IH', buf[i+24:i+30])
5005 elif buf[i:i+5] == '_DMI_':
5006 length = struct.unpack('H', buf[i+6:i+8])[0]
5007 base, num = struct.unpack('IH', buf[i+8:i+14])
5010 if base == 0 and length == 0 and num == 0:
5012 doError('Neither SMBIOS nor DMI were found')
5016 # read in the SM or DMI table
5017 fp = open(mempath, 'rb')
5020 buf = fp.read(length)
5023 doError('DMI table is unreachable, sorry')
5028 # scan the table for the values we want
5030 while(count < num and i <= len(buf) - 4):
5031 type, size, handle = struct.unpack('BBH', buf[i:i+4])
5033 while n < len(buf) - 1:
5034 if 0 == struct.unpack('H', buf[n:n+2])[0]:
5037 data = buf[i+size:n+2].split('\0')
5039 itype, idxadr = info[name]
5041 idx = struct.unpack('B', buf[i+idxadr])[0]
5042 if idx > 0 and idx < len(data) - 1:
5043 s = data[idx-1].strip()
5044 if s and s.lower() != 'to be filled by o.e.m.':
5045 out[name] = data[idx-1]
5051 p, charge, bat = '/sys/class/power_supply', 0, {}
5052 if not os.path.exists(p):
5054 for d in os.listdir(p):
5055 type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower()
5056 if type != 'battery':
5058 for v in ['status', 'energy_now', 'capacity_now']:
5059 bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower()
5061 if 'status' not in bat:
5063 ac = False if 'discharging' in bat['status'] else True
5064 for v in ['energy_now', 'capacity_now']:
5065 if v in bat and bat[v]:
5066 charge = int(bat[v])
5069 def displayControl(cmd):
5070 xset, ret = 'xset -d :0.0 {0}', 0
5071 if sysvals.sudouser:
5072 xset = 'sudo -u %s %s' % (sysvals.sudouser, xset)
5074 ret = call(xset.format('dpms 0 0 0'), shell=True)
5076 ret = call(xset.format('s off'), shell=True)
5077 elif cmd == 'reset':
5078 ret = call(xset.format('s reset'), shell=True)
5079 elif cmd in ['on', 'off', 'standby', 'suspend']:
5080 b4 = displayControl('stat')
5081 ret = call(xset.format('dpms force %s' % cmd), shell=True)
5083 curr = displayControl('stat')
5084 sysvals.vprint('Display Switched: %s -> %s' % (b4, curr))
5086 sysvals.vprint('WARNING: Display failed to change to %s' % cmd)
5088 sysvals.vprint('WARNING: Display failed to change to %s with xset' % cmd)
5091 fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout
5094 m = re.match('[\s]*Monitor is (?P<m>.*)', line)
5095 if(m and len(m.group('m')) >= 2):
5096 out = m.group('m').lower()
5097 ret = out[3:] if out[0:2] == 'in' else out
5104 # Read the acpi bios tables and pull out FPDT, the firmware data
5106 # output: True to output the info to stdout, False otherwise
5107 def getFPDT(output):
5109 rectype[0] = 'Firmware Basic Boot Performance Record'
5110 rectype[1] = 'S3 Performance Table Record'
5112 prectype[0] = 'Basic S3 Resume Performance Record'
5113 prectype[1] = 'Basic S3 Suspend Performance Record'
5115 sysvals.rootCheck(True)
5116 if(not os.path.exists(sysvals.fpdtpath)):
5118 doError('file does not exist: %s' % sysvals.fpdtpath)
5120 if(not os.access(sysvals.fpdtpath, os.R_OK)):
5122 doError('file is not readable: %s' % sysvals.fpdtpath)
5124 if(not os.path.exists(sysvals.mempath)):
5126 doError('file does not exist: %s' % sysvals.mempath)
5128 if(not os.access(sysvals.mempath, os.R_OK)):
5130 doError('file is not readable: %s' % sysvals.mempath)
5133 fp = open(sysvals.fpdtpath, 'rb')
5139 doError('Invalid FPDT table data, should '+\
5140 'be at least 36 bytes')
5143 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
5146 'Firmware Performance Data Table (%s)\n'\
5147 ' Signature : %s\n'\
5148 ' Table Length : %u\n'\
5150 ' Checksum : 0x%x\n'\
5152 ' OEM Table ID : %s\n'\
5153 ' OEM Revision : %u\n'\
5154 ' Creator ID : %s\n'\
5155 ' Creator Revision : 0x%x\n'\
5156 '' % (table[0], table[0], table[1], table[2], table[3],
5157 table[4], table[5], table[6], table[7], table[8]))
5159 if(table[0] != 'FPDT'):
5161 doError('Invalid FPDT table')
5168 fp = open(sysvals.mempath, 'rb')
5169 while(i < len(records)):
5170 header = struct.unpack('HBB', records[i:i+4])
5171 if(header[0] not in rectype):
5174 if(header[1] != 16):
5177 addr = struct.unpack('Q', records[i+8:i+16])[0]
5183 pprint('Bad address 0x%x in %s' % (addr, sysvals.mempath))
5185 rechead = struct.unpack('4sI', first)
5186 recdata = fp.read(rechead[1]-8)
5187 if(rechead[0] == 'FBPT'):
5188 record = struct.unpack('HBBIQQQQQ', recdata)
5191 ' Reset END : %u ns\n'\
5192 ' OS Loader LoadImage Start : %u ns\n'\
5193 ' OS Loader StartImage Start : %u ns\n'\
5194 ' ExitBootServices Entry : %u ns\n'\
5195 ' ExitBootServices Exit : %u ns'\
5196 '' % (rectype[header[0]], rechead[0], record[4], record[5],
5197 record[6], record[7], record[8]))
5198 elif(rechead[0] == 'S3PT'):
5200 pprint('%s (%s)' % (rectype[header[0]], rechead[0]))
5202 while(j < len(recdata)):
5203 prechead = struct.unpack('HBB', recdata[j:j+4])
5204 if(prechead[0] not in prectype):
5206 if(prechead[0] == 0):
5207 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
5208 fwData[1] = record[2]
5211 ' Resume Count : %u\n'\
5212 ' FullResume : %u ns\n'\
5213 ' AverageResume : %u ns'\
5214 '' % (prectype[prechead[0]], record[1],
5215 record[2], record[3]))
5216 elif(prechead[0] == 1):
5217 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
5218 fwData[0] = record[1] - record[0]
5221 ' SuspendStart : %u ns\n'\
5222 ' SuspendEnd : %u ns\n'\
5223 ' SuspendTime : %u ns'\
5224 '' % (prectype[prechead[0]], record[0],
5225 record[1], fwData[0]))
5234 # Function: statusCheck
5236 # Verify that the requested command and options will work, and
5237 # print the results to the terminal
5239 # True if the test will work, False if not
5240 def statusCheck(probecheck=False):
5243 pprint('Checking this system (%s)...' % platform.node())
5245 # check we have root access
5246 res = sysvals.colorText('NO (No features of this tool will work!)')
5247 if(sysvals.rootCheck(False)):
5249 pprint(' have root access: %s' % res)
5251 pprint(' Try running this script with sudo')
5252 return 'missing root access'
5254 # check sysfs is mounted
5255 res = sysvals.colorText('NO (No features of this tool will work!)')
5256 if(os.path.exists(sysvals.powerfile)):
5258 pprint(' is sysfs mounted: %s' % res)
5260 return 'sysfs is missing'
5262 # check target mode is a valid mode
5263 if sysvals.suspendmode != 'command':
5264 res = sysvals.colorText('NO')
5266 if(sysvals.suspendmode in modes):
5269 status = '%s mode is not supported' % sysvals.suspendmode
5270 pprint(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
5272 pprint(' valid power modes are: %s' % modes)
5273 pprint(' please choose one with -m')
5275 # check if ftrace is available
5276 res = sysvals.colorText('NO')
5277 ftgood = sysvals.verifyFtrace()
5280 elif(sysvals.usecallgraph):
5281 status = 'ftrace is not properly supported'
5282 pprint(' is ftrace supported: %s' % res)
5284 # check if kprobes are available
5285 res = sysvals.colorText('NO')
5286 sysvals.usekprobes = sysvals.verifyKprobes()
5287 if(sysvals.usekprobes):
5290 sysvals.usedevsrc = False
5291 pprint(' are kprobes supported: %s' % res)
5293 # what data source are we using
5296 sysvals.usetraceevents = True
5297 for e in sysvals.traceevents:
5298 if not os.path.exists(sysvals.epath+e):
5299 sysvals.usetraceevents = False
5300 if(sysvals.usetraceevents):
5301 res = 'FTRACE (all trace events found)'
5302 pprint(' timeline data source: %s' % res)
5305 res = sysvals.colorText('NO')
5306 if(sysvals.rtcpath != ''):
5308 elif(sysvals.rtcwake):
5309 status = 'rtcwake is not properly supported'
5310 pprint(' is rtcwake supported: %s' % res)
5316 if sysvals.usekprobes:
5317 for name in sysvals.tracefuncs:
5318 sysvals.defaultKprobe(name, sysvals.tracefuncs[name])
5319 if sysvals.usedevsrc:
5320 for name in sysvals.dev_tracefuncs:
5321 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])
5322 sysvals.addKprobes(True)
5328 # generic error function for catastrphic failures
5330 # msg: the error message to print
5331 # help: True if printHelp should be called after, False otherwise
5332 def doError(msg, help=False):
5335 pprint('ERROR: %s\n' % msg)
5336 sysvals.outputResult({'error':msg})
5339 # Function: getArgInt
5341 # pull out an integer argument from the command line with checks
5342 def getArgInt(name, args, min, max, main=True):
5347 doError(name+': no argument supplied', True)
5353 doError(name+': non-integer value given', True)
5354 if(val < min or val > max):
5355 doError(name+': value should be between %d and %d' % (min, max), True)
5358 # Function: getArgFloat
5360 # pull out a float argument from the command line with checks
5361 def getArgFloat(name, args, min, max, main=True):
5366 doError(name+': no argument supplied', True)
5372 doError(name+': non-numerical value given', True)
5373 if(val < min or val > max):
5374 doError(name+': value should be between %f and %f' % (min, max), True)
5377 def processData(live=False):
5378 pprint('PROCESSING DATA')
5380 if(sysvals.usetraceevents):
5381 testruns, error = parseTraceLog(live)
5382 if sysvals.dmesgfile:
5383 for data in testruns:
5384 data.extractErrorInfo()
5386 testruns = loadKernelLog()
5387 for data in testruns:
5388 parseKernelLog(data)
5389 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
5390 appendIncompleteTraceLog(testruns)
5391 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
5392 for data in testruns:
5394 a1, c1, a2, c2 = data.battery
5395 s = 'Battery:\n Before - AC: %s, Charge: %d\n After - AC: %s, Charge: %d' % \
5396 (a1, int(c1), a2, int(c2))
5400 for data in testruns:
5403 if len(testruns) < 1:
5404 pprint('ERROR: Not enough test data to build a timeline')
5405 return (testruns, {'error': 'timeline generation failed'})
5406 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
5407 createHTML(testruns, error)
5411 stamp['suspend'], stamp['resume'] = data.getTimeValues()
5413 stamp['fwsuspend'], stamp['fwresume'] = data.fwSuspend, data.fwResume
5415 stamp['error'] = error
5416 return (testruns, stamp)
5418 # Function: rerunTest
5420 # generate an output from an existing set of ftrace/dmesg logs
5422 if sysvals.ftracefile:
5423 doesTraceLogHaveTraceEvents()
5424 if not sysvals.dmesgfile and not sysvals.usetraceevents:
5425 doError('recreating this html output requires a dmesg file')
5426 sysvals.setOutputFile()
5427 if os.path.exists(sysvals.htmlfile):
5428 if not os.path.isfile(sysvals.htmlfile):
5429 doError('a directory already exists with this name: %s' % sysvals.htmlfile)
5430 elif not os.access(sysvals.htmlfile, os.W_OK):
5431 doError('missing permission to write to %s' % sysvals.htmlfile)
5432 testruns, stamp = processData(False)
5438 # execute a suspend/resume, gather the logs, and generate the output
5440 # prepare for the test
5441 sysvals.initFtrace()
5442 sysvals.initTestOutput('suspend')
5446 sysvals.cleanupFtrace()
5447 if sysvals.skiphtml:
5448 sysvals.sudoUserchown(sysvals.testdir)
5450 testruns, stamp = processData(True)
5451 for data in testruns:
5453 sysvals.sudoUserchown(sysvals.testdir)
5454 sysvals.outputResult(stamp, n)
5455 if 'error' in stamp:
5459 def find_in_html(html, start, end, firstonly=True):
5461 while n < len(html):
5462 m = re.search(start, html[n:])
5466 m = re.search(end, html[n+i:])
5470 str = html[n+i:n+i+j]
5472 num = re.search(r'[-+]?\d*\.\d+|\d+', str)
5473 str = num.group() if num else 'NaN'
5482 def data_from_html(file, outpath, devlist=False):
5483 html = open(file, 'r').read()
5484 suspend = find_in_html(html, 'Kernel Suspend', 'ms')
5485 resume = find_in_html(html, 'Kernel Resume', 'ms')
5486 line = find_in_html(html, '<div class="stamp">', '</div>')
5488 if not suspend or not resume or len(stmp) != 8:
5491 dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
5494 tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
5495 error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
5497 m = re.match('[a-z]* failed in (?P<p>[a-z0-9_]*) phase', error)
5499 result = 'fail in %s' % m.group('p')
5505 e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '→</div>', False)
5506 for i in list(set(e)):
5507 ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
5508 low = find_in_html(html, 'freeze time: <b>', ' ms</b>')
5509 if low and '|' in low:
5510 ilist.append('FREEZEx%d' % len(low.split('|')))
5512 for line in html.split('\n'):
5513 m = re.match(' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line)
5514 if not m or 'thread kth' in line or 'thread sec' in line:
5516 m = re.match('(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title'))
5519 name, time, phase = m.group('n'), m.group('t'), m.group('p')
5520 if ' async' in name or ' sync' in name:
5521 name = ' '.join(name.split(' ')[:-1])
5522 d = phase.split('_')[0]
5523 if d not in devices:
5525 if name not in devices[d]:
5526 devices[d][name] = 0.0
5527 devices[d][name] += float(time)
5528 worst = {'suspend': {'name':'', 'time': 0.0},
5529 'resume': {'name':'', 'time': 0.0}}
5534 if len(dev.keys()) > 0:
5535 n = sorted(dev, key=dev.get, reverse=True)[0]
5536 worst[d]['name'], worst[d]['time'] = n, dev[n]
5543 'issues': ' '.join(ilist),
5546 'sus_worst': worst['suspend']['name'],
5547 'sus_worsttime': worst['suspend']['time'],
5548 'res_worst': worst['resume']['name'],
5549 'res_worsttime': worst['resume']['time'],
5550 'url': os.path.relpath(file, outpath),
5553 data['devlist'] = devices
5556 # Function: runSummary
5558 # create a summary of tests in a sub-directory
5559 def runSummary(subdir, local=True, genhtml=False):
5560 inpath = os.path.abspath(subdir)
5561 outpath = os.path.abspath('.') if local else inpath
5562 pprint('Generating a summary of folder "%s"' % inpath)
5564 for dirname, dirnames, filenames in os.walk(subdir):
5565 sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
5566 for filename in filenames:
5567 if(re.match('.*_dmesg.txt', filename)):
5568 sysvals.dmesgfile = os.path.join(dirname, filename)
5569 elif(re.match('.*_ftrace.txt', filename)):
5570 sysvals.ftracefile = os.path.join(dirname, filename)
5571 sysvals.setOutputFile()
5572 if sysvals.ftracefile and sysvals.htmlfile and \
5573 not os.path.exists(sysvals.htmlfile):
5574 pprint('FTRACE: %s' % sysvals.ftracefile)
5575 if sysvals.dmesgfile:
5576 pprint('DMESG : %s' % sysvals.dmesgfile)
5579 desc = {'host':[],'mode':[],'kernel':[]}
5580 for dirname, dirnames, filenames in os.walk(subdir):
5581 for filename in filenames:
5582 if(not re.match('.*.html', filename)):
5584 data = data_from_html(os.path.join(dirname, filename), outpath)
5587 testruns.append(data)
5589 if data[key] not in desc[key]:
5590 desc[key].append(data[key])
5591 outfile = os.path.join(outpath, 'summary.html')
5592 pprint('Summary file: %s' % outfile)
5593 if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1:
5594 title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0])
5597 createHTMLSummarySimple(testruns, outfile, title)
5599 # Function: checkArgBool
5601 # check if a boolean string value is true or false
5602 def checkArgBool(name, value):
5603 if value in switchvalues:
5604 if value in switchoff:
5607 doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True)
5610 # Function: configFromFile
5612 # Configure the script via the info in a config file
5613 def configFromFile(file):
5614 Config = ConfigParser.ConfigParser()
5617 sections = Config.sections()
5618 overridekprobes = False
5619 overridedevkprobes = False
5620 if 'Settings' in sections:
5621 for opt in Config.options('Settings'):
5622 value = Config.get('Settings', opt).lower()
5623 option = opt.lower()
5624 if(option == 'verbose'):
5625 sysvals.verbose = checkArgBool(option, value)
5626 elif(option == 'addlogs'):
5627 sysvals.dmesglog = sysvals.ftracelog = checkArgBool(option, value)
5628 elif(option == 'dev'):
5629 sysvals.usedevsrc = checkArgBool(option, value)
5630 elif(option == 'proc'):
5631 sysvals.useprocmon = checkArgBool(option, value)
5632 elif(option == 'x2'):
5633 if checkArgBool(option, value):
5634 sysvals.execcount = 2
5635 elif(option == 'callgraph'):
5636 sysvals.usecallgraph = checkArgBool(option, value)
5637 elif(option == 'override-timeline-functions'):
5638 overridekprobes = checkArgBool(option, value)
5639 elif(option == 'override-dev-timeline-functions'):
5640 overridedevkprobes = checkArgBool(option, value)
5641 elif(option == 'skiphtml'):
5642 sysvals.skiphtml = checkArgBool(option, value)
5643 elif(option == 'sync'):
5644 sysvals.sync = checkArgBool(option, value)
5645 elif(option == 'rs' or option == 'runtimesuspend'):
5646 if value in switchvalues:
5647 if value in switchoff:
5652 doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)
5653 elif(option == 'display'):
5654 disopt = ['on', 'off', 'standby', 'suspend']
5655 if value not in disopt:
5656 doError('invalid value --> (%s: %s), use %s' % (option, value, disopt), True)
5657 sysvals.display = value
5658 elif(option == 'gzip'):
5659 sysvals.gzip = checkArgBool(option, value)
5660 elif(option == 'cgfilter'):
5661 sysvals.setCallgraphFilter(value)
5662 elif(option == 'cgskip'):
5663 if value in switchoff:
5666 sysvals.cgskip = sysvals.configFile(val)
5667 if(not sysvals.cgskip):
5668 doError('%s does not exist' % sysvals.cgskip)
5669 elif(option == 'cgtest'):
5670 sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)
5671 elif(option == 'cgphase'):
5673 if value not in d.sortedPhases():
5674 doError('invalid phase --> (%s: %s), valid phases are %s'\
5675 % (option, value, d.sortedPhases()), True)
5676 sysvals.cgphase = value
5677 elif(option == 'fadd'):
5678 file = sysvals.configFile(value)
5680 doError('%s does not exist' % value)
5681 sysvals.addFtraceFilterFunctions(file)
5682 elif(option == 'result'):
5683 sysvals.result = value
5684 elif(option == 'multi'):
5685 nums = value.split()
5687 doError('multi requires 2 integers (exec_count and delay)', True)
5688 sysvals.multitest['run'] = True
5689 sysvals.multitest['count'] = getArgInt('multi: n d (exec count)', nums[0], 2, 1000000, False)
5690 sysvals.multitest['delay'] = getArgInt('multi: n d (delay between tests)', nums[1], 0, 3600, False)
5691 elif(option == 'devicefilter'):
5692 sysvals.setDeviceFilter(value)
5693 elif(option == 'expandcg'):
5694 sysvals.cgexp = checkArgBool(option, value)
5695 elif(option == 'srgap'):
5696 if checkArgBool(option, value):
5698 elif(option == 'mode'):
5699 sysvals.suspendmode = value
5700 elif(option == 'command' or option == 'cmd'):
5701 sysvals.testcommand = value
5702 elif(option == 'x2delay'):
5703 sysvals.x2delay = getArgInt('x2delay', value, 0, 60000, False)
5704 elif(option == 'predelay'):
5705 sysvals.predelay = getArgInt('predelay', value, 0, 60000, False)
5706 elif(option == 'postdelay'):
5707 sysvals.postdelay = getArgInt('postdelay', value, 0, 60000, False)
5708 elif(option == 'maxdepth'):
5709 sysvals.max_graph_depth = getArgInt('maxdepth', value, 0, 1000, False)
5710 elif(option == 'rtcwake'):
5711 if value in switchoff:
5712 sysvals.rtcwake = False
5714 sysvals.rtcwake = True
5715 sysvals.rtcwaketime = getArgInt('rtcwake', value, 0, 3600, False)
5716 elif(option == 'timeprec'):
5717 sysvals.setPrecision(getArgInt('timeprec', value, 0, 6, False))
5718 elif(option == 'mindev'):
5719 sysvals.mindevlen = getArgFloat('mindev', value, 0.0, 10000.0, False)
5720 elif(option == 'callloop-maxgap'):
5721 sysvals.callloopmaxgap = getArgFloat('callloop-maxgap', value, 0.0, 1.0, False)
5722 elif(option == 'callloop-maxlen'):
5723 sysvals.callloopmaxgap = getArgFloat('callloop-maxlen', value, 0.0, 1.0, False)
5724 elif(option == 'mincg'):
5725 sysvals.mincglen = getArgFloat('mincg', value, 0.0, 10000.0, False)
5726 elif(option == 'bufsize'):
5727 sysvals.bufsize = getArgInt('bufsize', value, 1, 1024*1024*8, False)
5728 elif(option == 'output-dir'):
5729 sysvals.outdir = sysvals.setOutputFolder(value)
5731 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
5732 doError('No command supplied for mode "command"')
5734 # compatibility errors
5735 if sysvals.usedevsrc and sysvals.usecallgraph:
5736 doError('-dev is not compatible with -f')
5737 if sysvals.usecallgraph and sysvals.useprocmon:
5738 doError('-proc is not compatible with -f')
5741 sysvals.tracefuncs = dict()
5742 if overridedevkprobes:
5743 sysvals.dev_tracefuncs = dict()
5746 kprobesec = 'dev_timeline_functions_'+platform.machine()
5747 if kprobesec in sections:
5748 for name in Config.options(kprobesec):
5749 text = Config.get(kprobesec, name)
5750 kprobes[name] = (text, True)
5751 kprobesec = 'timeline_functions_'+platform.machine()
5752 if kprobesec in sections:
5753 for name in Config.options(kprobesec):
5755 doError('Duplicate timeline function found "%s"' % (name))
5756 text = Config.get(kprobesec, name)
5757 kprobes[name] = (text, False)
5759 for name in kprobes:
5764 text, dev = kprobes[name]
5768 # bracketted strings are special formatting, read them separately
5769 if val[0] == '[' and val[-1] == ']':
5770 for prop in val[1:-1].split(','):
5774 color = int(p[1], 16)
5779 # first real arg should be the format string
5782 # all other args are actual function args
5787 if not function or not format:
5788 doError('Invalid kprobe: %s' % name)
5789 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
5791 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
5792 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
5793 doError('Duplicate timeline function found "%s"' % (name))
5799 sysvals.archargs: args
5804 sysvals.dev_tracefuncs[name] = kp
5806 sysvals.tracefuncs[name] = kp
5808 # Function: printHelp
5810 # print out the help text
5812 pprint('\n%s v%s\n'\
5813 'Usage: sudo sleepgraph <options> <commands>\n'\
5816 ' This tool is designed to assist kernel and OS developers in optimizing\n'\
5817 ' their linux stack\'s suspend/resume time. Using a kernel image built\n'\
5818 ' with a few extra options enabled, the tool will execute a suspend and\n'\
5819 ' capture dmesg and ftrace data until resume is complete. This data is\n'\
5820 ' transformed into a device timeline and an optional callgraph to give\n'\
5821 ' a detailed view of which devices/subsystems are taking the most\n'\
5822 ' time in suspend/resume.\n'\
5824 ' If no specific command is given, the default behavior is to initiate\n'\
5825 ' a suspend/resume and capture the dmesg/ftrace output as an html timeline.\n'\
5827 ' Generates output files in subdirectory: suspend-yymmdd-HHMMSS\n'\
5828 ' HTML output: <hostname>_<mode>.html\n'\
5829 ' raw dmesg output: <hostname>_<mode>_dmesg.txt\n'\
5830 ' raw ftrace output: <hostname>_<mode>_ftrace.txt\n'\
5833 ' -h Print this help text\n'\
5834 ' -v Print the current tool version\n'\
5835 ' -config fn Pull arguments and config options from file fn\n'\
5836 ' -verbose Print extra information during execution and analysis\n'\
5837 ' -m mode Mode to initiate for suspend (default: %s)\n'\
5838 ' -o name Overrides the output subdirectory name when running a new test\n'\
5839 ' default: suspend-{date}-{time}\n'\
5840 ' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)\n'\
5841 ' -addlogs Add the dmesg and ftrace logs to the html output\n'\
5842 ' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\
5843 ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\
5844 ' -result fn Export a results table to a text file for parsing.\n'\
5846 ' -sync Sync the filesystems before starting the test\n'\
5847 ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\
5848 ' -display m Change the display mode to m for the test (on/off/standby/suspend)\n'\
5850 ' -gzip Gzip the trace and dmesg logs to save space\n'\
5851 ' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"\n'\
5852 ' -proc Add usermode process info into the timeline (default: disabled)\n'\
5853 ' -dev Add kernel function calls and threads to the timeline (default: disabled)\n'\
5854 ' -x2 Run two suspend/resumes back to back (default: disabled)\n'\
5855 ' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)\n'\
5856 ' -predelay t Include t ms delay before 1st suspend (default: 0 ms)\n'\
5857 ' -postdelay t Include t ms delay after last resume (default: 0 ms)\n'\
5858 ' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)\n'\
5859 ' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will\n'\
5860 ' be created in a new subdirectory with a summary page.\n'\
5862 ' -f Use ftrace to create device callgraphs (default: disabled)\n'\
5863 ' -maxdepth N limit the callgraph data to N call levels (default: 0=all)\n'\
5864 ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\
5865 ' -fadd file Add functions to be graphed in the timeline from a list in a text file\n'\
5866 ' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names\n'\
5867 ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\
5868 ' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)\n'\
5869 ' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)\n'\
5870 ' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)\n'\
5871 ' -cgfilter S Filter the callgraph output in the timeline\n'\
5872 ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\
5873 ' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)\n'\
5874 ' -devdump Print out all the raw device data for each phase\n'\
5875 ' -cgdump Print out all the raw callgraph data\n'\
5877 'Other commands:\n'\
5878 ' -modes List available suspend modes\n'\
5879 ' -status Test to see if the system is enabled to run this tool\n'\
5880 ' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\
5881 ' -battery Print out battery info (if available)\n'\
5882 ' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\
5883 ' -sysinfo Print out system info extracted from BIOS\n'\
5884 ' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\
5885 ' -flist Print the list of functions currently being captured in ftrace\n'\
5886 ' -flistall Print all functions capable of being captured in ftrace\n'\
5887 ' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]\n'\
5889 ' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)\n'\
5890 ' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)\n'\
5891 '' % (sysvals.title, sysvals.version, sysvals.suspendmode))
5894 # ----------------- MAIN --------------------
5895 # exec start (skipped if script is loaded as library)
5896 if __name__ == '__main__':
5899 simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall',
5900 '-devinfo', '-status', '-battery', '-xon', '-xoff', '-xstandby',
5901 '-xsuspend', '-xinit', '-xreset', '-xstat']
5902 if '-f' in sys.argv:
5903 sysvals.cgskip = sysvals.configFile('cgskip.txt')
5904 # loop through the command line arguments
5905 args = iter(sys.argv[1:])
5911 doError('No mode supplied', True)
5912 if val == 'command' and not sysvals.testcommand:
5913 doError('No command supplied for mode "command"', True)
5914 sysvals.suspendmode = val
5915 elif(arg in simplecmds):
5921 pprint("Version %s" % sysvals.version)
5924 sysvals.execcount = 2
5925 elif(arg == '-x2delay'):
5926 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
5927 elif(arg == '-predelay'):
5928 sysvals.predelay = getArgInt('-predelay', args, 0, 60000)
5929 elif(arg == '-postdelay'):
5930 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
5932 sysvals.usecallgraph = True
5933 elif(arg == '-skiphtml'):
5934 sysvals.skiphtml = True
5935 elif(arg == '-cgdump'):
5936 sysvals.cgdump = True
5937 elif(arg == '-devdump'):
5938 sysvals.devdump = True
5939 elif(arg == '-genhtml'):
5941 elif(arg == '-addlogs'):
5942 sysvals.dmesglog = sysvals.ftracelog = True
5943 elif(arg == '-addlogdmesg'):
5944 sysvals.dmesglog = True
5945 elif(arg == '-addlogftrace'):
5946 sysvals.ftracelog = True
5947 elif(arg == '-verbose'):
5948 sysvals.verbose = True
5949 elif(arg == '-proc'):
5950 sysvals.useprocmon = True
5951 elif(arg == '-dev'):
5952 sysvals.usedevsrc = True
5953 elif(arg == '-sync'):
5955 elif(arg == '-gzip'):
5961 doError('-rs requires "enable" or "disable"', True)
5962 if val.lower() in switchvalues:
5963 if val.lower() in switchoff:
5968 doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True)
5969 elif(arg == '-display'):
5973 doError('-display requires an mode value', True)
5974 disopt = ['on', 'off', 'standby', 'suspend']
5975 if val.lower() not in disopt:
5976 doError('valid display mode values are %s' % disopt, True)
5977 sysvals.display = val.lower()
5978 elif(arg == '-maxdepth'):
5979 sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
5980 elif(arg == '-rtcwake'):
5984 doError('No rtcwake time supplied', True)
5985 if val.lower() in switchoff:
5986 sysvals.rtcwake = False
5988 sysvals.rtcwake = True
5989 sysvals.rtcwaketime = getArgInt('-rtcwake', val, 0, 3600, False)
5990 elif(arg == '-timeprec'):
5991 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
5992 elif(arg == '-mindev'):
5993 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
5994 elif(arg == '-mincg'):
5995 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
5996 elif(arg == '-bufsize'):
5997 sysvals.bufsize = getArgInt('-bufsize', args, 1, 1024*1024*8)
5998 elif(arg == '-cgtest'):
5999 sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
6000 elif(arg == '-cgphase'):
6004 doError('No phase name supplied', True)
6006 if val not in d.phasedef:
6007 doError('invalid phase --> (%s: %s), valid phases are %s'\
6008 % (arg, val, d.phasedef.keys()), True)
6009 sysvals.cgphase = val
6010 elif(arg == '-cgfilter'):
6014 doError('No callgraph functions supplied', True)
6015 sysvals.setCallgraphFilter(val)
6016 elif(arg == '-cgskip'):
6020 doError('No file supplied', True)
6021 if val.lower() in switchoff:
6024 sysvals.cgskip = sysvals.configFile(val)
6025 if(not sysvals.cgskip):
6026 doError('%s does not exist' % sysvals.cgskip)
6027 elif(arg == '-callloop-maxgap'):
6028 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
6029 elif(arg == '-callloop-maxlen'):
6030 sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)
6031 elif(arg == '-cmd'):
6035 doError('No command string supplied', True)
6036 sysvals.testcommand = val
6037 sysvals.suspendmode = 'command'
6038 elif(arg == '-expandcg'):
6039 sysvals.cgexp = True
6040 elif(arg == '-srgap'):
6042 elif(arg == '-multi'):
6043 sysvals.multitest['run'] = True
6044 sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000)
6045 sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600)
6050 doError('No subdirectory name supplied', True)
6051 sysvals.outdir = sysvals.setOutputFolder(val)
6052 elif(arg == '-config'):
6056 doError('No text file supplied', True)
6057 file = sysvals.configFile(val)
6059 doError('%s does not exist' % val)
6060 configFromFile(file)
6061 elif(arg == '-fadd'):
6065 doError('No text file supplied', True)
6066 file = sysvals.configFile(val)
6068 doError('%s does not exist' % val)
6069 sysvals.addFtraceFilterFunctions(file)
6070 elif(arg == '-dmesg'):
6074 doError('No dmesg file supplied', True)
6075 sysvals.notestrun = True
6076 sysvals.dmesgfile = val
6077 if(os.path.exists(sysvals.dmesgfile) == False):
6078 doError('%s does not exist' % sysvals.dmesgfile)
6079 elif(arg == '-ftrace'):
6083 doError('No ftrace file supplied', True)
6084 sysvals.notestrun = True
6085 sysvals.ftracefile = val
6086 if(os.path.exists(sysvals.ftracefile) == False):
6087 doError('%s does not exist' % sysvals.ftracefile)
6088 elif(arg == '-summary'):
6092 doError('No directory supplied', True)
6094 sysvals.outdir = val
6095 sysvals.notestrun = True
6096 if(os.path.isdir(val) == False):
6097 doError('%s is not accesible' % val)
6098 elif(arg == '-filter'):
6102 doError('No devnames supplied', True)
6103 sysvals.setDeviceFilter(val)
6104 elif(arg == '-result'):
6108 doError('No result file supplied', True)
6109 sysvals.result = val
6110 sysvals.signalHandlerInit()
6112 doError('Invalid argument: '+arg, True)
6114 # compatibility errors
6115 if(sysvals.usecallgraph and sysvals.usedevsrc):
6116 doError('-dev is not compatible with -f')
6117 if(sysvals.usecallgraph and sysvals.useprocmon):
6118 doError('-proc is not compatible with -f')
6120 if sysvals.usecallgraph and sysvals.cgskip:
6121 sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip)
6122 sysvals.setCallgraphBlacklist(sysvals.cgskip)
6124 # callgraph size cannot exceed device size
6125 if sysvals.mincglen < sysvals.mindevlen:
6126 sysvals.mincglen = sysvals.mindevlen
6128 # remove existing buffers before calculating memory
6129 if(sysvals.usecallgraph or sysvals.usedevsrc):
6130 sysvals.fsetVal('16', 'buffer_size_kb')
6133 # just run a utility command and exit
6136 if(cmd == 'status'):
6137 if not statusCheck(True):
6139 elif(cmd == 'fpdt'):
6140 if not getFPDT(True):
6142 elif(cmd == 'battery'):
6145 pprint('AC Connect : %s\nBattery Charge: %d' % out)
6147 pprint('no battery found')
6149 elif(cmd == 'sysinfo'):
6150 sysvals.printSystemInfo(True)
6151 elif(cmd == 'devinfo'):
6153 elif(cmd == 'modes'):
6155 elif(cmd == 'flist'):
6156 sysvals.getFtraceFilterFunctions(True)
6157 elif(cmd == 'flistall'):
6158 sysvals.getFtraceFilterFunctions(False)
6159 elif(cmd == 'summary'):
6160 runSummary(sysvals.outdir, True, genhtml)
6161 elif(cmd in ['xon', 'xoff', 'xstandby', 'xsuspend', 'xinit', 'xreset']):
6162 sysvals.verbose = True
6163 ret = displayControl(cmd[1:])
6164 elif(cmd == 'xstat'):
6165 pprint('Display Status: %s' % displayControl('stat').upper())
6168 # if instructed, re-analyze existing data files
6169 if(sysvals.notestrun):
6171 sysvals.outputResult(stamp)
6174 # verify that we can run a test
6175 error = statusCheck()
6179 # extract mem/disk extra modes and convert
6180 mode = sysvals.suspendmode
6181 if mode.startswith('mem'):
6182 memmode = mode.split('-', 1)[-1] if '-' in mode else 'deep'
6183 if memmode == 'shallow':
6185 elif memmode == 's2idle':
6189 sysvals.memmode = memmode
6190 sysvals.suspendmode = mode
6191 if mode.startswith('disk-'):
6192 sysvals.diskmode = mode.split('-', 1)[-1]
6193 sysvals.suspendmode = 'disk'
6195 sysvals.systemInfo(dmidecode(sysvals.mempath))
6197 setRuntimeSuspend(True)
6199 displayControl('init')
6201 if sysvals.multitest['run']:
6202 # run multiple tests in a separate subdirectory
6203 if not sysvals.outdir:
6204 s = 'suspend-x%d' % sysvals.multitest['count']
6205 sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
6206 if not os.path.isdir(sysvals.outdir):
6207 os.mkdir(sysvals.outdir)
6208 for i in range(sysvals.multitest['count']):
6210 pprint('Waiting %d seconds...' % (sysvals.multitest['delay']))
6211 time.sleep(sysvals.multitest['delay'])
6212 pprint('TEST (%d/%d) START' % (i+1, sysvals.multitest['count']))
6213 fmt = 'suspend-%y%m%d-%H%M%S'
6214 sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
6216 pprint('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
6218 if not sysvals.skiphtml:
6219 runSummary(sysvals.outdir, False, False)
6220 sysvals.sudoUserchown(sysvals.outdir)
6223 sysvals.testdir = sysvals.outdir
6224 # run the test in the current directory
6227 displayControl('reset')
6228 setRuntimeSuspend(False)