3 # Tool for analyzing suspend/resume timing
4 # Copyright (c) 2013, Intel Corporation.
6 # This program is free software; you can redistribute it and/or modify it
7 # under the terms and conditions of the GNU General Public License,
8 # version 2, as published by the Free Software Foundation.
10 # This program is distributed in the hope it will be useful, but WITHOUT
11 # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12 # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
16 # Todd Brandt <todd.e.brandt@linux.intel.com>
20 # https://01.org/suspendresume
22 # git@github.com:01org/pm-graph
25 # This tool is designed to assist kernel and OS developers in optimizing
26 # their linux stack's suspend/resume time. Using a kernel image built
27 # with a few extra options enabled, the tool will execute a suspend and
28 # will capture dmesg and ftrace data until resume is complete. This data
29 # is transformed into a device timeline and a callgraph to give a quick
30 # and detailed view of which devices and callbacks are taking the most
31 # time in suspend/resume. The output is a single html file which can be
32 # viewed in firefox or chrome.
34 # The following kernel build options are required:
36 # CONFIG_PM_SLEEP_DEBUG=y
38 # CONFIG_FUNCTION_TRACER=y
39 # CONFIG_FUNCTION_GRAPH_TRACER=y
41 # CONFIG_KPROBES_ON_FTRACE=y
43 # For kernel versions older than 3.15:
44 # The following additional kernel parameters are required:
45 # (e.g. in file /etc/default/grub)
46 # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
49 # ----------------- LIBRARIES --------------------
57 from datetime import datetime
61 from threading import Thread
62 from subprocess import call, Popen, PIPE
64 # ----------------- CLASSES --------------------
68 # A global, single-instance container used to
69 # store system values and test parameters
87 multitest = {'run': False, 'count': 0, 'delay': 0}
89 callloopmaxgap = 0.0001
90 callloopmaxlen = 0.005
99 tpath = '/sys/kernel/debug/tracing/'
100 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
101 epath = '/sys/kernel/debug/tracing/events/power/'
104 'device_pm_callback_end',
105 'device_pm_callback_start'
110 powerfile = '/sys/power/state'
111 mempowerfile = '/sys/power/mem_sleep'
114 hostname = 'localhost'
121 htmlfile = 'output.html'
133 usetraceevents = False
134 usetracemarkers = True
140 mixedphaseheight = True
144 procexecfmt = 'ps - (?P<ps>.*)$'
145 devpropfmt = '# Device Properties: .*'
146 tracertypefmt = '# tracer: (?P<t>.*)'
147 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
150 '__pm_notifier_call_chain': {},
151 'pm_prepare_console': {},
152 'pm_notifier_call_chain': {},
153 'freeze_processes': {},
154 'freeze_kernel_threads': {},
155 'pm_restrict_gfp_mask': {},
156 'acpi_suspend_begin': {},
157 'acpi_hibernation_begin': {},
158 'acpi_hibernation_enter': {},
159 'acpi_hibernation_leave': {},
160 'acpi_pm_freeze': {},
162 'hibernate_preallocate_memory': {},
163 'create_basic_memory_bitmaps': {},
165 'suspend_console': {},
166 'acpi_pm_prepare': {},
167 'syscore_suspend': {},
168 'arch_enable_nonboot_cpus_end': {},
169 'syscore_resume': {},
170 'acpi_pm_finish': {},
171 'resume_console': {},
173 'pm_restore_gfp_mask': {},
174 'thaw_processes': {},
175 'pm_restore_console': {},
178 'args_x86_64': {'cpu':'%di:s32'},
179 'format': 'CPU_OFF[{cpu}]'
183 'args_x86_64': {'cpu':'%di:s32'},
184 'format': 'CPU_ON[{cpu}]'
188 # general wait/delay/sleep
189 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
190 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
191 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
192 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
193 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
194 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
195 'acpi_os_stall': {'ub': 1},
197 'acpi_resume_power_resources': {},
198 'acpi_ps_parse_aml': {},
202 'iwlagn_mac_start': {},
203 'iwlagn_alloc_bcast_station': {},
204 'iwl_trans_pcie_start_hw': {},
205 'iwl_trans_pcie_start_fw': {},
206 'iwl_run_init_ucode': {},
207 'iwl_load_ucode_wait_alive': {},
208 'iwl_alive_start': {},
209 'iwlagn_mac_stop': {},
210 'iwlagn_mac_suspend': {},
211 'iwlagn_mac_resume': {},
212 'iwlagn_mac_add_interface': {},
213 'iwlagn_mac_remove_interface': {},
214 'iwlagn_mac_change_interface': {},
215 'iwlagn_mac_config': {},
216 'iwlagn_configure_filter': {},
217 'iwlagn_mac_hw_scan': {},
218 'iwlagn_bss_info_changed': {},
219 'iwlagn_mac_channel_switch': {},
220 'iwlagn_mac_flush': {},
222 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
224 'i915_gem_resume': {},
225 'i915_restore_state': {},
226 'intel_opregion_setup': {},
227 'g4x_pre_enable_dp': {},
228 'vlv_pre_enable_dp': {},
229 'chv_pre_enable_dp': {},
232 'intel_hpd_init': {},
233 'intel_opregion_register': {},
234 'intel_dp_detect': {},
235 'intel_hdmi_detect': {},
236 'intel_opregion_init': {},
237 'intel_fbdev_set_suspend': {},
242 cmdline = '%s %s' % \
243 (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
245 self.archargs = 'args_'+platform.machine()
246 self.hostname = platform.node()
247 if(self.hostname == ''):
248 self.hostname = 'localhost'
250 if os.path.exists('/dev/rtc'):
251 rtc = os.readlink('/dev/rtc')
252 rtc = '/sys/class/rtc/'+rtc
253 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
254 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
256 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
258 self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
259 def vprint(self, msg):
260 self.logmsg += msg+'\n'
263 def rootCheck(self, fatal=True):
264 if(os.access(self.powerfile, os.W_OK)):
267 msg = 'This command requires sysfs mount and root access'
268 print('ERROR: %s\n') % msg
269 self.outputResult({'error':msg})
272 def rootUser(self, fatal=False):
273 if 'USER' in os.environ and os.environ['USER'] == 'root':
276 msg = 'This command must be run as root'
277 print('ERROR: %s\n') % msg
278 self.outputResult({'error':msg})
281 def getExec(self, cmd):
282 dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
283 '/usr/local/sbin', '/usr/local/bin']
285 cmdfull = os.path.join(path, cmd)
286 if os.path.exists(cmdfull):
289 def setPrecision(self, num):
290 if num < 0 or num > 6:
292 self.timeformat = '%.{0}f'.format(num)
293 def setOutputFolder(self, value):
296 args['date'] = n.strftime('%y%m%d')
297 args['time'] = n.strftime('%H%M%S')
298 args['hostname'] = args['host'] = self.hostname
299 return value.format(**args)
300 def setOutputFile(self):
301 if self.dmesgfile != '':
302 m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)
304 self.htmlfile = m.group('name')+'.html'
305 if self.ftracefile != '':
306 m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
308 self.htmlfile = m.group('name')+'.html'
309 def systemInfo(self, info):
311 if 'baseboard-manufacturer' in info:
312 m = info['baseboard-manufacturer']
313 elif 'system-manufacturer' in info:
314 m = info['system-manufacturer']
315 if 'baseboard-product-name' in info:
316 p = info['baseboard-product-name']
317 elif 'system-product-name' in info:
318 p = info['system-product-name']
319 if 'processor-version' in info:
320 c = info['processor-version']
321 if 'bios-version' in info:
322 b = info['bios-version']
323 self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \
324 (m, p, c, b, self.cpucount, self.memtotal, self.memfree)
325 def printSystemInfo(self, fatal=False):
327 out = dmidecode(self.mempath, fatal)
331 for name in sorted(out):
332 print fmt % (name, out[name])
333 print fmt % ('cpucount', ('%d' % self.cpucount))
334 print fmt % ('memtotal', ('%d kB' % self.memtotal))
335 print fmt % ('memfree', ('%d kB' % self.memfree))
338 fp = open('/proc/cpuinfo', 'r')
340 if re.match('^processor[ \t]*:[ \t]*[0-9]*', line):
343 fp = open('/proc/meminfo', 'r')
345 m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
347 self.memtotal = int(m.group('sz'))
348 m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)
350 self.memfree = int(m.group('sz'))
352 def initTestOutput(self, name):
353 self.prefix = self.hostname
354 v = open('/proc/version', 'r').read().strip()
355 kver = string.split(v)[2]
356 fmt = name+'-%m%d%y-%H%M%S'
357 testtime = datetime.now().strftime(fmt)
359 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
364 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
366 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
368 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
369 if not os.path.isdir(self.testdir):
370 os.mkdir(self.testdir)
371 def getValueList(self, value):
373 for i in value.split(','):
375 out.append(i.strip())
377 def setDeviceFilter(self, value):
378 self.devicefilter = self.getValueList(value)
379 def setCallgraphFilter(self, value):
380 self.cgfilter = self.getValueList(value)
381 def setCallgraphBlacklist(self, file):
382 self.cgblacklist = self.listFromFile(file)
383 def rtcWakeAlarmOn(self):
384 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
385 nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()
387 nowtime = int(nowtime)
389 # if hardware time fails, use the software time
390 nowtime = int(datetime.now().strftime('%s'))
391 alarm = nowtime + self.rtcwaketime
392 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
393 def rtcWakeAlarmOff(self):
394 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
396 # get the latest time stamp from the dmesg log
397 fp = Popen('dmesg', stdout=PIPE).stdout
400 line = line.replace('\r\n', '')
404 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
406 ktime = m.group('ktime')
408 self.dmesgstart = float(ktime)
409 def getdmesg(self, fwdata=[]):
410 op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata)
411 # store all new dmesg lines since initdmesg was called
412 fp = Popen('dmesg', stdout=PIPE).stdout
414 line = line.replace('\r\n', '')
418 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
421 ktime = float(m.group('ktime'))
422 if ktime > self.dmesgstart:
426 def listFromFile(self, file):
429 for i in fp.read().split('\n'):
431 if i and i[0] != '#':
435 def addFtraceFilterFunctions(self, file):
436 for i in self.listFromFile(file):
439 self.tracefuncs[i] = dict()
440 def getFtraceFilterFunctions(self, current):
443 call('cat '+self.tpath+'available_filter_functions', shell=True)
445 master = self.listFromFile(self.tpath+'available_filter_functions')
446 for i in self.tracefuncs:
447 if 'func' in self.tracefuncs[i]:
448 i = self.tracefuncs[i]['func']
452 print self.colorText(i)
453 def setFtraceFilterFunctions(self, list):
454 master = self.listFromFile(self.tpath+'available_filter_functions')
460 flist += i.split(' ')[0]+'\n'
463 fp = open(self.tpath+'set_graph_function', 'w')
466 def basicKprobe(self, name):
467 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
468 def defaultKprobe(self, name, kdata):
470 for field in ['name', 'format', 'func']:
473 if self.archargs in k:
474 k['args'] = k[self.archargs]
478 self.kprobes[name] = k
479 def kprobeColor(self, name):
480 if name not in self.kprobes or 'color' not in self.kprobes[name]:
482 return self.kprobes[name]['color']
483 def kprobeDisplayName(self, name, dataraw):
484 if name not in self.kprobes:
485 self.basicKprobe(name)
488 # first remvoe any spaces inside quotes, and the quotes
491 quote = (quote + 1) % 2
492 if quote and c == ' ':
496 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
498 # now process the args
499 for arg in sorted(args):
501 m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
503 arglist[arg] = m.group('arg')
505 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
507 arglist[arg] = m.group('arg')
508 out = fmt.format(**arglist)
509 out = out.replace(' ', '_').replace('"', '')
511 def kprobeText(self, kname, kprobe):
512 name = fmt = func = kname
515 name = kprobe['name']
516 if 'format' in kprobe:
517 fmt = kprobe['format']
519 func = kprobe['func']
520 if self.archargs in kprobe:
521 args = kprobe[self.archargs]
523 args = kprobe['args']
524 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
525 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
526 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
528 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
529 val = 'p:%s_cal %s' % (name, func)
530 for i in sorted(args):
531 val += ' %s=%s' % (i, args[i])
532 val += '\nr:%s_ret %s $retval\n' % (name, func)
534 def addKprobes(self, output=False):
535 if len(self.kprobes) < 1:
538 print(' kprobe functions in this kernel:')
539 # first test each kprobe
541 # sort kprobes: trace, ub-dev, custom, dev
542 kpl = [[], [], [], []]
543 linesout = len(self.kprobes)
544 for name in sorted(self.kprobes):
545 res = self.colorText('YES', 32)
546 if not self.testKprobe(name, self.kprobes[name]):
547 res = self.colorText('NO')
550 if name in self.tracefuncs:
552 elif name in self.dev_tracefuncs:
553 if 'ub' in self.dev_tracefuncs[name]:
560 print(' %s: %s' % (name, res))
561 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
562 # remove all failed ones from the list
564 self.kprobes.pop(name)
565 # set the kprobes all at once
566 self.fsetVal('', 'kprobe_events')
569 kprobeevents += self.kprobeText(kp, self.kprobes[kp])
570 self.fsetVal(kprobeevents, 'kprobe_events')
572 check = self.fgetVal('kprobe_events')
573 linesack = (len(check.split('\n')) - 1) / 2
574 print(' kprobe functions enabled: %d/%d' % (linesack, linesout))
575 self.fsetVal('1', 'events/kprobes/enable')
576 def testKprobe(self, kname, kprobe):
577 self.fsetVal('0', 'events/kprobes/enable')
578 kprobeevents = self.kprobeText(kname, kprobe)
582 self.fsetVal(kprobeevents, 'kprobe_events')
583 check = self.fgetVal('kprobe_events')
586 linesout = len(kprobeevents.split('\n'))
587 linesack = len(check.split('\n'))
588 if linesack < linesout:
591 def setVal(self, val, file, mode='w'):
592 if not os.path.exists(file):
595 fp = open(file, mode, 0)
602 def fsetVal(self, val, path, mode='w'):
603 return self.setVal(val, self.tpath+path, mode)
604 def getVal(self, file):
606 if not os.path.exists(file):
615 def fgetVal(self, path):
616 return self.getVal(self.tpath+path)
617 def cleanupFtrace(self):
618 if(self.usecallgraph or self.usetraceevents or self.usedevsrc):
619 self.fsetVal('0', 'events/kprobes/enable')
620 self.fsetVal('', 'kprobe_events')
621 self.fsetVal('1024', 'buffer_size_kb')
622 def setupAllKprobes(self):
623 for name in self.tracefuncs:
624 self.defaultKprobe(name, self.tracefuncs[name])
625 for name in self.dev_tracefuncs:
626 self.defaultKprobe(name, self.dev_tracefuncs[name])
627 def isCallgraphFunc(self, name):
628 if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
630 for i in self.tracefuncs:
631 if 'func' in self.tracefuncs[i]:
632 f = self.tracefuncs[i]['func']
638 def initFtrace(self):
639 self.printSystemInfo(False)
640 print('INITIALIZING FTRACE...')
642 self.fsetVal('0', 'tracing_on')
644 # set the trace clock to global
645 self.fsetVal('global', 'trace_clock')
646 self.fsetVal('nop', 'current_tracer')
647 # set trace buffer to an appropriate value
648 cpus = max(1, self.cpucount)
650 tgtsize = self.bufsize
651 elif self.usecallgraph or self.usedevsrc:
652 tgtsize = min(self.memfree, 3*1024*1024)
655 while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
656 # if the size failed to set, lower it and keep trying
659 tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
661 print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)
662 # initialize the callgraph trace
663 if(self.usecallgraph):
665 self.fsetVal('function_graph', 'current_tracer')
666 self.fsetVal('', 'set_ftrace_filter')
667 # set trace format options
668 self.fsetVal('print-parent', 'trace_options')
669 self.fsetVal('funcgraph-abstime', 'trace_options')
670 self.fsetVal('funcgraph-cpu', 'trace_options')
671 self.fsetVal('funcgraph-duration', 'trace_options')
672 self.fsetVal('funcgraph-proc', 'trace_options')
673 self.fsetVal('funcgraph-tail', 'trace_options')
674 self.fsetVal('nofuncgraph-overhead', 'trace_options')
675 self.fsetVal('context-info', 'trace_options')
676 self.fsetVal('graph-time', 'trace_options')
677 self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
678 cf = ['dpm_run_callback']
679 if(self.usetraceevents):
680 cf += ['dpm_prepare', 'dpm_complete']
681 for fn in self.tracefuncs:
682 if 'func' in self.tracefuncs[fn]:
683 cf.append(self.tracefuncs[fn]['func'])
686 self.setFtraceFilterFunctions(cf)
687 # initialize the kprobe trace
688 elif self.usekprobes:
689 for name in self.tracefuncs:
690 self.defaultKprobe(name, self.tracefuncs[name])
692 for name in self.dev_tracefuncs:
693 self.defaultKprobe(name, self.dev_tracefuncs[name])
694 print('INITIALIZING KPROBES...')
695 self.addKprobes(self.verbose)
696 if(self.usetraceevents):
697 # turn trace events on
698 events = iter(self.traceevents)
700 self.fsetVal('1', 'events/power/'+e+'/enable')
701 # clear the trace buffer
702 self.fsetVal('', 'trace')
703 def verifyFtrace(self):
704 # files needed for any trace data
705 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
706 'trace_marker', 'trace_options', 'tracing_on']
707 # files needed for callgraph trace data
709 if(self.usecallgraph):
711 'available_filter_functions',
716 if(os.path.exists(tp+f) == False):
719 def verifyKprobes(self):
720 # files needed for kprobes to work
721 files = ['kprobe_events', 'events']
724 if(os.path.exists(tp+f) == False):
727 def colorText(self, str, color=31):
730 return '\x1B[%d;40m%s\x1B[m' % (color, str)
731 def writeDatafileHeader(self, filename, fwdata=[]):
732 fp = self.openlog(filename, 'w')
733 fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
734 if(self.suspendmode == 'mem' or self.suspendmode == 'command'):
737 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
739 def sudouser(self, dir):
740 if os.path.exists(dir) and os.getuid() == 0 and \
741 'SUDO_USER' in os.environ:
742 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
743 call(cmd.format(os.environ['SUDO_USER'], dir), shell=True)
744 def outputResult(self, testdata, num=0):
750 fp = open(self.result, 'a')
751 if 'error' in testdata:
752 fp.write('result%s: fail\n' % n)
753 fp.write('error%s: %s\n' % (n, testdata['error']))
755 fp.write('result%s: pass\n' % n)
756 for v in ['suspend', 'resume', 'boot', 'lastinit']:
758 fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))
759 for v in ['fwsuspend', 'fwresume']:
761 fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0))
762 if 'bugurl' in testdata:
763 fp.write('url%s: %s\n' % (n, testdata['bugurl']))
765 self.sudouser(self.result)
766 def configFile(self, file):
767 dir = os.path.dirname(os.path.realpath(__file__))
768 if os.path.exists(file):
770 elif os.path.exists(dir+'/'+file):
772 elif os.path.exists(dir+'/config/'+file):
773 return dir+'/config/'+file
775 def openlog(self, filename, mode):
779 with gzip.open(filename, mode+'b') as fp:
785 return gzip.open(filename, mode+'b')
786 return open(filename, mode)
788 sysvals = SystemValues()
789 switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
790 switchoff = ['disable', 'off', 'false', '0']
792 'freeze': 'Freeze (S0)',
793 'standby': 'Standby (S1)',
794 'mem': 'Suspend (S3)',
795 'disk': 'Hibernate (S4)'
800 # Simple class which holds property values collected
801 # for all the devices used in the timeline.
809 return '%s,%s,%d;' % (dev, self.altname, self.async)
810 def debug(self, dev):
811 print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)
812 def altName(self, dev):
813 if not self.altname or self.altname == dev:
815 return '%s [%s]' % (self.altname, dev)
818 return ' '+self.xtraclass
824 return ' '+self.xtraclass
826 return ' async_device'
827 return ' sync_device'
831 # A container used to create a device hierachy, with a single root node
832 # and a tree of child nodes. Used by Data.deviceTopology()
837 def __init__(self, nodename, nodedepth):
840 self.depth = nodedepth
844 # The primary container for suspend/resume test data. There is one for
845 # each test run. The data is organized into a cronological hierarchy:
848 # 10 sequential, non-overlapping phases of S/R
849 # contents: times for phase start/end, order/color data for html
851 # device callback or action list for this phase
853 # a single device callback or generic action
854 # contents: start/stop times, pid/cpu/driver info
855 # parents/children, html id for timeline/callgraph
856 # optionally includes an ftrace callgraph
857 # optionally includes dev/ps data
864 dmesg = {} # root data structure
865 phases = [] # ordered list of phases
866 start = 0.0 # test start
868 tSuspended = 0.0 # low-level suspend start
869 tResumed = 0.0 # low-level resume start
870 tKernSus = 0.0 # kernel level suspend start
871 tKernRes = 0.0 # kernel level resume end
872 tLow = 0.0 # time spent in low-level suspend (standby/freeze)
873 fwValid = False # is firmware data available
874 fwSuspend = 0 # time spent in firmware suspend
875 fwResume = 0 # time spent in firmware resume
876 dmesgtext = [] # dmesg text file in memory
877 pstl = 0 # process timeline
885 def __init__(self, num):
886 idchar = 'abcdefghij'
888 self.testnumber = num
889 self.idstr = idchar[num]
892 self.dmesg = { # fixed list of 10 phases
893 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
894 'row': 0, 'color': '#CCFFCC', 'order': 0},
895 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
896 'row': 0, 'color': '#88FF88', 'order': 1},
897 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
898 'row': 0, 'color': '#00AA00', 'order': 2},
899 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
900 'row': 0, 'color': '#008888', 'order': 3},
901 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
902 'row': 0, 'color': '#0000FF', 'order': 4},
903 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
904 'row': 0, 'color': '#FF0000', 'order': 5},
905 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
906 'row': 0, 'color': '#FF9900', 'order': 6},
907 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
908 'row': 0, 'color': '#FFCC00', 'order': 7},
909 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
910 'row': 0, 'color': '#FFFF88', 'order': 8},
911 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
912 'row': 0, 'color': '#FFFFCC', 'order': 9}
914 self.phases = self.sortedPhases()
915 self.devicegroups = []
916 for phase in self.phases:
917 self.devicegroups.append([phase])
918 self.errorinfo = {'suspend':[],'resume':[]}
919 def extractErrorInfo(self):
921 'HWERROR' : '.*\[ *Hardware Error *\].*',
922 'FWBUG' : '.*\[ *Firmware Bug *\].*',
924 'ERROR' : '.*ERROR.*',
925 'WARNING' : '.*WARNING.*',
926 'IRQ' : '.*genirq: .*',
927 'TASKFAIL': '.*Freezing of tasks failed.*',
929 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
934 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
937 t = float(m.group('ktime'))
938 if t < self.start or t > self.end:
940 dir = 'suspend' if t < self.tSuspended else 'resume'
943 if re.match(elist[err], msg):
944 list.append((err, dir, t, i, i))
948 type, dir, t, idx1, idx2 = e
949 sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t))
950 self.errorinfo[dir].append((type, t, idx1, idx2))
952 sysvals.dmesglog = True
954 def setStart(self, time):
956 def setEnd(self, time):
958 def isTraceEventOutsideDeviceCalls(self, pid, time):
959 for phase in self.phases:
960 list = self.dmesg[phase]['list']
963 if(d['pid'] == pid and time >= d['start'] and
967 def phaseCollision(self, phase, isbegin, line):
971 if self.dmesg[phase][key] >= 0:
972 sysvals.vprint('IGNORE: %s' % line.strip())
975 def sourcePhase(self, start):
976 for phase in self.phases:
977 pend = self.dmesg[phase]['end']
980 return 'resume_complete'
981 def sourceDevice(self, phaselist, start, end, pid, type):
983 for phase in phaselist:
984 list = self.dmesg[phase]['list']
988 if dev['pid'] != pid:
993 # device target event is entirely inside the source boundary
994 if(start < devS or start >= devE or end <= devS or end > devE):
996 elif type == 'thread':
997 # thread target event will expand the source boundary
1005 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
1006 # try to place the call in a device
1007 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device')
1008 # calls with device pids that occur outside device bounds are dropped
1009 # TODO: include these somehow
1010 if not tgtdev and pid in self.devpids:
1012 # try to place the call in a thread
1014 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread')
1015 # create new thread blocks, expand as new calls are found
1018 threadname = 'kthread-%d' % (pid)
1020 threadname = '%s-%d' % (proc, pid)
1021 tgtphase = self.sourcePhase(start)
1022 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
1023 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
1024 # this should not happen
1026 sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \
1027 (start, end, proc, pid, kprobename, cdata, rdata))
1029 # place the call data inside the src element of the tgtdev
1030 if('src' not in tgtdev):
1032 dtf = sysvals.dev_tracefuncs
1034 if kprobename in dtf and 'ub' in dtf[kprobename]:
1036 title = cdata+' '+rdata
1037 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
1038 m = re.match(mstr, title)
1040 c = m.group('caller')
1041 a = m.group('args').strip()
1047 if ubiquitous and c in dtf and 'ub' in dtf[c]:
1049 color = sysvals.kprobeColor(kprobename)
1050 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
1051 tgtdev['src'].append(e)
1053 def overflowDevices(self):
1054 # get a list of devices that extend beyond the end of this test run
1056 for phase in self.phases:
1057 list = self.dmesg[phase]['list']
1058 for devname in list:
1060 if dev['end'] > self.end:
1063 def mergeOverlapDevices(self, devlist):
1064 # merge any devices that overlap devlist
1066 devname = dev['name']
1067 for phase in self.phases:
1068 list = self.dmesg[phase]['list']
1069 if devname not in list:
1071 tdev = list[devname]
1072 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
1075 dev['end'] = tdev['end']
1076 if 'src' not in dev or 'src' not in tdev:
1078 dev['src'] += tdev['src']
1080 def usurpTouchingThread(self, name, dev):
1081 # the caller test has priority of this thread, give it to him
1082 for phase in self.phases:
1083 list = self.dmesg[phase]['list']
1086 if tdev['start'] - dev['end'] < 0.1:
1087 dev['end'] = tdev['end']
1088 if 'src' not in dev:
1091 dev['src'] += tdev['src']
1094 def stitchTouchingThreads(self, testlist):
1095 # merge any threads between tests that touch
1096 for phase in self.phases:
1097 list = self.dmesg[phase]['list']
1098 for devname in list:
1100 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
1102 for data in testlist:
1103 data.usurpTouchingThread(devname, dev)
1104 def optimizeDevSrc(self):
1105 # merge any src call loops to reduce timeline size
1106 for phase in self.phases:
1107 list = self.dmesg[phase]['list']
1109 if 'src' not in list[dev]:
1111 src = list[dev]['src']
1113 for e in sorted(src, key=lambda event: event.time):
1114 if not p or not e.repeat(p):
1117 # e is another iteration of p, move it into p
1119 p.length = p.end - p.time
1122 def trimTimeVal(self, t, t0, dT, left):
1137 def trimTime(self, t0, dT, left):
1138 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
1139 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
1140 self.start = self.trimTimeVal(self.start, t0, dT, left)
1141 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
1142 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
1143 self.end = self.trimTimeVal(self.end, t0, dT, left)
1144 for phase in self.phases:
1145 p = self.dmesg[phase]
1146 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
1147 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
1151 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
1152 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
1155 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
1156 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
1157 for line in cg.list:
1158 line.time = self.trimTimeVal(line.time, t0, dT, left)
1161 e.time = self.trimTimeVal(e.time, t0, dT, left)
1162 for dir in ['suspend', 'resume']:
1164 for e in self.errorinfo[dir]:
1165 type, tm, idx1, idx2 = e
1166 tm = self.trimTimeVal(tm, t0, dT, left)
1167 list.append((type, tm, idx1, idx2))
1168 self.errorinfo[dir] = list
1169 def normalizeTime(self, tZero):
1170 # trim out any standby or freeze clock time
1171 if(self.tSuspended != self.tResumed):
1172 if(self.tResumed > tZero):
1173 self.trimTime(self.tSuspended, \
1174 self.tResumed-self.tSuspended, True)
1176 self.trimTime(self.tSuspended, \
1177 self.tResumed-self.tSuspended, False)
1178 def getTimeValues(self):
1179 sktime = (self.dmesg['suspend_machine']['end'] - \
1180 self.tKernSus) * 1000
1181 rktime = (self.dmesg['resume_complete']['end'] - \
1182 self.dmesg['resume_machine']['start']) * 1000
1183 return (sktime, rktime)
1184 def setPhase(self, phase, ktime, isbegin):
1186 self.dmesg[phase]['start'] = ktime
1188 self.dmesg[phase]['end'] = ktime
1189 def dmesgSortVal(self, phase):
1190 return self.dmesg[phase]['order']
1191 def sortedPhases(self):
1192 return sorted(self.dmesg, key=self.dmesgSortVal)
1193 def sortedDevices(self, phase):
1194 list = self.dmesg[phase]['list']
1197 for devname in list:
1199 if dev['length'] == 0:
1201 tmp[dev['start']] = devname
1202 for t in sorted(tmp):
1203 slist.append(tmp[t])
1205 def fixupInitcalls(self, phase):
1206 # if any calls never returned, clip them at system resume end
1207 phaselist = self.dmesg[phase]['list']
1208 for devname in phaselist:
1209 dev = phaselist[devname]
1211 for p in self.phases:
1212 if self.dmesg[p]['end'] > dev['start']:
1213 dev['end'] = self.dmesg[p]['end']
1215 sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
1216 def deviceFilter(self, devicefilter):
1217 for phase in self.phases:
1218 list = self.dmesg[phase]['list']
1222 for filter in devicefilter:
1223 if filter in name or \
1224 ('drv' in list[name] and filter in list[name]['drv']):
1230 def fixupInitcallsThatDidntReturn(self):
1231 # if any calls never returned, clip them at system resume end
1232 for phase in self.phases:
1233 self.fixupInitcalls(phase)
1234 def phaseOverlap(self, phases):
1237 for group in self.devicegroups:
1238 for phase in phases:
1239 if phase not in group:
1242 if p not in newgroup:
1244 if group not in rmgroups:
1245 rmgroups.append(group)
1246 for group in rmgroups:
1247 self.devicegroups.remove(group)
1248 self.devicegroups.append(newgroup)
1249 def newActionGlobal(self, name, start, end, pid=-1, color=''):
1250 # which phase is this device callback or action in
1251 targetphase = 'none'
1255 for phase in self.phases:
1256 pstart = self.dmesg[phase]['start']
1257 pend = self.dmesg[phase]['end']
1258 # see if the action overlaps this phase
1259 o = max(0, min(end, pend) - max(start, pstart))
1261 phases.append(phase)
1262 # set the target phase to the one that overlaps most
1264 if overlap > 0 and phase == 'post_resume':
1268 # if no target phase was found, pin it to the edge
1269 if targetphase == 'none':
1270 p0start = self.dmesg[self.phases[0]]['start']
1271 if start <= p0start:
1272 targetphase = self.phases[0]
1274 targetphase = self.phases[-1]
1281 self.phaseOverlap(phases)
1282 if targetphase in self.phases:
1283 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1284 return (targetphase, newname)
1286 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
1287 # new device callback for a specific phase
1288 self.html_device_id += 1
1289 devid = '%s%d' % (self.idstr, self.html_device_id)
1290 list = self.dmesg[phase]['list']
1292 if(start >= 0 and end >= 0):
1293 length = end - start
1297 while(name in list):
1298 name = '%s[%d]' % (origname, i)
1300 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,
1301 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }
1303 list[name]['htmlclass'] = htmlclass
1305 list[name]['color'] = color
1307 def deviceChildren(self, devname, phase):
1309 list = self.dmesg[phase]['list']
1311 if(list[child]['par'] == devname):
1312 devlist.append(child)
1314 def printDetails(self):
1315 sysvals.vprint('Timeline Details:')
1316 sysvals.vprint(' test start: %f' % self.start)
1317 sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
1318 for phase in self.phases:
1319 dc = len(self.dmesg[phase]['list'])
1320 sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \
1321 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
1322 sysvals.vprint(' kernel resume end: %f' % self.tKernRes)
1323 sysvals.vprint(' test end: %f' % self.end)
1324 def deviceChildrenAllPhases(self, devname):
1326 for phase in self.phases:
1327 list = self.deviceChildren(devname, phase)
1329 if dev not in devlist:
1332 def masterTopology(self, name, list, depth):
1333 node = DeviceNode(name, depth)
1338 clist = self.deviceChildrenAllPhases(cname)
1339 cnode = self.masterTopology(cname, clist, depth+1)
1340 node.children.append(cnode)
1342 def printTopology(self, node):
1347 for phase in self.phases:
1348 list = self.dmesg[phase]['list']
1349 if node.name in list:
1350 s = list[node.name]['start']
1351 e = list[node.name]['end']
1352 if list[node.name]['drv']:
1353 drv = ' {'+list[node.name]['drv']+'}'
1354 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
1355 html += '<li><b>'+node.name+drv+'</b>'
1357 html += '<ul>'+info+'</ul>'
1359 if len(node.children) > 0:
1361 for cnode in node.children:
1362 html += self.printTopology(cnode)
1365 def rootDeviceList(self):
1366 # list of devices graphed
1368 for phase in self.dmesg:
1369 list = self.dmesg[phase]['list']
1371 if list[dev]['pid'] >= 0 and dev not in real:
1373 # list of top-most root devices
1375 for phase in self.dmesg:
1376 list = self.dmesg[phase]['list']
1378 pdev = list[dev]['par']
1379 pid = list[dev]['pid']
1380 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
1382 if pdev and pdev not in real and pdev not in rootlist:
1383 rootlist.append(pdev)
1385 def deviceTopology(self):
1386 rootlist = self.rootDeviceList()
1387 master = self.masterTopology('', rootlist, 0)
1388 return self.printTopology(master)
1389 def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
1390 # only select devices that will actually show up in html
1391 self.tdevlist = dict()
1392 for phase in self.dmesg:
1394 list = self.dmesg[phase]['list']
1396 length = (list[dev]['end'] - list[dev]['start']) * 1000
1397 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
1398 if width != '0.000000' and length >= mindevlen:
1400 self.tdevlist[phase] = devlist
1401 def addHorizontalDivider(self, devname, devend):
1402 phase = 'suspend_prepare'
1403 self.newAction(phase, devname, -2, '', \
1404 self.start, devend, '', ' sec', '')
1405 if phase not in self.tdevlist:
1406 self.tdevlist[phase] = []
1407 self.tdevlist[phase].append(devname)
1408 d = DevItem(0, phase, self.dmesg[phase]['list'][devname])
1410 def addProcessUsageEvent(self, name, times):
1411 # get the start and end times for this process
1416 for t in sorted(times):
1420 if name in self.pstl[t]:
1421 if start == -1 or tlast < start:
1423 if end == -1 or t > end:
1426 if start == -1 or end == -1:
1428 # add a new action for this process and get the object
1429 out = self.newActionGlobal(name, start, end, -3)
1432 phase, devname = out
1433 dev = self.dmesg[phase]['list'][devname]
1434 # get the cpu exec data
1438 for t in sorted(times):
1439 if tlast == 0 or t <= start or t > end:
1453 dev['cpuexec'] = cpuexec
1455 def createProcessUsageEvents(self):
1456 # get an array of process names
1459 pslist = self.pstl[t]
1461 if ps not in proclist:
1463 # get a list of data points for suspend and resume
1466 for t in sorted(self.pstl):
1467 if t < self.tSuspended:
1471 # process the events for suspend and resume
1472 if len(proclist) > 0:
1473 sysvals.vprint('Process Execution:')
1475 c = self.addProcessUsageEvent(ps, tsus)
1477 sysvals.vprint('%25s (sus): %d' % (ps, c))
1478 c = self.addProcessUsageEvent(ps, tres)
1480 sysvals.vprint('%25s (res): %d' % (ps, c))
1481 def debugPrint(self):
1482 for p in self.phases:
1483 list = self.dmesg[p]['list']
1484 for devname in list:
1487 dev['ftrace'].debugPrint(' [%s]' % devname)
1489 # Class: DevFunction
1491 # A container for kprobe function data we want in the dev timeline
1495 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
1498 self.caller = caller
1501 self.length = end - start
1510 cnt = '(x%d)' % self.count
1511 l = '%0.3fms' % (self.length * 1000)
1513 title = '%s(%s)%s <- %s, %s(%s)' % \
1514 (self.name, self.args, cnt, self.caller, self.ret, l)
1516 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
1517 return title.replace('"', '')
1520 text = '%s(x%d)' % (self.name, self.count)
1524 def repeat(self, tgt):
1525 # is the tgt call just a repeat of this call (e.g. are we in a loop)
1526 dt = self.time - tgt.end
1527 # only combine calls if -all- attributes are identical
1528 if tgt.caller == self.caller and \
1529 tgt.name == self.name and tgt.args == self.args and \
1530 tgt.proc == self.proc and tgt.pid == self.pid and \
1531 tgt.ret == self.ret and dt >= 0 and \
1532 dt <= sysvals.callloopmaxgap and \
1533 self.length < sysvals.callloopmaxlen:
1539 # A container for a single line of ftrace data. There are six basic types:
1541 # call: " dpm_run_callback() {"
1543 # leaf: " dpm_run_callback();"
1545 # tracing_mark_write: SUSPEND START or RESUME COMPLETE
1546 # suspend_resume: phase or custom exec block data
1547 # device_pm_callback: device callback info
1558 def __init__(self, t, m='', d=''):
1559 self.time = float(t)
1562 # is this a trace event
1563 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
1564 if(d == 'traceevent'):
1565 # nop format trace event
1568 # function_graph format trace event
1569 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
1570 msg = em.group('msg')
1572 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
1574 self.name = emm.group('msg')
1575 self.type = emm.group('call')
1578 km = re.match('^(?P<n>.*)_cal$', self.type)
1582 self.type = km.group('n')
1584 km = re.match('^(?P<n>.*)_ret$', self.type)
1588 self.type = km.group('n')
1592 # convert the duration to seconds
1594 self.length = float(d)/1000000
1595 # the indentation determines the depth
1596 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
1599 self.depth = self.getDepth(match.group('d'))
1600 m = match.group('o')
1605 # includes comment with function name
1606 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
1608 self.name = match.group('n').strip()
1612 # function call with children
1614 match = re.match('^(?P<n>.*) *\(.*', m)
1616 self.name = match.group('n').strip()
1617 # function call with no children (leaf)
1620 match = re.match('^(?P<n>.*) *\(.*', m)
1622 self.name = match.group('n').strip()
1623 # something else (possibly a trace marker)
1627 return self.fcall and not self.freturn
1629 return self.freturn and not self.fcall
1631 return self.fcall and self.freturn
1632 def getDepth(self, str):
1634 def debugPrint(self, info=''):
1636 print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
1637 self.depth, self.name, self.length*1000000, info))
1639 print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
1640 self.depth, self.name, self.length*1000000, info))
1642 print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
1643 self.depth, self.name, self.length*1000000, info))
1644 def startMarker(self):
1645 # Is this the starting line of a suspend?
1648 if sysvals.usetracemarkers:
1649 if(self.name == 'SUSPEND START'):
1653 if(self.type == 'suspend_resume' and
1654 re.match('suspend_enter\[.*\] begin', self.name)):
1657 def endMarker(self):
1658 # Is this the ending line of a resume?
1661 if sysvals.usetracemarkers:
1662 if(self.name == 'RESUME COMPLETE'):
1666 if(self.type == 'suspend_resume' and
1667 re.match('thaw_processes\[.*\] end', self.name)):
1671 # Class: FTraceCallGraph
1673 # A container for the ftrace callgraph of a single recursive function.
1674 # This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
1675 # Each instance is tied to a single device in a single phase, and is
1676 # comprised of an ordered list of FTraceLine objects
1677 class FTraceCallGraph:
1687 vfname = 'missing_function_name'
1690 def __init__(self, pid, sv):
1697 def addLine(self, line):
1698 # if this is already invalid, just leave
1700 if(line.depth == 0 and line.freturn):
1703 # invalidate on bad depth
1705 self.invalidate(line)
1707 # ignore data til we return to the current depth
1709 if line.depth > self.depth:
1712 self.list[-1].freturn = True
1713 self.list[-1].length = line.time - self.list[-1].time
1715 # if this is a return at self.depth, no more work is needed
1716 if line.depth == self.depth and line.isReturn():
1718 self.end = line.time
1721 # compare current depth with this lines pre-call depth
1722 prelinedep = line.depth
1726 lasttime = line.time
1727 if len(self.list) > 0:
1728 last = self.list[-1]
1729 lasttime = last.time
1731 lasttime += last.length
1732 # handle low misalignments by inserting returns
1733 mismatch = prelinedep - self.depth
1734 warning = self.sv.verbose and abs(mismatch) > 1
1738 # add return calls to get the depth down
1739 while prelinedep < self.depth:
1741 if idx == 0 and last and last.isCall():
1742 # special case, turn last call into a leaf
1743 last.depth = self.depth
1745 last.length = line.time - last.time
1747 info.append(('[make leaf]', last))
1749 vline = FTraceLine(lasttime)
1750 vline.depth = self.depth
1751 vline.name = self.vfname
1752 vline.freturn = True
1753 self.list.append(vline)
1756 info.append(('', last))
1757 info.append(('[add return]', vline))
1760 info.append(('', line))
1761 # handle high misalignments by inserting calls
1765 info.append(('', last))
1766 # add calls to get the depth up
1767 while prelinedep > self.depth:
1768 if idx == 0 and line.isReturn():
1769 # special case, turn this return into a leaf
1773 info.append(('[make leaf]', line))
1775 vline = FTraceLine(lasttime)
1776 vline.depth = self.depth
1777 vline.name = self.vfname
1779 self.list.append(vline)
1782 self.start = vline.time
1784 info.append(('[add call]', vline))
1786 if warning and ('[make leaf]', line) not in info:
1787 info.append(('', line))
1789 print 'WARNING: ftrace data missing, corrections made:'
1794 # process the call and set the new depth
1796 md = self.sv.max_graph_depth
1798 # ignore blacklisted/overdepth funcs
1799 if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):
1803 elif line.isReturn():
1805 # remove blacklisted/overdepth/empty funcs that slipped through
1806 if (last and last.isCall() and last.depth == line.depth) or \
1807 (md and last and last.depth >= md) or \
1808 (line.name in self.sv.cgblacklist):
1809 while len(self.list) > 0 and self.list[-1].depth > line.depth:
1811 if len(self.list) == 0:
1814 self.list[-1].freturn = True
1815 self.list[-1].length = line.time - self.list[-1].time
1816 self.list[-1].name = line.name
1818 if len(self.list) < 1:
1819 self.start = line.time
1820 # check for a mismatch that returned all the way to callgraph end
1822 if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn:
1823 line = self.list[-1]
1827 self.list.append(line)
1828 if(line.depth == 0 and line.freturn):
1830 self.start = line.time
1831 self.end = line.time
1833 self.end += line.length
1834 if self.list[0].name == self.vfname:
1840 def invalidate(self, line):
1841 if(len(self.list) > 0):
1842 first = self.list[0]
1844 self.list.append(first)
1846 id = 'task %s' % (self.pid)
1847 window = '(%f - %f)' % (self.start, line.time)
1849 print('Data misalignment for '+id+\
1850 ' (buffer overflow), ignoring this callback')
1852 print('Too much data for '+id+\
1853 ' '+window+', ignoring this callback')
1854 def slice(self, dev):
1855 minicg = FTraceCallGraph(dev['pid'], self.sv)
1856 minicg.name = self.name
1860 if(l.time < dev['start'] or l.time > dev['end']):
1863 if l.name == 'mutex_lock' and l.freturn:
1866 elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall:
1871 if not good or len(minicg.list) < 1:
1874 def repair(self, enddepth):
1875 # bring the depth back to 0 with additional returns
1877 last = self.list[-1]
1878 for i in reversed(range(enddepth)):
1879 t = FTraceLine(last.time)
1882 fixed = self.addLine(t)
1884 self.end = last.time
1887 def postProcess(self):
1888 if len(self.list) > 0:
1889 self.name = self.list[0].name
1894 # ftrace bug: reported duration is not reliable
1895 # check each leaf and clip it at max possible length
1896 if last and last.isLeaf():
1897 if last.length > l.time - last.time:
1898 last.length = l.time - last.time
1903 if(l.depth not in stack):
1905 print 'Post Process Error: Depth missing'
1908 # calculate call length from call/return lines
1910 cl.length = l.time - cl.time
1911 if cl.name == self.vfname:
1918 # trace caught the whole call tree
1922 print 'Post Process Error: Depth is less than 0'
1924 # trace ended before call tree finished
1925 return self.repair(cnt)
1926 def deviceMatch(self, pid, data):
1928 # add the callgraph data to the device hierarchy
1930 'dpm_prepare': 'suspend_prepare',
1931 'dpm_complete': 'resume_complete'
1933 if(self.name in borderphase):
1934 p = borderphase[self.name]
1935 list = data.dmesg[p]['list']
1936 for devname in list:
1938 if(pid == dev['pid'] and
1939 self.start <= dev['start'] and
1940 self.end >= dev['end']):
1941 cg = self.slice(dev)
1946 for p in data.phases:
1947 if(data.dmesg[p]['start'] <= self.start and
1948 self.start <= data.dmesg[p]['end']):
1949 list = data.dmesg[p]['list']
1950 for devname in list:
1952 if(pid == dev['pid'] and
1953 self.start <= dev['start'] and
1954 self.end >= dev['end']):
1955 dev['ftrace'] = self
1960 def newActionFromFunction(self, data):
1962 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
1966 if fs < data.start or fe > data.end:
1969 for p in data.phases:
1970 if(data.dmesg[p]['start'] <= self.start and
1971 self.start < data.dmesg[p]['end']):
1976 out = data.newActionGlobal(name, fs, fe, -2)
1979 data.dmesg[phase]['list'][myname]['ftrace'] = self
1980 def debugPrint(self, info=''):
1981 print('%s pid=%d [%f - %f] %.3f us') % \
1982 (self.name, self.pid, self.start, self.end,
1983 (self.end - self.start)*1000000)
1986 print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
1987 l.depth, l.name, l.length*1000000, info))
1989 print('%f (%02d): %s} (%.3f us)%s' % (l.time, \
1990 l.depth, l.name, l.length*1000000, info))
1992 print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
1993 l.depth, l.name, l.length*1000000, info))
1997 def __init__(self, test, phase, dev):
2002 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:
2008 # A container for a device timeline which calculates
2009 # all the html properties to display it correctly
2012 height = 0 # total timeline height
2013 scaleH = 20 # timescale (top) row height
2014 rowH = 30 # device row height
2015 bodyH = 0 # body height
2016 rows = 0 # total timeline rows
2019 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
2020 html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
2021 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'
2022 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
2023 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}"> {2}</div>\n'
2024 def __init__(self, rowheight, scaleheight):
2025 self.rowH = rowheight
2026 self.scaleH = scaleheight
2028 def createHeader(self, sv, stamp):
2029 if(not stamp['time']):
2031 self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \
2032 % (sv.title, sv.version)
2033 if sv.logmsg and sv.testlog:
2034 self.html += '<button id="showtest" class="logbtn btnfmt">log</button>'
2036 self.html += '<button id="showdmesg" class="logbtn btnfmt">dmesg</button>'
2038 self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>'
2039 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
2040 self.html += headline_stamp.format(stamp['host'], stamp['kernel'],
2041 stamp['mode'], stamp['time'])
2042 if 'man' in stamp and 'plat' in stamp and 'cpu' in stamp and \
2043 stamp['man'] and stamp['plat'] and stamp['cpu']:
2044 headline_sysinfo = '<div class="stamp sysinfo">{0} {1} <i>with</i> {2}</div>\n'
2045 self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu'])
2047 # Function: getDeviceRows
2049 # determine how may rows the device funcs will take
2051 # rawlist: the list of devices/actions for a single phase
2053 # The total number of rows needed to display this phase of the timeline
2054 def getDeviceRows(self, rawlist):
2055 # clear all rows and set them to undefined
2057 for item in rawlist:
2059 sortdict[item] = item.length
2060 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
2061 remaining = len(sortlist)
2064 # try to pack each row with as many ranges as possible
2065 while(remaining > 0):
2066 if(row not in rowdata):
2072 e = i.time + i.length
2074 for ritem in rowdata[row]:
2076 re = ritem.time + ritem.length
2077 if(not (((s <= rs) and (e <= rs)) or
2078 ((s >= re) and (e >= re)))):
2082 rowdata[row].append(i)
2087 # Function: getPhaseRows
2089 # Organize the timeline entries into the smallest
2090 # number of rows possible, with no entry overlapping
2092 # devlist: the list of devices/actions in a group of contiguous phases
2094 # The total number of rows needed to display this phase of the timeline
2095 def getPhaseRows(self, devlist, row=0, sortby='length'):
2096 # clear all rows and set them to undefined
2097 remaining = len(devlist)
2101 # initialize all device rows to -1 and calculate devrows
2102 for item in devlist:
2104 tp = (item.test, item.phase)
2105 if tp not in myphases:
2108 if sortby == 'start':
2109 # sort by start 1st, then length 2nd
2110 sortdict[item] = (-1*float(dev['start']), float(dev['end']) - float(dev['start']))
2112 # sort by length 1st, then name 2nd
2113 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])
2115 dev['devrows'] = self.getDeviceRows(dev['src'])
2116 # sort the devlist by length so that large items graph on top
2117 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
2119 for item in sortlist:
2120 if item.dev['pid'] == -2:
2121 orderedlist.append(item)
2122 for item in sortlist:
2123 if item not in orderedlist:
2124 orderedlist.append(item)
2125 # try to pack each row with as many devices as possible
2126 while(remaining > 0):
2128 if(row not in rowdata):
2130 for item in orderedlist:
2136 for ritem in rowdata[row]:
2137 rs = ritem.dev['start']
2138 re = ritem.dev['end']
2139 if(not (((s <= rs) and (e <= rs)) or
2140 ((s >= re) and (e >= re)))):
2144 rowdata[row].append(item)
2147 if 'devrows' in dev and dev['devrows'] > rowheight:
2148 rowheight = dev['devrows']
2149 for t, p in myphases:
2150 if t not in self.rowlines or t not in self.rowheight:
2151 self.rowlines[t] = dict()
2152 self.rowheight[t] = dict()
2153 if p not in self.rowlines[t] or p not in self.rowheight[t]:
2154 self.rowlines[t][p] = dict()
2155 self.rowheight[t][p] = dict()
2157 # section headers should use a different row height
2158 if len(rowdata[row]) == 1 and \
2159 'htmlclass' in rowdata[row][0].dev and \
2160 'sec' in rowdata[row][0].dev['htmlclass']:
2162 self.rowlines[t][p][row] = rowheight
2163 self.rowheight[t][p][row] = rowheight * rh
2165 if(row > self.rows):
2166 self.rows = int(row)
2168 def phaseRowHeight(self, test, phase, row):
2169 return self.rowheight[test][phase][row]
2170 def phaseRowTop(self, test, phase, row):
2172 for i in sorted(self.rowheight[test][phase]):
2175 top += self.rowheight[test][phase][i]
2177 def calcTotalRows(self):
2178 # Calculate the heights and offsets for the header and rows
2181 for t in self.rowlines:
2182 for p in self.rowlines[t]:
2184 for i in sorted(self.rowlines[t][p]):
2185 total += self.rowlines[t][p][i]
2188 if total == len(self.rowlines[t][p]):
2189 standardphases.append((t, p))
2190 self.height = self.scaleH + (maxrows*self.rowH)
2191 self.bodyH = self.height - self.scaleH
2192 # if there is 1 line per row, draw them the standard way
2193 for t, p in standardphases:
2194 for i in sorted(self.rowheight[t][p]):
2195 self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p])
2196 def createZoomBox(self, mode='command', testcount=1):
2197 # Create bounding box, add buttons
2198 html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
2199 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
2200 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail{0}</button>'
2201 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
2202 if mode != 'command':
2204 self.html += html_devlist2
2205 self.html += html_devlist1.format('1')
2207 self.html += html_devlist1.format('')
2208 self.html += html_zoombox
2209 self.html += html_timeline.format('dmesg', self.height)
2210 # Function: createTimeScale
2212 # Create the timescale for a timeline block
2214 # m0: start time (mode begin)
2215 # mMax: end time (mode end)
2216 # tTotal: total timeline time
2217 # mode: suspend or resume
2219 # The html code needed to display the time scale
2220 def createTimeScale(self, m0, mMax, tTotal, mode):
2221 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
2222 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">{0}</div>\n'
2223 output = '<div class="timescale">\n'
2224 # set scale for timeline
2228 return output+'</div>\n'
2231 divTotal = int(mTotal/tS) + 1
2232 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
2233 for i in range(divTotal):
2235 if(mode == 'suspend'):
2236 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
2237 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
2238 if(i == divTotal - 1):
2240 htmlline = timescale.format(pos, val)
2242 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
2243 val = '%0.fms' % (float(i)*tS*1000)
2244 htmlline = timescale.format(pos, val)
2246 htmlline = rline.format(mode)
2248 self.html += output+'</div>\n'
2252 # A list of values describing the properties of these test runs
2260 stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
2261 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
2262 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
2263 sysinfofmt = '^# sysinfo .*'
2264 cmdlinefmt = '^# command \| (?P<cmd>.*)'
2265 kparamsfmt = '^# kparams \| (?P<kp>.*)'
2266 ftrace_line_fmt_fg = \
2267 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
2268 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
2269 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
2270 ftrace_line_fmt_nop = \
2271 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
2272 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
2274 ftrace_line_fmt = ftrace_line_fmt_nop
2280 def setTracerType(self, tracer):
2281 if(tracer == 'function_graph'):
2282 self.cgformat = True
2283 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
2284 elif(tracer == 'nop'):
2285 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2287 doError('Invalid tracer format: [%s]' % tracer)
2288 def parseStamp(self, data, sv):
2289 m = re.match(self.stampfmt, self.stamp)
2290 data.stamp = {'time': '', 'host': '', 'mode': ''}
2291 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
2292 int(m.group('d')), int(m.group('H')), int(m.group('M')),
2294 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
2295 data.stamp['host'] = m.group('host')
2296 data.stamp['mode'] = m.group('mode')
2297 data.stamp['kernel'] = m.group('kernel')
2298 if re.match(self.sysinfofmt, self.sysinfo):
2299 for f in self.sysinfo.split('|'):
2302 tmp = f.strip().split(':', 1)
2305 data.stamp[key] = val
2306 sv.hostname = data.stamp['host']
2307 sv.suspendmode = data.stamp['mode']
2308 if sv.suspendmode == 'command' and sv.ftracefile != '':
2309 modes = ['on', 'freeze', 'standby', 'mem', 'disk']
2310 fp = sysvals.openlog(sv.ftracefile, 'r')
2312 m = re.match('.* machine_suspend\[(?P<mode>.*)\]', line)
2313 if m and m.group('mode') in ['1', '2', '3', '4']:
2314 sv.suspendmode = modes[int(m.group('mode'))]
2315 data.stamp['mode'] = sv.suspendmode
2318 m = re.match(self.cmdlinefmt, self.cmdline)
2320 sv.cmdline = m.group('cmd')
2322 m = re.match(self.kparamsfmt, self.kparams)
2324 sv.kparams = m.group('kp')
2326 sv.stamp = data.stamp
2330 # A container for a suspend/resume test run. This is necessary as
2331 # there could be more than one, and they need to be separate.
2336 def __init__(self, dataobj):
2341 class ProcessMonitor:
2345 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
2346 process = Popen(c, shell=True, stdout=PIPE)
2348 for line in process.stdout:
2351 name = re.sub('[()]', '', data[1])
2352 user = int(data[13])
2353 kern = int(data[14])
2355 if pid not in self.proclist:
2356 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern}
2358 val = self.proclist[pid]
2359 ujiff = user - val['user']
2360 kjiff = kern - val['kern']
2363 if ujiff > 0 or kjiff > 0:
2364 running[pid] = ujiff + kjiff
2368 jiffies = running[pid]
2369 val = self.proclist[pid]
2372 out += '%s-%s %d' % (val['name'], pid, jiffies)
2374 def processMonitor(self, tid):
2376 out = self.procstat()
2378 sysvals.fsetVal(out, 'trace_marker')
2380 self.thread = Thread(target=self.processMonitor, args=(0,))
2384 self.running = False
2386 # ----------------- FUNCTIONS --------------------
2388 # Function: doesTraceLogHaveTraceEvents
2390 # Quickly determine if the ftrace log has all of the trace events,
2391 # markers, and/or kprobes required for primary parsing.
2392 def doesTraceLogHaveTraceEvents():
2393 kpcheck = ['_cal: (', '_cpu_down()']
2394 techeck = ['suspend_resume']
2395 tmcheck = ['SUSPEND START', 'RESUME COMPLETE']
2396 sysvals.usekprobes = False
2397 fp = sysvals.openlog(sysvals.ftracefile, 'r')
2400 if not sysvals.usekprobes:
2403 sysvals.usekprobes = True
2404 # check for all necessary trace events
2410 # check for all necessary trace markers
2417 if len(techeck) == 0:
2418 sysvals.usetraceevents = True
2420 sysvals.usetraceevents = False
2421 if len(tmcheck) == 0:
2422 sysvals.usetracemarkers = True
2424 sysvals.usetracemarkers = False
2426 # Function: appendIncompleteTraceLog
2428 # [deprecated for kernel 3.15 or newer]
2429 # Legacy support of ftrace outputs that lack the device_pm_callback
2430 # and/or suspend_resume trace events. The primary data should be
2431 # taken from dmesg, and this ftrace is used only for callgraph data
2432 # or custom actions in the timeline. The data is appended to the Data
2435 # testruns: the array of Data objects obtained from parseKernelLog
2436 def appendIncompleteTraceLog(testruns):
2437 # create TestRun vessels for ftrace parsing
2438 testcnt = len(testruns)
2441 for data in testruns:
2442 testrun.append(TestRun(data))
2444 # extract the callgraph and traceevent data
2445 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
2446 os.path.basename(sysvals.ftracefile))
2448 tf = sysvals.openlog(sysvals.ftracefile, 'r')
2451 # remove any latent carriage returns
2452 line = line.replace('\r\n', '')
2453 # grab the stamp and sysinfo
2454 if re.match(tp.stampfmt, line):
2457 elif re.match(tp.sysinfofmt, line):
2460 elif re.match(tp.cmdlinefmt, line):
2463 # determine the trace data type (required for further parsing)
2464 m = re.match(sysvals.tracertypefmt, line)
2466 tp.setTracerType(m.group('t'))
2468 # device properties line
2469 if(re.match(sysvals.devpropfmt, line)):
2472 # parse only valid lines, if this is not one move on
2473 m = re.match(tp.ftrace_line_fmt, line)
2476 # gather the basic message data from the line
2477 m_time = m.group('time')
2478 m_pid = m.group('pid')
2479 m_msg = m.group('msg')
2481 m_param3 = m.group('dur')
2483 m_param3 = 'traceevent'
2484 if(m_time and m_pid and m_msg):
2485 t = FTraceLine(m_time, m_msg, m_param3)
2489 # the line should be a call, return, or event
2490 if(not t.fcall and not t.freturn and not t.fevent):
2492 # look for the suspend start marker
2493 if(t.startMarker()):
2494 data = testrun[testidx].data
2495 tp.parseStamp(data, sysvals)
2496 data.setStart(t.time)
2500 # find the end of resume
2504 if(testidx >= testcnt):
2507 # trace event processing
2509 # general trace events have two types, begin and end
2510 if(re.match('(?P<name>.*) begin$', t.name)):
2512 elif(re.match('(?P<name>.*) end$', t.name)):
2516 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2518 val = m.group('val')
2520 name = m.group('name')
2522 name = m.group('name')+'['+val+']'
2524 m = re.match('(?P<name>.*) .*', t.name)
2525 name = m.group('name')
2526 # special processing for trace events
2527 if re.match('dpm_prepare\[.*', name):
2529 elif re.match('machine_suspend.*', name):
2531 elif re.match('suspend_enter\[.*', name):
2533 data.dmesg['suspend_prepare']['end'] = t.time
2535 elif re.match('dpm_suspend\[.*', name):
2537 data.dmesg['suspend']['end'] = t.time
2539 elif re.match('dpm_suspend_late\[.*', name):
2541 data.dmesg['suspend_late']['start'] = t.time
2543 data.dmesg['suspend_late']['end'] = t.time
2545 elif re.match('dpm_suspend_noirq\[.*', name):
2547 data.dmesg['suspend_noirq']['start'] = t.time
2549 data.dmesg['suspend_noirq']['end'] = t.time
2551 elif re.match('dpm_resume_noirq\[.*', name):
2553 data.dmesg['resume_machine']['end'] = t.time
2554 data.dmesg['resume_noirq']['start'] = t.time
2556 data.dmesg['resume_noirq']['end'] = t.time
2558 elif re.match('dpm_resume_early\[.*', name):
2560 data.dmesg['resume_early']['start'] = t.time
2562 data.dmesg['resume_early']['end'] = t.time
2564 elif re.match('dpm_resume\[.*', name):
2566 data.dmesg['resume']['start'] = t.time
2568 data.dmesg['resume']['end'] = t.time
2570 elif re.match('dpm_complete\[.*', name):
2572 data.dmesg['resume_complete']['start'] = t.time
2574 data.dmesg['resume_complete']['end'] = t.time
2576 # skip trace events inside devices calls
2577 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2579 # global events (outside device calls) are simply graphed
2581 # store each trace event in ttemp
2582 if(name not in testrun[testidx].ttemp):
2583 testrun[testidx].ttemp[name] = []
2584 testrun[testidx].ttemp[name].append(\
2585 {'begin': t.time, 'end': t.time})
2587 # finish off matching trace event in ttemp
2588 if(name in testrun[testidx].ttemp):
2589 testrun[testidx].ttemp[name][-1]['end'] = t.time
2590 # call/return processing
2591 elif sysvals.usecallgraph:
2592 # create a callgraph object for the data
2593 if(pid not in testrun[testidx].ftemp):
2594 testrun[testidx].ftemp[pid] = []
2595 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
2596 # when the call is finished, see which device matches it
2597 cg = testrun[testidx].ftemp[pid][-1]
2600 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
2602 testrun[testidx].ftemp[pid][-1].addLine(t)
2605 for test in testrun:
2606 # add the traceevent data to the device hierarchy
2607 if(sysvals.usetraceevents):
2608 for name in test.ttemp:
2609 for event in test.ttemp[name]:
2610 test.data.newActionGlobal(name, event['begin'], event['end'])
2612 # add the callgraph data to the device hierarchy
2613 for pid in test.ftemp:
2614 for cg in test.ftemp[pid]:
2615 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
2617 if(not cg.postProcess()):
2618 id = 'task %s cpu %s' % (pid, m.group('cpu'))
2619 sysvals.vprint('Sanity check failed for '+\
2620 id+', ignoring this callback')
2622 callstart = cg.start
2624 for p in test.data.phases:
2625 if(test.data.dmesg[p]['start'] <= callstart and
2626 callstart <= test.data.dmesg[p]['end']):
2627 list = test.data.dmesg[p]['list']
2628 for devname in list:
2630 if(pid == dev['pid'] and
2631 callstart <= dev['start'] and
2632 callend >= dev['end']):
2636 # Function: parseTraceLog
2638 # Analyze an ftrace log output file generated from this app during
2639 # the execution phase. Used when the ftrace log is the primary data source
2640 # and includes the suspend_resume and device_pm_callback trace events
2641 # The ftrace filename is taken from sysvals
2643 # An array of Data objects
2644 def parseTraceLog(live=False):
2645 sysvals.vprint('Analyzing the ftrace data (%s)...' % \
2646 os.path.basename(sysvals.ftracefile))
2647 if(os.path.exists(sysvals.ftracefile) == False):
2648 doError('%s does not exist' % sysvals.ftracefile)
2650 sysvals.setupAllKprobes()
2652 if sysvals.usekprobes:
2653 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2654 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
2656 # extract the callgraph and traceevent data
2662 tf = sysvals.openlog(sysvals.ftracefile, 'r')
2663 phase = 'suspend_prepare'
2665 # remove any latent carriage returns
2666 line = line.replace('\r\n', '')
2667 # stamp and sysinfo lines
2668 if re.match(tp.stampfmt, line):
2671 elif re.match(tp.sysinfofmt, line):
2674 elif re.match(tp.cmdlinefmt, line):
2677 # firmware line: pull out any firmware data
2678 m = re.match(sysvals.firmwarefmt, line)
2680 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2682 # tracer type line: determine the trace data type
2683 m = re.match(sysvals.tracertypefmt, line)
2685 tp.setTracerType(m.group('t'))
2687 # device properties line
2688 if(re.match(sysvals.devpropfmt, line)):
2691 # ignore all other commented lines
2694 # ftrace line: parse only valid lines
2695 m = re.match(tp.ftrace_line_fmt, line)
2698 # gather the basic message data from the line
2699 m_time = m.group('time')
2700 m_proc = m.group('proc')
2701 m_pid = m.group('pid')
2702 m_msg = m.group('msg')
2704 m_param3 = m.group('dur')
2706 m_param3 = 'traceevent'
2707 if(m_time and m_pid and m_msg):
2708 t = FTraceLine(m_time, m_msg, m_param3)
2712 # the line should be a call, return, or event
2713 if(not t.fcall and not t.freturn and not t.fevent):
2715 # find the start of suspend
2716 if(t.startMarker()):
2717 phase = 'suspend_prepare'
2718 data = Data(len(testdata))
2719 testdata.append(data)
2720 testrun = TestRun(data)
2721 testruns.append(testrun)
2722 tp.parseStamp(data, sysvals)
2723 data.setStart(t.time)
2724 data.tKernSus = t.time
2728 # process cpu exec line
2729 if t.type == 'tracing_mark_write':
2730 m = re.match(sysvals.procexecfmt, t.name)
2733 for ps in m.group('ps').split(','):
2737 name = val[0].replace('--', '-')
2738 proclist[name] = int(val[1])
2739 data.pstl[t.time] = proclist
2741 # find the end of resume
2744 if data.tKernRes == 0.0:
2745 data.tKernRes = t.time
2746 if data.dmesg['resume_complete']['end'] < 0:
2747 data.dmesg['resume_complete']['end'] = t.time
2748 if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
2749 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2750 if(data.tSuspended != 0 and data.tResumed != 0 and \
2751 (data.fwSuspend > 0 or data.fwResume > 0)):
2753 if(not sysvals.usetracemarkers):
2754 # no trace markers? then quit and be sure to finish recording
2755 # the event we used to trigger resume end
2756 if(len(testrun.ttemp['thaw_processes']) > 0):
2757 # if an entry exists, assume this is its end
2758 testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2761 # trace event processing
2763 if(phase == 'post_resume'):
2765 if(t.type == 'suspend_resume'):
2766 # suspend_resume trace events have two types, begin and end
2767 if(re.match('(?P<name>.*) begin$', t.name)):
2769 elif(re.match('(?P<name>.*) end$', t.name)):
2773 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2775 val = m.group('val')
2777 name = m.group('name')
2779 name = m.group('name')+'['+val+']'
2781 m = re.match('(?P<name>.*) .*', t.name)
2782 name = m.group('name')
2783 # ignore these events
2784 if(name.split('[')[0] in tracewatch):
2786 # -- phase changes --
2787 # start of kernel suspend
2788 if(re.match('suspend_enter\[.*', t.name)):
2789 if(isbegin and data.start == data.tKernSus):
2790 data.dmesg[phase]['start'] = t.time
2791 data.tKernSus = t.time
2793 # suspend_prepare start
2794 elif(re.match('dpm_prepare\[.*', t.name)):
2795 phase = 'suspend_prepare'
2797 data.dmesg[phase]['end'] = t.time
2798 if data.dmesg[phase]['start'] < 0:
2799 data.dmesg[phase]['start'] = data.start
2802 elif(re.match('dpm_suspend\[.*', t.name)):
2804 data.setPhase(phase, t.time, isbegin)
2806 # suspend_late start
2807 elif(re.match('dpm_suspend_late\[.*', t.name)):
2808 phase = 'suspend_late'
2809 data.setPhase(phase, t.time, isbegin)
2811 # suspend_noirq start
2812 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2813 if data.phaseCollision('suspend_noirq', isbegin, line):
2815 phase = 'suspend_noirq'
2816 data.setPhase(phase, t.time, isbegin)
2818 phase = 'suspend_machine'
2819 data.dmesg[phase]['start'] = t.time
2821 # suspend_machine/resume_machine
2822 elif(re.match('machine_suspend\[.*', t.name)):
2824 phase = 'suspend_machine'
2825 data.dmesg[phase]['end'] = t.time
2826 data.tSuspended = t.time
2828 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
2829 data.dmesg['suspend_machine']['end'] = t.time
2830 data.tSuspended = t.time
2831 phase = 'resume_machine'
2832 data.dmesg[phase]['start'] = t.time
2833 data.tResumed = t.time
2834 data.tLow = data.tResumed - data.tSuspended
2837 elif(re.match('acpi_suspend\[.*', t.name)):
2838 # acpi_suspend[0] S0i3
2839 if(re.match('acpi_suspend\[0\] begin', t.name)):
2840 if(sysvals.suspendmode == 'mem'):
2842 data.dmesg['suspend_machine']['end'] = t.time
2843 data.tSuspended = t.time
2845 # resume_noirq start
2846 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2847 if data.phaseCollision('resume_noirq', isbegin, line):
2849 phase = 'resume_noirq'
2850 data.setPhase(phase, t.time, isbegin)
2852 data.dmesg['resume_machine']['end'] = t.time
2854 # resume_early start
2855 elif(re.match('dpm_resume_early\[.*', t.name)):
2856 phase = 'resume_early'
2857 data.setPhase(phase, t.time, isbegin)
2860 elif(re.match('dpm_resume\[.*', t.name)):
2862 data.setPhase(phase, t.time, isbegin)
2864 # resume complete start
2865 elif(re.match('dpm_complete\[.*', t.name)):
2866 phase = 'resume_complete'
2868 data.dmesg[phase]['start'] = t.time
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 elif(phase == 'post_resume'):
2885 # post resume events can just have ends
2886 testrun.ttemp[name].append({
2887 'begin': data.dmesg[phase]['start'],
2889 # device callback start
2890 elif(t.type == 'device_pm_callback_start'):
2891 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2895 drv = m.group('drv')
2899 data.newAction(phase, n, pid, p, t.time, -1, drv)
2900 if pid not in data.devpids:
2901 data.devpids.append(pid)
2902 # device callback finish
2903 elif(t.type == 'device_pm_callback_end'):
2904 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2908 list = data.dmesg[phase]['list']
2911 dev['length'] = t.time - dev['start']
2913 # kprobe event processing
2917 key = (kprobename, pid)
2918 # displayname is generated from kprobe data
2921 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2924 if(key not in tp.ktemp):
2926 tp.ktemp[key].append({
2930 'name': displayname,
2931 'cdata': kprobedata,
2935 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2937 e = tp.ktemp[key][-1]
2938 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2942 e['rdata'] = kprobedata
2943 # end of kernel resume
2944 if(kprobename == 'pm_notifier_call_chain' or \
2945 kprobename == 'pm_restore_console'):
2946 data.dmesg[phase]['end'] = t.time
2947 data.tKernRes = t.time
2949 # callgraph processing
2950 elif sysvals.usecallgraph:
2951 # create a callgraph object for the data
2953 if(key not in testrun.ftemp):
2954 testrun.ftemp[key] = []
2955 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
2956 # when the call is finished, see which device matches it
2957 cg = testrun.ftemp[key][-1]
2960 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
2962 testrun.ftemp[key][-1].addLine(t)
2965 if sysvals.suspendmode == 'command':
2966 for test in testruns:
2967 for p in test.data.phases:
2968 if p == 'suspend_prepare':
2969 test.data.dmesg[p]['start'] = test.data.start
2970 test.data.dmesg[p]['end'] = test.data.end
2972 test.data.dmesg[p]['start'] = test.data.end
2973 test.data.dmesg[p]['end'] = test.data.end
2974 test.data.tSuspended = test.data.end
2975 test.data.tResumed = test.data.end
2977 test.data.fwValid = False
2979 # dev source and procmon events can be unreadable with mixed phase height
2980 if sysvals.usedevsrc or sysvals.useprocmon:
2981 sysvals.mixedphaseheight = False
2983 for i in range(len(testruns)):
2986 # find the total time range for this test (begin, end)
2987 tlb, tle = data.start, data.end
2988 if i < len(testruns) - 1:
2989 tle = testruns[i+1].data.start
2990 # add the process usage data to the timeline
2991 if sysvals.useprocmon:
2992 data.createProcessUsageEvents()
2993 # add the traceevent data to the device hierarchy
2994 if(sysvals.usetraceevents):
2995 # add actual trace funcs
2996 for name in test.ttemp:
2997 for event in test.ttemp[name]:
2998 data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
2999 # add the kprobe based virtual tracefuncs as actual devices
3000 for key in tp.ktemp:
3002 if name not in sysvals.tracefuncs:
3004 for e in tp.ktemp[key]:
3005 kb, ke = e['begin'], e['end']
3006 if kb == ke or tlb > kb or tle <= kb:
3008 color = sysvals.kprobeColor(name)
3009 data.newActionGlobal(e['name'], kb, ke, pid, color)
3010 # add config base kprobes and dev kprobes
3011 if sysvals.usedevsrc:
3012 for key in tp.ktemp:
3014 if name in sysvals.tracefuncs or name not in sysvals.dev_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 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
3021 ke, e['cdata'], e['rdata'])
3022 if sysvals.usecallgraph:
3023 # add the callgraph data to the device hierarchy
3025 for key in test.ftemp:
3027 for cg in test.ftemp[key]:
3028 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
3030 if(not cg.postProcess()):
3031 id = 'task %s' % (pid)
3032 sysvals.vprint('Sanity check failed for '+\
3033 id+', ignoring this callback')
3035 # match cg data to devices
3037 if sysvals.suspendmode != 'command':
3038 devname = cg.deviceMatch(pid, data)
3040 sortkey = '%f%f%d' % (cg.start, cg.end, pid)
3041 sortlist[sortkey] = cg
3042 elif len(cg.list) > 1000000:
3043 print 'WARNING: the callgraph for %s is massive (%d lines)' %\
3044 (devname, len(cg.list))
3045 # create blocks for orphan cg data
3046 for sortkey in sorted(sortlist):
3047 cg = sortlist[sortkey]
3049 if sysvals.isCallgraphFunc(name):
3050 sysvals.vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
3051 cg.newActionFromFunction(data)
3052 if sysvals.suspendmode == 'command':
3053 return (testdata, '')
3055 # fill in any missing phases
3057 for data in testdata:
3058 tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))
3061 for p in data.phases:
3062 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
3064 print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)
3065 terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp)
3067 sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3068 if(data.dmesg[p]['start'] < 0):
3069 data.dmesg[p]['start'] = data.dmesg[lp]['end']
3070 if(p == 'resume_machine'):
3071 data.tSuspended = data.dmesg[lp]['end']
3072 data.tResumed = data.dmesg[lp]['end']
3074 if(data.dmesg[p]['end'] < 0):
3075 data.dmesg[p]['end'] = data.dmesg[p]['start']
3076 if(p != lp and not ('machine' in p and 'machine' in lp)):
3077 data.dmesg[lp]['end'] = data.dmesg[p]['start']
3080 if(len(sysvals.devicefilter) > 0):
3081 data.deviceFilter(sysvals.devicefilter)
3082 data.fixupInitcallsThatDidntReturn()
3083 if sysvals.usedevsrc:
3084 data.optimizeDevSrc()
3086 # x2: merge any overlapping devices between test runs
3087 if sysvals.usedevsrc and len(testdata) > 1:
3089 for i in range(tc - 1):
3090 devlist = testdata[i].overflowDevices()
3091 for j in range(i + 1, tc):
3092 testdata[j].mergeOverlapDevices(devlist)
3093 testdata[0].stitchTouchingThreads(testdata[1:])
3094 return (testdata, ', '.join(error))
3096 # Function: loadKernelLog
3098 # [deprecated for kernel 3.15.0 or newer]
3099 # load the dmesg file into memory and fix up any ordering issues
3100 # The dmesg filename is taken from sysvals
3102 # An array of empty Data objects with only their dmesgtext attributes set
3103 def loadKernelLog():
3104 sysvals.vprint('Analyzing the dmesg data (%s)...' % \
3105 os.path.basename(sysvals.dmesgfile))
3106 if(os.path.exists(sysvals.dmesgfile) == False):
3107 doError('%s does not exist' % sysvals.dmesgfile)
3109 # there can be multiple test runs in a single file
3111 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
3114 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
3116 line = line.replace('\r\n', '')
3117 idx = line.find('[')
3120 # grab the stamp and sysinfo
3121 if re.match(tp.stampfmt, line):
3124 elif re.match(tp.sysinfofmt, line):
3127 elif re.match(tp.cmdlinefmt, line):
3130 m = re.match(sysvals.firmwarefmt, line)
3132 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
3134 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
3137 msg = m.group("msg")
3138 if(re.match('PM: Syncing filesystems.*', msg)):
3140 testruns.append(data)
3141 data = Data(len(testruns))
3142 tp.parseStamp(data, sysvals)
3143 if len(tp.fwdata) > data.testnumber:
3144 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
3145 if(data.fwSuspend > 0 or data.fwResume > 0):
3149 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
3151 sysvals.stamp['kernel'] = m.group('k')
3152 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
3154 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')
3155 data.dmesgtext.append(line)
3159 testruns.append(data)
3160 if len(testruns) < 1:
3161 print('ERROR: dmesg log has no suspend/resume data: %s' \
3162 % sysvals.dmesgfile)
3164 # fix lines with same timestamp/function with the call and return swapped
3165 for data in testruns:
3167 for line in data.dmesgtext:
3168 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
3169 '(?P<f>.*)\+ @ .*, parent: .*', line)
3170 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
3171 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
3172 if(mc and mr and (mc.group('t') == mr.group('t')) and
3173 (mc.group('f') == mr.group('f'))):
3174 i = data.dmesgtext.index(last)
3175 j = data.dmesgtext.index(line)
3176 data.dmesgtext[i] = line
3177 data.dmesgtext[j] = last
3181 # Function: parseKernelLog
3183 # [deprecated for kernel 3.15.0 or newer]
3184 # Analyse a dmesg log output file generated from this app during
3185 # the execution phase. Create a set of device structures in memory
3186 # for subsequent formatting in the html output file
3187 # This call is only for legacy support on kernels where the ftrace
3188 # data lacks the suspend_resume or device_pm_callbacks trace events.
3190 # data: an empty Data object (with dmesgtext) obtained from loadKernelLog
3192 # The filled Data object
3193 def parseKernelLog(data):
3194 phase = 'suspend_runtime'
3197 sysvals.vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
3198 (data.fwSuspend, data.fwResume))
3200 # dmesg phase match table
3202 'suspend_prepare': 'PM: Syncing filesystems.*',
3203 'suspend': 'PM: Entering [a-z]* sleep.*',
3204 'suspend_late': 'PM: suspend of devices complete after.*',
3205 'suspend_noirq': 'PM: late suspend of devices complete after.*',
3206 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
3207 'resume_machine': 'ACPI: Low-level resume complete.*',
3208 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
3209 'resume_early': 'PM: noirq resume of devices complete after.*',
3210 'resume': 'PM: early resume of devices complete after.*',
3211 'resume_complete': 'PM: resume of devices complete after.*',
3212 'post_resume': '.*Restarting tasks \.\.\..*',
3214 if(sysvals.suspendmode == 'standby'):
3215 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
3216 elif(sysvals.suspendmode == 'disk'):
3217 dm['suspend_late'] = 'PM: freeze of devices complete after.*'
3218 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
3219 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
3220 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
3221 dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
3222 dm['resume'] = 'PM: early restore of devices complete after.*'
3223 dm['resume_complete'] = 'PM: restore of devices complete after.*'
3224 elif(sysvals.suspendmode == 'freeze'):
3225 dm['resume_machine'] = 'ACPI: resume from mwait'
3227 # action table (expected events that occur and show up in dmesg)
3229 'sync_filesystems': {
3230 'smsg': 'PM: Syncing filesystems.*',
3231 'emsg': 'PM: Preparing system for mem sleep.*' },
3232 'freeze_user_processes': {
3233 'smsg': 'Freezing user space processes .*',
3234 'emsg': 'Freezing remaining freezable tasks.*' },
3236 'smsg': 'Freezing remaining freezable tasks.*',
3237 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
3239 'smsg': 'ACPI: Preparing to enter system sleep state.*',
3240 'emsg': 'PM: Saving platform NVS memory.*' },
3242 'smsg': 'PM: Saving platform NVS memory.*',
3243 'emsg': 'Disabling non-boot CPUs .*' },
3250 for line in data.dmesgtext:
3251 # parse each dmesg line into the time and message
3252 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
3254 val = m.group('ktime')
3259 msg = m.group('msg')
3260 # initialize data start to first line time
3262 data.setStart(ktime)
3267 # hack for determining resume_machine end for freeze
3268 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
3269 and phase == 'resume_machine' and \
3270 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3271 data.dmesg['resume_machine']['end'] = ktime
3272 phase = 'resume_noirq'
3273 data.dmesg[phase]['start'] = ktime
3276 if(re.match(dm['suspend_prepare'], msg)):
3277 phase = 'suspend_prepare'
3278 data.dmesg[phase]['start'] = ktime
3279 data.setStart(ktime)
3280 data.tKernSus = ktime
3282 elif(re.match(dm['suspend'], msg)):
3283 data.dmesg['suspend_prepare']['end'] = ktime
3285 data.dmesg[phase]['start'] = ktime
3286 # suspend_late start
3287 elif(re.match(dm['suspend_late'], msg)):
3288 data.dmesg['suspend']['end'] = ktime
3289 phase = 'suspend_late'
3290 data.dmesg[phase]['start'] = ktime
3291 # suspend_noirq start
3292 elif(re.match(dm['suspend_noirq'], msg)):
3293 data.dmesg['suspend_late']['end'] = ktime
3294 phase = 'suspend_noirq'
3295 data.dmesg[phase]['start'] = ktime
3296 # suspend_machine start
3297 elif(re.match(dm['suspend_machine'], msg)):
3298 data.dmesg['suspend_noirq']['end'] = ktime
3299 phase = 'suspend_machine'
3300 data.dmesg[phase]['start'] = ktime
3301 # resume_machine start
3302 elif(re.match(dm['resume_machine'], msg)):
3303 if(sysvals.suspendmode in ['freeze', 'standby']):
3304 data.tSuspended = prevktime
3305 data.dmesg['suspend_machine']['end'] = prevktime
3307 data.tSuspended = ktime
3308 data.dmesg['suspend_machine']['end'] = ktime
3309 phase = 'resume_machine'
3310 data.tResumed = ktime
3311 data.tLow = data.tResumed - data.tSuspended
3312 data.dmesg[phase]['start'] = ktime
3313 # resume_noirq start
3314 elif(re.match(dm['resume_noirq'], msg)):
3315 data.dmesg['resume_machine']['end'] = ktime
3316 phase = 'resume_noirq'
3317 data.dmesg[phase]['start'] = ktime
3318 # resume_early start
3319 elif(re.match(dm['resume_early'], msg)):
3320 data.dmesg['resume_noirq']['end'] = ktime
3321 phase = 'resume_early'
3322 data.dmesg[phase]['start'] = ktime
3324 elif(re.match(dm['resume'], msg)):
3325 data.dmesg['resume_early']['end'] = ktime
3327 data.dmesg[phase]['start'] = ktime
3328 # resume complete start
3329 elif(re.match(dm['resume_complete'], msg)):
3330 data.dmesg['resume']['end'] = ktime
3331 phase = 'resume_complete'
3332 data.dmesg[phase]['start'] = ktime
3334 elif(re.match(dm['post_resume'], msg)):
3335 data.dmesg['resume_complete']['end'] = ktime
3337 data.tKernRes = ktime
3340 # -- device callbacks --
3341 if(phase in data.phases):
3343 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3344 sm = re.match('calling (?P<f>.*)\+ @ '+\
3345 '(?P<n>.*), parent: (?P<p>.*)', msg);
3350 data.newAction(phase, f, int(n), p, ktime, -1, '')
3351 # device init return
3352 elif(re.match('call (?P<f>.*)\+ returned .* after '+\
3353 '(?P<t>.*) usecs', msg)):
3354 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
3355 '(?P<t>.*) usecs(?P<a>.*)', msg);
3358 list = data.dmesg[phase]['list']
3361 dev['length'] = int(t)
3364 # if trace events are not available, these are better than nothing
3365 if(not sysvals.usetraceevents):
3366 # look for known actions
3368 if(re.match(at[a]['smsg'], msg)):
3369 if(a not in actions):
3371 actions[a].append({'begin': ktime, 'end': ktime})
3372 if(re.match(at[a]['emsg'], msg)):
3374 actions[a][-1]['end'] = ktime
3375 # now look for CPU on/off events
3376 if(re.match('Disabling non-boot CPUs .*', msg)):
3377 # start of first cpu suspend
3379 elif(re.match('Enabling non-boot CPUs .*', msg)):
3380 # start of first cpu resume
3382 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
3383 # end of a cpu suspend, start of the next
3384 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
3385 cpu = 'CPU'+m.group('cpu')
3386 if(cpu not in actions):
3388 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3390 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
3391 # end of a cpu resume, start of the next
3392 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
3393 cpu = 'CPU'+m.group('cpu')
3394 if(cpu not in actions):
3396 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3400 # fill in any missing phases
3402 for p in data.phases:
3403 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
3404 print('WARNING: phase "%s" is missing, something went wrong!' % p)
3405 print(' In %s, this dmesg line denotes the start of %s:' % \
3406 (sysvals.suspendmode, p))
3407 print(' "%s"' % dm[p])
3408 if(data.dmesg[p]['start'] < 0):
3409 data.dmesg[p]['start'] = data.dmesg[lp]['end']
3410 if(p == 'resume_machine'):
3411 data.tSuspended = data.dmesg[lp]['end']
3412 data.tResumed = data.dmesg[lp]['end']
3414 if(data.dmesg[p]['end'] < 0):
3415 data.dmesg[p]['end'] = data.dmesg[p]['start']
3418 # fill in any actions we've found
3419 for name in actions:
3420 for event in actions[name]:
3421 data.newActionGlobal(name, event['begin'], event['end'])
3423 if(len(sysvals.devicefilter) > 0):
3424 data.deviceFilter(sysvals.devicefilter)
3425 data.fixupInitcallsThatDidntReturn()
3428 def callgraphHTML(sv, hf, num, cg, title, color, devid):
3429 html_func_top = '<article id="{0}" class="atop" style="background:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
3430 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
3431 html_func_end = '</article>\n'
3432 html_func_leaf = '<article>{0} {1}</article>\n'
3437 cglen = (cg.end - cg.start) * 1000
3438 if cglen < sv.mincglen:
3441 fmt = '<r>(%.3f ms @ '+sv.timeformat+' to '+sv.timeformat+')</r>'
3442 flen = fmt % (cglen, cg.start, cg.end)
3443 hf.write(html_func_top.format(cgid, color, num, title, flen))
3445 for line in cg.list:
3446 if(line.length < 0.000000001):
3449 fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'
3450 flen = fmt % (line.length*1000, line.time)
3452 hf.write(html_func_leaf.format(line.name, flen))
3454 hf.write(html_func_end)
3456 hf.write(html_func_start.format(num, line.name, flen))
3458 hf.write(html_func_end)
3461 def addCallgraphs(sv, hf, data):
3462 hf.write('<section id="callgraphs" class="callgraph">\n')
3463 # write out the ftrace data converted to html
3465 for p in data.phases:
3466 if sv.cgphase and p != sv.cgphase:
3468 list = data.dmesg[p]['list']
3469 for devname in data.sortedDevices(p):
3470 if len(sv.cgfilter) > 0 and devname not in sv.cgfilter:
3474 if 'color' in data.dmesg[p]:
3475 color = data.dmesg[p]['color']
3477 color = dev['color']
3479 if(devname in sv.devprops):
3480 name = sv.devprops[devname].altName(devname)
3481 if sv.suspendmode in suspendmodename:
3483 if('ftrace' in dev):
3485 num = callgraphHTML(sv, hf, num, cg,
3486 name, color, dev['id'])
3487 if('ftraces' in dev):
3488 for cg in dev['ftraces']:
3489 num = callgraphHTML(sv, hf, num, cg,
3490 name+' → '+cg.name, color, dev['id'])
3491 hf.write('\n\n </section>\n')
3493 # Function: createHTMLSummarySimple
3495 # Create summary html file for a series of tests
3497 # testruns: array of Data objects from parseTraceLog
3498 def createHTMLSummarySimple(testruns, htmlfile, folder):
3499 # write the html header first (html head, css code, up to body start)
3500 html = '<!DOCTYPE html>\n<html>\n<head>\n\
3501 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3502 <title>SleepGraph Summary</title>\n\
3503 <style type=\'text/css\'>\n\
3504 .stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\
3505 table {width:100%;border-collapse: collapse;}\n\
3506 .summary {border:1px solid;}\n\
3507 th {border: 1px solid black;background:#222;color:white;}\n\
3508 td {font: 16px "Times New Roman";text-align: center;}\n\
3509 tr.head td {border: 1px solid black;background:#aaa;}\n\
3510 tr.alt {background-color:#ddd;}\n\
3511 tr.notice {color:red;}\n\
3512 .minval {background-color:#BBFFBB;}\n\
3513 .medval {background-color:#BBBBFF;}\n\
3514 .maxval {background-color:#FFBBBB;}\n\
3515 .head a {color:#000;text-decoration: none;}\n\
3516 </style>\n</head>\n<body>\n'
3518 # extract the test data into list
3520 tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
3521 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3524 cnt = {'pass':0, 'fail':0, 'hang':0}
3525 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
3527 if mode not in list:
3528 list[mode] = {'data': [], 'avg': [0,0], 'min': [0,0], 'max': [0,0], 'med': [0,0]}
3529 if lastmode and lastmode != mode and num > 0:
3532 list[lastmode]['med'][i] = s[int(len(s)/2)]
3533 iMed[i] = tMed[i].index(list[lastmode]['med'][i])
3534 list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
3535 list[lastmode]['min'] = tMin
3536 list[lastmode]['max'] = tMax
3537 list[lastmode]['idx'] = (iMin, iMed, iMax)
3538 tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
3539 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3541 tVal = [float(data['suspend']), float(data['resume'])]
3542 list[mode]['data'].append([data['host'], data['kernel'],
3543 data['time'], tVal[0], tVal[1], data['url'], data['result'],
3545 idx = len(list[mode]['data']) - 1
3546 if data['result'] == 'pass':
3549 tMed[i].append(tVal[i])
3551 if tMin[i] == 0 or tVal[i] < tMin[i]:
3554 if tMax[i] == 0 or tVal[i] > tMax[i]:
3558 elif data['result'] == 'hang':
3560 elif data['result'] == 'fail':
3563 if lastmode and num > 0:
3566 list[lastmode]['med'][i] = s[int(len(s)/2)]
3567 iMed[i] = tMed[i].index(list[lastmode]['med'][i])
3568 list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
3569 list[lastmode]['min'] = tMin
3570 list[lastmode]['max'] = tMax
3571 list[lastmode]['idx'] = (iMin, iMed, iMax)
3575 for ilk in sorted(cnt, reverse=True):
3577 desc.append('%d %s' % (cnt[ilk], ilk))
3578 html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (folder, len(testruns), ', '.join(desc))
3579 th = '\t<th>{0}</th>\n'
3580 td = '\t<td>{0}</td>\n'
3581 tdh = '\t<td{1}>{0}</td>\n'
3582 tdlink = '\t<td><a href="{0}">html</a></td>\n'
3585 html += '<table class="summary">\n<tr>\n' + th.format('#') +\
3586 th.format('Mode') + th.format('Host') + th.format('Kernel') +\
3587 th.format('Test Time') + th.format('Result') + th.format('Issues') +\
3588 th.format('Suspend') + th.format('Resume') + th.format('Detail') + '</tr>\n'
3590 # export list into html
3591 head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\
3592 '<td colspan=8 class="sus">Suspend Avg={2} '+\
3593 '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\
3594 '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\
3595 '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\
3597 '<span class=minval><a href="#r{10}min">Min={7}</a></span> '+\
3598 '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\
3599 '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\
3601 headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=8></td></tr>\n'
3603 # header line for each suspend mode
3605 tAvg, tMin, tMax, tMed = list[mode]['avg'], list[mode]['min'],\
3606 list[mode]['max'], list[mode]['med']
3607 count = len(list[mode]['data'])
3608 if 'idx' in list[mode]:
3609 iMin, iMed, iMax = list[mode]['idx']
3610 html += head.format('%d' % count, mode.upper(),
3611 '%.3f' % tAvg[0], '%.3f' % tMin[0], '%.3f' % tMed[0], '%.3f' % tMax[0],
3612 '%.3f' % tAvg[1], '%.3f' % tMin[1], '%.3f' % tMed[1], '%.3f' % tMax[1],
3616 iMin = iMed = iMax = [-1, -1, -1]
3617 html += headnone.format('%d' % count, mode.upper())
3618 for d in list[mode]['data']:
3619 # row classes - alternate row color
3620 rcls = ['alt'] if num % 2 == 1 else []
3622 rcls.append('notice')
3623 html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
3624 # figure out if the line has sus or res highlighted
3625 idx = list[mode]['data'].index(d)
3628 tag = 's%s' % mode if i == 0 else 'r%s' % mode
3630 tHigh[i] = ' id="%smin" class=minval title="Minimum"' % tag
3631 elif idx == iMax[i]:
3632 tHigh[i] = ' id="%smax" class=maxval title="Maximum"' % tag
3633 elif idx == iMed[i]:
3634 tHigh[i] = ' id="%smed" class=medval title="Median"' % tag
3635 html += td.format("%d" % (list[mode]['data'].index(d) + 1)) # row
3636 html += td.format(mode) # mode
3637 html += td.format(d[0]) # host
3638 html += td.format(d[1]) # kernel
3639 html += td.format(d[2]) # time
3640 html += td.format(d[6]) # result
3641 html += td.format(d[7]) # issues
3642 html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend
3643 html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume
3644 html += tdlink.format(d[5]) if d[5] else td.format('') # url
3648 # flush the data to file
3649 hf = open(htmlfile, 'w')
3650 hf.write(html+'</table>\n</body>\n</html>\n')
3655 if value < 10 or value > 19:
3658 elif value % 10 == 2:
3660 elif value % 10 == 3:
3662 return '%d%s' % (value, suffix)
3664 # Function: createHTML
3666 # Create the output html file from the resident test data
3668 # testruns: array of Data objects from parseKernelLog or parseTraceLog
3670 # True if the html file was created, false if it failed
3671 def createHTML(testruns, testfail):
3672 if len(testruns) < 1:
3673 print('ERROR: Not enough test data to build a timeline')
3677 for data in testruns:
3680 data.normalizeTime(testruns[-1].tSuspended)
3682 # html function templates
3683 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</div>\n'
3684 html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n'
3685 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
3686 html_timetotal = '<table class="time1">\n<tr>'\
3687 '<td class="green" title="{3}">{2} Suspend Time: <b>{0} ms</b></td>'\
3688 '<td class="yellow" title="{4}">{2} Resume Time: <b>{1} ms</b></td>'\
3690 html_timetotal2 = '<table class="time1">\n<tr>'\
3691 '<td class="green" title="{4}">{3} Suspend Time: <b>{0} ms</b></td>'\
3692 '<td class="gray" title="time spent in low-power mode with clock running">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
3693 '<td class="yellow" title="{5}">{3} Resume Time: <b>{2} ms</b></td>'\
3695 html_timetotal3 = '<table class="time1">\n<tr>'\
3696 '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3697 '<td class="yellow">Command: <b>{1}</b></td>'\
3699 html_timegroups = '<table class="time2">\n<tr>'\
3700 '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\
3701 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3702 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
3703 '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\
3705 html_fail = '<table class="testfail"><tr><td>{0}</td></tr></table>\n'
3707 # html format variables
3713 devtl = Timeline(30, scaleH)
3715 # write the test title and general info header
3716 devtl.createHeader(sysvals, testruns[0].stamp)
3718 # Generate the header for this timeline
3719 for data in testruns:
3720 tTotal = data.end - data.start
3721 sktime, rktime = data.getTimeValues()
3723 doError('No timeline data')
3725 low_time = '%.0f'%(data.tLow*1000)
3726 if sysvals.suspendmode == 'command':
3727 run_time = '%.0f'%((data.end-data.start)*1000)
3728 if sysvals.testcommand:
3729 testdesc = sysvals.testcommand
3731 testdesc = 'unknown'
3732 if(len(testruns) > 1):
3733 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3734 thtml = html_timetotal3.format(run_time, testdesc)
3737 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3738 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
3741 stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode
3742 rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode
3743 if(len(testruns) > 1):
3744 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3747 thtml = html_timetotal.format(suspend_time, \
3748 resume_time, testdesc1, stitle, rtitle)
3750 thtml = html_timetotal2.format(suspend_time, low_time, \
3751 resume_time, testdesc1, stitle, rtitle)
3753 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3754 rftime = '%.3f'%(data.fwResume / 1000000.0)
3755 devtl.html += html_timegroups.format('%.3f'%sktime, \
3756 sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode)
3758 suspend_time = '%.3f' % sktime
3759 resume_time = '%.3f' % rktime
3761 stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode
3762 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode
3763 if(len(testruns) > 1):
3764 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3766 thtml = html_timetotal.format(suspend_time, \
3767 resume_time, testdesc, stitle, rtitle)
3769 thtml = html_timetotal2.format(suspend_time, low_time, \
3770 resume_time, testdesc, stitle, rtitle)
3774 devtl.html += html_fail.format(testfail)
3776 # time scale for potentially multiple datasets
3777 t0 = testruns[0].start
3778 tMax = testruns[-1].end
3781 # determine the maximum number of rows we need to draw
3786 for data in testruns:
3787 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
3788 for group in data.devicegroups:
3791 for devname in data.tdevlist[phase]:
3792 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3795 threadlist.append(d)
3802 if sysvals.mixedphaseheight:
3803 devtl.getPhaseRows(devlist)
3804 if not sysvals.mixedphaseheight:
3805 if len(threadlist) > 0 and len(fulllist) > 0:
3806 if pscnt > 0 and devcnt > 0:
3807 msg = 'user processes & device pm callbacks'
3809 msg = 'user processes'
3811 msg = 'device pm callbacks'
3812 d = testruns[0].addHorizontalDivider(msg, testruns[-1].end)
3813 fulllist.insert(0, d)
3814 devtl.getPhaseRows(fulllist)
3815 if len(threadlist) > 0:
3816 d = testruns[0].addHorizontalDivider('asynchronous kernel threads', testruns[-1].end)
3817 threadlist.insert(0, d)
3818 devtl.getPhaseRows(threadlist, devtl.rows)
3819 devtl.calcTotalRows()
3821 # draw the full timeline
3822 devtl.createZoomBox(sysvals.suspendmode, len(testruns))
3823 phases = {'suspend':[],'resume':[]}
3824 for phase in data.dmesg:
3825 if 'resume' in phase:
3826 phases['resume'].append(phase)
3828 phases['suspend'].append(phase)
3830 # draw each test run chronologically
3831 for data in testruns:
3832 # now draw the actual timeline blocks
3834 # draw suspend and resume blocks separately
3835 bname = '%s%d' % (dir[0], data.testnumber)
3836 if dir == 'suspend':
3838 mMax = data.tSuspended
3839 left = '%f' % (((m0-t0)*100.0)/tTotal)
3841 m0 = data.tSuspended
3843 # in an x2 run, remove any gap between blocks
3844 if len(testruns) > 1 and data.testnumber == 0:
3845 mMax = testruns[1].start
3846 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
3848 # if a timeline block is 0 length, skip altogether
3851 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3852 devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)
3853 for b in sorted(phases[dir]):
3854 # draw the phase color background
3855 phase = data.dmesg[b]
3856 length = phase['end']-phase['start']
3857 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
3858 width = '%f' % ((length*100.0)/mTotal)
3859 devtl.html += devtl.html_phase.format(left, width, \
3860 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
3861 data.dmesg[b]['color'], '')
3862 for e in data.errorinfo[dir]:
3863 # draw red lines for any kernel errors found
3864 type, t, idx1, idx2 = e
3865 id = '%d_%d' % (idx1, idx2)
3866 right = '%f' % (((mMax-t)*100.0)/mTotal)
3867 devtl.html += html_error.format(right, id, type)
3868 for b in sorted(phases[dir]):
3869 # draw the devices for this phase
3870 phaselist = data.dmesg[b]['list']
3871 for d in data.tdevlist[b]:
3878 if 'htmlclass' in dev:
3879 xtraclass = dev['htmlclass']
3881 xtrastyle = 'background:%s;' % dev['color']
3882 if(d in sysvals.devprops):
3883 name = sysvals.devprops[d].altName(d)
3884 xtraclass = sysvals.devprops[d].xtraClass()
3885 xtrainfo = sysvals.devprops[d].xtraInfo()
3886 elif xtraclass == ' kth':
3887 xtrainfo = ' kernel_thread'
3888 if('drv' in dev and dev['drv']):
3889 drv = ' {%s}' % dev['drv']
3890 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row'])
3891 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row'])
3892 top = '%.3f' % (rowtop + devtl.scaleH)
3893 left = '%f' % (((dev['start']-m0)*100)/mTotal)
3894 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
3895 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
3896 title = name+drv+xtrainfo+length
3897 if sysvals.suspendmode == 'command':
3898 title += sysvals.testcommand
3899 elif xtraclass == ' ps':
3901 title += 'pre_suspend_process'
3903 title += 'post_resume_process'
3906 devtl.html += devtl.html_device.format(dev['id'], \
3907 title, left, top, '%.3f'%rowheight, width, \
3908 d+drv, xtraclass, xtrastyle)
3909 if('cpuexec' in dev):
3910 for t in sorted(dev['cpuexec']):
3912 j = float(dev['cpuexec'][t]) / 5
3915 height = '%.3f' % (rowheight/3)
3916 top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3)
3917 left = '%f' % (((start-m0)*100)/mTotal)
3918 width = '%f' % ((end-start)*100/mTotal)
3919 color = 'rgba(255, 0, 0, %f)' % j
3921 html_cpuexec.format(left, top, height, width, color)
3922 if('src' not in dev):
3924 # draw any trace events for this device
3925 for e in dev['src']:
3926 height = '%.3f' % devtl.rowH
3927 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
3928 left = '%f' % (((e.time-m0)*100)/mTotal)
3929 width = '%f' % (e.length*100/mTotal)
3932 xtrastyle = 'background:%s;' % e.color
3934 html_traceevent.format(e.title(), \
3935 left, top, height, width, e.text(), '', xtrastyle)
3936 # draw the time scale, try to make the number of labels readable
3937 devtl.createTimeScale(m0, mMax, tTotal, dir)
3938 devtl.html += '</div>\n'
3940 # timeline is finished
3941 devtl.html += '</div>\n</div>\n'
3943 # draw a legend which describes the phases by color
3944 if sysvals.suspendmode != 'command':
3946 devtl.html += '<div class="legend">\n'
3947 pdelta = 100.0/len(data.phases)
3948 pmargin = pdelta / 4.0
3949 for phase in data.phases:
3950 tmp = phase.split('_')
3954 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3955 name = string.replace(phase, '_', ' ')
3956 devtl.html += devtl.html_legend.format(order, \
3957 data.dmesg[phase]['color'], name, id)
3958 devtl.html += '</div>\n'
3960 hf = open(sysvals.htmlfile, 'w')
3961 addCSS(hf, sysvals, len(testruns), kerror)
3963 # write the device timeline
3964 hf.write(devtl.html)
3965 hf.write('<div id="devicedetailtitle"></div>\n')
3966 hf.write('<div id="devicedetail" style="display:none;">\n')
3967 # draw the colored boxes for the device detail section
3968 for data in testruns:
3969 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
3970 pscolor = 'linear-gradient(to top left, #ccc, #eee)'
3971 hf.write(devtl.html_phaselet.format('pre_suspend_process', \
3973 for b in data.phases:
3974 phase = data.dmesg[b]
3975 length = phase['end']-phase['start']
3976 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
3977 width = '%.3f' % ((length*100.0)/tTotal)
3978 hf.write(devtl.html_phaselet.format(b, left, width, \
3979 data.dmesg[b]['color']))
3980 hf.write(devtl.html_phaselet.format('post_resume_process', \
3982 if sysvals.suspendmode == 'command':
3983 hf.write(devtl.html_phaselet.format('cmdexec', '0', '0', pscolor))
3984 hf.write('</div>\n')
3985 hf.write('</div>\n')
3987 # write the ftrace data (callgraph)
3988 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
3989 data = testruns[sysvals.cgtest]
3992 if sysvals.usecallgraph:
3993 addCallgraphs(sysvals, hf, data)
3995 # add the test log as a hidden div
3996 if sysvals.testlog and sysvals.logmsg:
3997 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
3998 # add the dmesg log as a hidden div
3999 if sysvals.dmesglog and sysvals.dmesgfile:
4000 hf.write('<div id="dmesglog" style="display:none;">\n')
4001 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
4003 line = line.replace('<', '<').replace('>', '>')
4006 hf.write('</div>\n')
4007 # add the ftrace log as a hidden div
4008 if sysvals.ftracelog and sysvals.ftracefile:
4009 hf.write('<div id="ftracelog" style="display:none;">\n')
4010 lf = sysvals.openlog(sysvals.ftracefile, 'r')
4014 hf.write('</div>\n')
4016 # write the footer and close
4017 addScriptCode(hf, testruns)
4018 hf.write('</body>\n</html>\n')
4022 def addCSS(hf, sv, testcount=1, kerror=False, extra=''):
4023 kernel = sv.stamp['kernel']
4024 host = sv.hostname[0].upper()+sv.hostname[1:]
4025 mode = sv.suspendmode
4026 if sv.suspendmode in suspendmodename:
4027 mode = suspendmodename[sv.suspendmode]
4028 title = host+' '+mode+' '+kernel
4030 # various format changes by flags
4032 cgnchk = 'not(:checked)'
4034 cgchk = 'not(:checked)'
4037 hoverZ = 'z-index:8;'
4041 devlistpos = 'absolute'
4043 devlistpos = 'relative'
4049 # write the html header first (html head, css code, up to body start)
4050 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
4051 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
4052 <title>'+title+'</title>\n\
4053 <style type=\'text/css\'>\n\
4054 body {overflow-y:scroll;}\n\
4055 .stamp {width:100%;text-align:center;background:gray;line-height:30px;color:white;font:25px Arial;}\n\
4056 .stamp.sysinfo {font:10px Arial;}\n\
4057 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
4058 .callgraph article * {padding-left:28px;}\n\
4059 h1 {color:black;font:bold 30px Times;}\n\
4060 t0 {color:black;font:bold 30px Times;}\n\
4061 t1 {color:black;font:30px Times;}\n\
4062 t2 {color:black;font:25px Times;}\n\
4063 t3 {color:black;font:20px Times;white-space:nowrap;}\n\
4064 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
4065 cS {font:bold 13px Times;}\n\
4066 table {width:100%;}\n\
4067 .gray {background:rgba(80,80,80,0.1);}\n\
4068 .green {background:rgba(204,255,204,0.4);}\n\
4069 .purple {background:rgba(128,0,128,0.2);}\n\
4070 .yellow {background:rgba(255,255,204,0.4);}\n\
4071 .blue {background:rgba(169,208,245,0.4);}\n\
4072 .time1 {font:22px Arial;border:1px solid;}\n\
4073 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
4074 .testfail {font:bold 22px Arial;color:red;border:1px dashed;}\n\
4075 td {text-align:center;}\n\
4076 r {color:#500000;font:15px Tahoma;}\n\
4077 n {color:#505050;font:15px Tahoma;}\n\
4078 .tdhl {color:red;}\n\
4079 .hide {display:none;}\n\
4080 .pf {display:none;}\n\
4081 .pf:'+cgchk+' + label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
4082 .pf:'+cgnchk+' ~ label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
4083 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
4084 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\
4085 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
4086 .thread {position:absolute;height:0%;overflow:hidden;z-index:7;line-height:30px;font-size:14px;border:1px solid;text-align:center;white-space:nowrap;}\n\
4087 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\
4088 .thread:hover {background:white;border:1px solid red;'+hoverZ+'}\n\
4089 .thread.sec,.thread.sec:hover {background:black;border:0;color:white;line-height:15px;font-size:10px;}\n\
4090 .hover {background:white;border:1px solid red;'+hoverZ+'}\n\
4091 .hover.sync {background:white;}\n\
4092 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background:white;}\n\
4093 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\
4094 .traceevent {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
4095 .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\
4096 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
4097 .phaselet {float:left;overflow:hidden;border:0px;text-align:center;min-height:100px;font-size:24px;}\n\
4098 .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\
4099 .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\
4100 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
4101 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
4102 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
4103 .btnfmt {position:relative;float:right;height:25px;width:auto;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
4104 .devlist {position:'+devlistpos+';width:190px;}\n\
4105 a:link {color:white;text-decoration:none;}\n\
4106 a:visited {color:white;}\n\
4107 a:hover {color:white;}\n\
4108 a:active {color:white;}\n\
4109 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
4110 #devicedetail {min-height:100px;box-shadow:5px 5px 20px black;}\n\
4111 .tblock {position:absolute;height:100%;background:#ddd;}\n\
4112 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\
4115 </style>\n</head>\n<body>\n'
4116 hf.write(html_header)
4118 # Function: addScriptCode
4120 # Adds the javascript code to the output html
4122 # hf: the open html file pointer
4123 # testruns: array of Data objects from parseKernelLog or parseTraceLog
4124 def addScriptCode(hf, testruns):
4125 t0 = testruns[0].start * 1000
4126 tMax = testruns[-1].end * 1000
4127 # create an array in javascript memory with the device details
4128 detail = ' var devtable = [];\n'
4129 for data in testruns:
4130 topo = data.deviceTopology()
4131 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
4132 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
4133 # add the code which will manipulate the data in the browser
4135 '<script type="text/javascript">\n'+detail+\
4136 ' var resolution = -1;\n'\
4137 ' var dragval = [0, 0];\n'\
4138 ' function redrawTimescale(t0, tMax, tS) {\n'\
4139 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;">\';\n'\
4140 ' var tTotal = tMax - t0;\n'\
4141 ' var list = document.getElementsByClassName("tblock");\n'\
4142 ' for (var i = 0; i < list.length; i++) {\n'\
4143 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
4144 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
4145 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
4146 ' var mMax = m0 + mTotal;\n'\
4147 ' var html = "";\n'\
4148 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
4149 ' if(divTotal > 1000) continue;\n'\
4150 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
4151 ' var pos = 0.0, val = 0.0;\n'\
4152 ' for (var j = 0; j < divTotal; j++) {\n'\
4153 ' var htmlline = "";\n'\
4154 ' var mode = list[i].id[5];\n'\
4155 ' if(mode == "s") {\n'\
4156 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
4157 ' val = (j-divTotal+1)*tS;\n'\
4158 ' if(j == divTotal - 1)\n'\
4159 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S→</cS></div>\';\n'\
4161 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
4163 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
4165 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
4167 ' if(mode == "r")\n'\
4168 ' htmlline = rline+"<cS>←R</cS></div>";\n'\
4170 ' htmlline = rline+"<cS>0ms</div>";\n'\
4172 ' html += htmlline;\n'\
4174 ' timescale.innerHTML = html;\n'\
4177 ' function zoomTimeline() {\n'\
4178 ' var dmesg = document.getElementById("dmesg");\n'\
4179 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4180 ' var left = zoombox.scrollLeft;\n'\
4181 ' var val = parseFloat(dmesg.style.width);\n'\
4182 ' var newval = 100;\n'\
4183 ' var sh = window.outerWidth / 2;\n'\
4184 ' if(this.id == "zoomin") {\n'\
4185 ' newval = val * 1.2;\n'\
4186 ' if(newval > 910034) newval = 910034;\n'\
4187 ' dmesg.style.width = newval+"%";\n'\
4188 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
4189 ' } else if (this.id == "zoomout") {\n'\
4190 ' newval = val / 1.2;\n'\
4191 ' if(newval < 100) newval = 100;\n'\
4192 ' dmesg.style.width = newval+"%";\n'\
4193 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
4195 ' zoombox.scrollLeft = 0;\n'\
4196 ' dmesg.style.width = "100%";\n'\
4198 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
4199 ' var t0 = bounds[0];\n'\
4200 ' var tMax = bounds[1];\n'\
4201 ' var tTotal = tMax - t0;\n'\
4202 ' var wTotal = tTotal * 100.0 / newval;\n'\
4203 ' var idx = 7*window.innerWidth/1100;\n'\
4204 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
4205 ' if(i >= tS.length) i = tS.length - 1;\n'\
4206 ' if(tS[i] == resolution) return;\n'\
4207 ' resolution = tS[i];\n'\
4208 ' redrawTimescale(t0, tMax, tS[i]);\n'\
4210 ' function deviceName(title) {\n'\
4211 ' var name = title.slice(0, title.indexOf(" ("));\n'\
4214 ' function deviceHover() {\n'\
4215 ' var name = deviceName(this.title);\n'\
4216 ' var dmesg = document.getElementById("dmesg");\n'\
4217 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4219 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
4220 ' cpu = parseInt(name.slice(7));\n'\
4221 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
4222 ' cpu = parseInt(name.slice(8));\n'\
4223 ' for (var i = 0; i < dev.length; i++) {\n'\
4224 ' dname = deviceName(dev[i].title);\n'\
4225 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
4226 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
4227 ' (name == dname))\n'\
4229 ' dev[i].className = "hover "+cname;\n'\
4231 ' dev[i].className = cname;\n'\
4235 ' function deviceUnhover() {\n'\
4236 ' var dmesg = document.getElementById("dmesg");\n'\
4237 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4238 ' for (var i = 0; i < dev.length; i++) {\n'\
4239 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
4242 ' function deviceTitle(title, total, cpu) {\n'\
4243 ' var prefix = "Total";\n'\
4244 ' if(total.length > 3) {\n'\
4245 ' prefix = "Average";\n'\
4246 ' total[1] = (total[1]+total[3])/2;\n'\
4247 ' total[2] = (total[2]+total[4])/2;\n'\
4249 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
4250 ' var name = deviceName(title);\n'\
4251 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
4252 ' var driver = "";\n'\
4253 ' var tS = "<t2>(</t2>";\n'\
4254 ' var tR = "<t2>)</t2>";\n'\
4255 ' if(total[1] > 0)\n'\
4256 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
4257 ' if(total[2] > 0)\n'\
4258 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
4259 ' var s = title.indexOf("{");\n'\
4260 ' var e = title.indexOf("}");\n'\
4261 ' if((s >= 0) && (e >= 0))\n'\
4262 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
4263 ' if(total[1] > 0 && total[2] > 0)\n'\
4264 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
4266 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
4269 ' function deviceDetail() {\n'\
4270 ' var devinfo = document.getElementById("devicedetail");\n'\
4271 ' devinfo.style.display = "block";\n'\
4272 ' var name = deviceName(this.title);\n'\
4274 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
4275 ' cpu = parseInt(name.slice(7));\n'\
4276 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
4277 ' cpu = parseInt(name.slice(8));\n'\
4278 ' var dmesg = document.getElementById("dmesg");\n'\
4279 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4280 ' var idlist = [];\n'\
4281 ' var pdata = [[]];\n'\
4282 ' if(document.getElementById("devicedetail1"))\n'\
4283 ' pdata = [[], []];\n'\
4284 ' var pd = pdata[0];\n'\
4285 ' var total = [0.0, 0.0, 0.0];\n'\
4286 ' for (var i = 0; i < dev.length; i++) {\n'\
4287 ' dname = deviceName(dev[i].title);\n'\
4288 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
4289 ' (name == dname))\n'\
4291 ' idlist[idlist.length] = dev[i].id;\n'\
4293 ' if(dev[i].id[0] == "a") {\n'\
4294 ' pd = pdata[0];\n'\
4296 ' if(pdata.length == 1) pdata[1] = [];\n'\
4297 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
4298 ' pd = pdata[1];\n'\
4301 ' var info = dev[i].title.split(" ");\n'\
4302 ' var pname = info[info.length-1];\n'\
4303 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
4304 ' total[0] += pd[pname];\n'\
4305 ' if(pname.indexOf("suspend") >= 0)\n'\
4306 ' total[tidx] += pd[pname];\n'\
4308 ' total[tidx+1] += pd[pname];\n'\
4311 ' var devname = deviceTitle(this.title, total, cpu);\n'\
4312 ' var left = 0.0;\n'\
4313 ' for (var t = 0; t < pdata.length; t++) {\n'\
4314 ' pd = pdata[t];\n'\
4315 ' devinfo = document.getElementById("devicedetail"+t);\n'\
4316 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
4317 ' for (var i = 0; i < phases.length; i++) {\n'\
4318 ' if(phases[i].id in pd) {\n'\
4319 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
4321 ' if(w < 8) fs = 4*w | 0;\n'\
4322 ' var fs2 = fs*3/4;\n'\
4323 ' phases[i].style.width = w+"%";\n'\
4324 ' phases[i].style.left = left+"%";\n'\
4325 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
4327 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
4328 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\
4329 ' phases[i].innerHTML = time+pname;\n'\
4331 ' phases[i].style.width = "0%";\n'\
4332 ' phases[i].style.left = left+"%";\n'\
4336 ' if(typeof devstats !== \'undefined\')\n'\
4337 ' callDetail(this.id, this.title);\n'\
4338 ' var cglist = document.getElementById("callgraphs");\n'\
4339 ' if(!cglist) return;\n'\
4340 ' var cg = cglist.getElementsByClassName("atop");\n'\
4341 ' if(cg.length < 10) return;\n'\
4342 ' for (var i = 0; i < cg.length; i++) {\n'\
4343 ' cgid = cg[i].id.split("x")[0]\n'\
4344 ' if(idlist.indexOf(cgid) >= 0) {\n'\
4345 ' cg[i].style.display = "block";\n'\
4347 ' cg[i].style.display = "none";\n'\
4351 ' function callDetail(devid, devtitle) {\n'\
4352 ' if(!(devid in devstats) || devstats[devid].length < 1)\n'\
4354 ' var list = devstats[devid];\n'\
4355 ' var tmp = devtitle.split(" ");\n'\
4356 ' var name = tmp[0], phase = tmp[tmp.length-1];\n'\
4357 ' var dd = document.getElementById(phase);\n'\
4358 ' var total = parseFloat(tmp[1].slice(1));\n'\
4359 ' var mlist = [];\n'\
4360 ' var maxlen = 0;\n'\
4362 ' for(var i in list) {\n'\
4363 ' if(list[i][0] == "@") {\n'\
4364 ' info = list[i].split("|");\n'\
4367 ' var tmp = list[i].split("|");\n'\
4368 ' var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]);\n'\
4369 ' var p = (t*100.0/total).toFixed(2);\n'\
4370 ' mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"];\n'\
4371 ' if(f.length > maxlen)\n'\
4372 ' maxlen = f.length;\n'\
4375 ' if(mlist.length == 0) pad = 30;\n'\
4376 ' var html = \'<div style="padding-top:\'+pad+\'px"><t3> <b>\'+name+\':</b>\';\n'\
4377 ' if(info.length > 2)\n'\
4378 ' html += " start=<b>"+info[1]+"</b>, end=<b>"+info[2]+"</b>";\n'\
4379 ' if(info.length > 3)\n'\
4380 ' html += ", length<i>(w/o overhead)</i>=<b>"+info[3]+" ms</b>";\n'\
4381 ' if(info.length > 4)\n'\
4382 ' html += ", return=<b>"+info[4]+"</b>";\n'\
4383 ' html += "</t3></div>";\n'\
4384 ' if(mlist.length > 0) {\n'\
4385 ' html += \'<table class=fstat style="padding-top:\'+(maxlen*5)+\'px;"><tr><th>Function</th>\';\n'\
4386 ' for(var i in mlist)\n'\
4387 ' html += "<td class=vt>"+mlist[i][0]+"</td>";\n'\
4388 ' html += "</tr><tr><th>Calls</th>";\n'\
4389 ' for(var i in mlist)\n'\
4390 ' html += "<td>"+mlist[i][1]+"</td>";\n'\
4391 ' html += "</tr><tr><th>Time(ms)</th>";\n'\
4392 ' for(var i in mlist)\n'\
4393 ' html += "<td>"+mlist[i][2]+"</td>";\n'\
4394 ' html += "</tr><tr><th>Percent</th>";\n'\
4395 ' for(var i in mlist)\n'\
4396 ' html += "<td>"+mlist[i][3]+"</td>";\n'\
4397 ' html += "</tr></table>";\n'\
4399 ' dd.innerHTML = html;\n'\
4400 ' var height = (maxlen*5)+100;\n'\
4401 ' dd.style.height = height+"px";\n'\
4402 ' document.getElementById("devicedetail").style.height = height+"px";\n'\
4404 ' function callSelect() {\n'\
4405 ' var cglist = document.getElementById("callgraphs");\n'\
4406 ' if(!cglist) return;\n'\
4407 ' var cg = cglist.getElementsByClassName("atop");\n'\
4408 ' for (var i = 0; i < cg.length; i++) {\n'\
4409 ' if(this.id == cg[i].id) {\n'\
4410 ' cg[i].style.display = "block";\n'\
4412 ' cg[i].style.display = "none";\n'\
4416 ' function devListWindow(e) {\n'\
4417 ' var win = window.open();\n'\
4418 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
4419 ' "<style type=\\"text/css\\">"+\n'\
4420 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
4422 ' var dt = devtable[0];\n'\
4423 ' if(e.target.id != "devlist1")\n'\
4424 ' dt = devtable[1];\n'\
4425 ' win.document.write(html+dt);\n'\
4427 ' function errWindow() {\n'\
4428 ' var range = this.id.split("_");\n'\
4429 ' var idx1 = parseInt(range[0]);\n'\
4430 ' var idx2 = parseInt(range[1]);\n'\
4431 ' var win = window.open();\n'\
4432 ' var log = document.getElementById("dmesglog");\n'\
4433 ' var title = "<title>dmesg log</title>";\n'\
4434 ' var text = log.innerHTML.split("\\n");\n'\
4435 ' var html = "";\n'\
4436 ' for(var i = 0; i < text.length; i++) {\n'\
4437 ' if(i == idx1) {\n'\
4438 ' html += "<e id=target>"+text[i]+"</e>\\n";\n'\
4439 ' } else if(i > idx1 && i <= idx2) {\n'\
4440 ' html += "<e>"+text[i]+"</e>\\n";\n'\
4442 ' html += text[i]+"\\n";\n'\
4445 ' win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>");\n'\
4446 ' win.location.hash = "#target";\n'\
4447 ' win.document.close();\n'\
4449 ' function logWindow(e) {\n'\
4450 ' var name = e.target.id.slice(4);\n'\
4451 ' var win = window.open();\n'\
4452 ' var log = document.getElementById(name+"log");\n'\
4453 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
4454 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
4455 ' win.document.close();\n'\
4457 ' function onMouseDown(e) {\n'\
4458 ' dragval[0] = e.clientX;\n'\
4459 ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\
4460 ' document.onmousemove = onMouseMove;\n'\
4462 ' function onMouseMove(e) {\n'\
4463 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4464 ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\
4466 ' function onMouseUp(e) {\n'\
4467 ' document.onmousemove = null;\n'\
4469 ' function onKeyPress(e) {\n'\
4470 ' var c = e.charCode;\n'\
4471 ' if(c != 42 && c != 43 && c != 45) return;\n'\
4472 ' var click = document.createEvent("Events");\n'\
4473 ' click.initEvent("click", true, false);\n'\
4475 ' document.getElementById("zoomin").dispatchEvent(click);\n'\
4476 ' else if(c == 45)\n'\
4477 ' document.getElementById("zoomout").dispatchEvent(click);\n'\
4478 ' else if(c == 42)\n'\
4479 ' document.getElementById("zoomdef").dispatchEvent(click);\n'\
4481 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
4482 ' window.addEventListener("load", function () {\n'\
4483 ' var dmesg = document.getElementById("dmesg");\n'\
4484 ' dmesg.style.width = "100%"\n'\
4485 ' dmesg.onmousedown = onMouseDown;\n'\
4486 ' document.onmouseup = onMouseUp;\n'\
4487 ' document.onkeypress = onKeyPress;\n'\
4488 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
4489 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
4490 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
4491 ' var list = document.getElementsByClassName("err");\n'\
4492 ' for (var i = 0; i < list.length; i++)\n'\
4493 ' list[i].onclick = errWindow;\n'\
4494 ' var list = document.getElementsByClassName("logbtn");\n'\
4495 ' for (var i = 0; i < list.length; i++)\n'\
4496 ' list[i].onclick = logWindow;\n'\
4497 ' list = document.getElementsByClassName("devlist");\n'\
4498 ' for (var i = 0; i < list.length; i++)\n'\
4499 ' list[i].onclick = devListWindow;\n'\
4500 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4501 ' for (var i = 0; i < dev.length; i++) {\n'\
4502 ' dev[i].onclick = deviceDetail;\n'\
4503 ' dev[i].onmouseover = deviceHover;\n'\
4504 ' dev[i].onmouseout = deviceUnhover;\n'\
4506 ' var dev = dmesg.getElementsByClassName("srccall");\n'\
4507 ' for (var i = 0; i < dev.length; i++)\n'\
4508 ' dev[i].onclick = callSelect;\n'\
4509 ' zoomTimeline();\n'\
4512 hf.write(script_code);
4514 def setRuntimeSuspend(before=True):
4520 # runtime suspend disable or enable
4522 sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled'
4524 sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled'
4525 print('CONFIGURING RUNTIME SUSPEND...')
4526 sv.rslist = deviceInfo(sv.rstgt)
4528 sv.setVal(sv.rsval, i)
4529 print('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist)))
4530 print('waiting 5 seconds...')
4533 # runtime suspend re-enable or re-disable
4535 sv.setVal(sv.rstgt, i)
4536 print('runtime suspend settings restored on %d devices' % len(sv.rslist))
4538 # Function: executeSuspend
4540 # Execute system suspend through the sysfs interface, then copy the output
4541 # dmesg and ftrace files to the test output directory.
4542 def executeSuspend():
4543 pm = ProcessMonitor()
4546 # run these commands to prepare the system for suspend
4548 if sysvals.display > 0:
4549 print('TURN DISPLAY ON')
4550 call('xset -d :0.0 dpms force suspend', shell=True)
4551 call('xset -d :0.0 dpms force on', shell=True)
4553 print('TURN DISPLAY OFF')
4554 call('xset -d :0.0 dpms force suspend', shell=True)
4557 print('SYNCING FILESYSTEMS')
4558 call('sync', shell=True)
4559 # mark the start point in the kernel ring buffer just as we start
4562 if(sysvals.usecallgraph or sysvals.usetraceevents):
4563 print('START TRACING')
4564 sysvals.fsetVal('1', 'tracing_on')
4565 if sysvals.useprocmon:
4567 # execute however many s/r runs requested
4568 for count in range(1,sysvals.execcount+1):
4569 # x2delay in between test runs
4570 if(count > 1 and sysvals.x2delay > 0):
4571 sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
4572 time.sleep(sysvals.x2delay/1000.0)
4573 sysvals.fsetVal('WAIT END', 'trace_marker')
4575 if sysvals.testcommand != '':
4576 print('COMMAND START')
4578 if(sysvals.rtcwake):
4579 print('SUSPEND START')
4581 print('SUSPEND START (press a key to resume)')
4583 if(sysvals.rtcwake):
4584 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
4585 sysvals.rtcWakeAlarmOn()
4586 # start of suspend trace marker
4587 if(sysvals.usecallgraph or sysvals.usetraceevents):
4588 sysvals.fsetVal('SUSPEND START', 'trace_marker')
4590 if(count == 1 and sysvals.predelay > 0):
4591 sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
4592 time.sleep(sysvals.predelay/1000.0)
4593 sysvals.fsetVal('WAIT END', 'trace_marker')
4594 # initiate suspend or command
4595 if sysvals.testcommand != '':
4596 call(sysvals.testcommand+' 2>&1', shell=True);
4598 mode = sysvals.suspendmode
4599 if sysvals.memmode and os.path.exists(sysvals.mempowerfile):
4601 pf = open(sysvals.mempowerfile, 'w')
4602 pf.write(sysvals.memmode)
4604 pf = open(sysvals.powerfile, 'w')
4606 # execution will pause here
4611 if(sysvals.rtcwake):
4612 sysvals.rtcWakeAlarmOff()
4614 if(count == sysvals.execcount and sysvals.postdelay > 0):
4615 sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
4616 time.sleep(sysvals.postdelay/1000.0)
4617 sysvals.fsetVal('WAIT END', 'trace_marker')
4618 # return from suspend
4619 print('RESUME COMPLETE')
4620 if(sysvals.usecallgraph or sysvals.usetraceevents):
4621 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
4622 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4623 fwdata.append(getFPDT(False))
4625 if(sysvals.usecallgraph or sysvals.usetraceevents):
4626 if sysvals.useprocmon:
4628 sysvals.fsetVal('0', 'tracing_on')
4629 print('CAPTURING TRACE')
4630 op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata)
4631 fp = open(tp+'trace', 'r')
4635 sysvals.fsetVal('', 'trace')
4637 # grab a copy of the dmesg output
4638 print('CAPTURING DMESG')
4639 sysvals.getdmesg(fwdata)
4642 if os.path.islink(file):
4643 return os.readlink(file).split('/')[-1]
4645 return sysvals.getVal(file).strip()
4649 # Print out a very concise time string in minutes and seconds
4651 # The time string, e.g. "1901m16s"
4655 m = (val / 60000) % 60
4656 s = (val / 1000) % 60
4658 return '%d:%02d:%02d' % (h, m, s)
4660 return '%02d:%02d' % (m, s)
4664 list = {'enabled':'A', 'disabled':'S', 'auto':'E', 'on':'D',
4665 'active':'A', 'suspended':'S', 'suspending':'S'}
4670 # Function: deviceInfo
4672 # Detect all the USB hosts and devices currently connected and add
4673 # a list of USB device names to sysvals for better timeline readability
4674 def deviceInfo(output=''):
4677 print('---------------------------------------------------------------------------------------------')
4678 print(' A = async/sync PM queue (A/S) C = runtime active children')
4679 print(' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)')
4680 print(' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)')
4681 print(' U = runtime usage count')
4682 print('---------------------------------------------------------------------------------------------')
4683 print('DEVICE NAME A R S U C rACTIVE rSUSPEND')
4684 print('---------------------------------------------------------------------------------------------')
4687 tgtval = 'runtime_status'
4689 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4690 if(not re.match('.*/power', dirname) or
4691 'control' not in filenames or
4692 tgtval not in filenames):
4695 dirname = dirname[:-6]
4696 device = dirname.split('/')[-1]
4698 power[tgtval] = readFile('%s/power/%s' % (dirname, tgtval))
4699 # only list devices which support runtime suspend
4700 if power[tgtval] not in ['active', 'suspended', 'suspending']:
4702 for i in ['product', 'driver', 'subsystem']:
4703 file = '%s/%s' % (dirname, i)
4704 if os.path.exists(file):
4705 name = readFile(file)
4707 for i in ['async', 'control', 'runtime_status', 'runtime_usage',
4708 'runtime_active_kids', 'runtime_active_time',
4709 'runtime_suspended_time']:
4711 power[i] = readFile('%s/power/%s' % (dirname, i))
4713 if power['control'] == output:
4714 res.append('%s/power/control' % dirname)
4716 lines[dirname] = '%-26s %-26s %1s %1s %1s %1s %1s %10s %10s' % \
4717 (device[:26], name[:26],
4718 yesno(power['async']), \
4719 yesno(power['control']), \
4720 yesno(power['runtime_status']), \
4721 power['runtime_usage'], \
4722 power['runtime_active_kids'], \
4723 ms2nice(power['runtime_active_time']), \
4724 ms2nice(power['runtime_suspended_time']))
4725 for i in sorted(lines):
4729 # Function: devProps
4731 # Retrieve a list of properties for all devices in the trace log
4732 def devProps(data=0):
4736 idx = data.index(': ') + 2
4737 if idx >= len(data):
4739 devlist = data[idx:].split(';')
4745 props[dev] = DevProps()
4746 props[dev].altname = f[1]
4748 props[dev].async = True
4750 props[dev].async = False
4751 sysvals.devprops = props
4752 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4753 sysvals.testcommand = props['testcommandstring'].altname
4756 if(os.path.exists(sysvals.ftracefile) == False):
4757 doError('%s does not exist' % sysvals.ftracefile)
4759 # first get the list of devices we need properties for
4760 msghead = 'Additional data added by AnalyzeSuspend'
4761 alreadystamped = False
4763 tf = sysvals.openlog(sysvals.ftracefile, 'r')
4766 alreadystamped = True
4768 # determine the trace data type (required for further parsing)
4769 m = re.match(sysvals.tracertypefmt, line)
4771 tp.setTracerType(m.group('t'))
4773 # parse only valid lines, if this is not one move on
4774 m = re.match(tp.ftrace_line_fmt, line)
4775 if(not m or 'device_pm_callback_start' not in line):
4777 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
4781 if dev not in props:
4782 props[dev] = DevProps()
4785 if not alreadystamped and sysvals.suspendmode == 'command':
4786 out = '#\n# '+msghead+'\n# Device Properties: '
4787 out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
4788 with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
4790 sysvals.devprops = props
4793 # now get the syspath for each of our target devices
4794 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4795 if(re.match('.*/power', dirname) and 'async' in filenames):
4796 dev = dirname.split('/')[-2]
4797 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
4798 props[dev].syspath = dirname[:-6]
4800 # now fill in the properties for our target devices
4802 dirname = props[dev].syspath
4803 if not dirname or not os.path.exists(dirname):
4805 with open(dirname+'/power/async') as fp:
4807 props[dev].async = False
4808 if 'enabled' in text:
4809 props[dev].async = True
4810 fields = os.listdir(dirname)
4811 if 'product' in fields:
4812 with open(dirname+'/product') as fp:
4813 props[dev].altname = fp.read()
4814 elif 'name' in fields:
4815 with open(dirname+'/name') as fp:
4816 props[dev].altname = fp.read()
4817 elif 'model' in fields:
4818 with open(dirname+'/model') as fp:
4819 props[dev].altname = fp.read()
4820 elif 'description' in fields:
4821 with open(dirname+'/description') as fp:
4822 props[dev].altname = fp.read()
4823 elif 'id' in fields:
4824 with open(dirname+'/id') as fp:
4825 props[dev].altname = fp.read()
4826 elif 'idVendor' in fields and 'idProduct' in fields:
4828 with open(dirname+'/idVendor') as fp:
4829 idv = fp.read().strip()
4830 with open(dirname+'/idProduct') as fp:
4831 idp = fp.read().strip()
4832 props[dev].altname = '%s:%s' % (idv, idp)
4834 if props[dev].altname:
4835 out = props[dev].altname.strip().replace('\n', ' ')
4836 out = out.replace(',', ' ')
4837 out = out.replace(';', ' ')
4838 props[dev].altname = out
4840 # and now write the data to the ftrace file
4841 if not alreadystamped:
4842 out = '#\n# '+msghead+'\n# Device Properties: '
4843 for dev in sorted(props):
4844 out += props[dev].out(dev)
4845 with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
4848 sysvals.devprops = props
4850 # Function: getModes
4852 # Determine the supported power modes on this system
4854 # A string list of the available modes
4857 if(os.path.exists(sysvals.powerfile)):
4858 fp = open(sysvals.powerfile, 'r')
4859 modes = string.split(fp.read())
4861 if(os.path.exists(sysvals.mempowerfile)):
4863 fp = open(sysvals.mempowerfile, 'r')
4864 for m in string.split(fp.read()):
4865 memmode = m.strip('[]')
4866 if memmode == 'deep':
4869 modes.append('mem-%s' % memmode)
4871 if 'mem' in modes and not deep:
4875 # Function: dmidecode
4877 # Read the bios tables and pull out system info
4879 # mempath: /dev/mem or custom mem path
4880 # fatal: True to exit on error, False to return empty dict
4882 # A dict object with all available key/values
4883 def dmidecode(mempath, fatal=False):
4886 # the list of values to retrieve, with hardcoded (type, idx)
4888 'bios-vendor': (0, 4),
4889 'bios-version': (0, 5),
4890 'bios-release-date': (0, 8),
4891 'system-manufacturer': (1, 4),
4892 'system-product-name': (1, 5),
4893 'system-version': (1, 6),
4894 'system-serial-number': (1, 7),
4895 'baseboard-manufacturer': (2, 4),
4896 'baseboard-product-name': (2, 5),
4897 'baseboard-version': (2, 6),
4898 'baseboard-serial-number': (2, 7),
4899 'chassis-manufacturer': (3, 4),
4900 'chassis-type': (3, 5),
4901 'chassis-version': (3, 6),
4902 'chassis-serial-number': (3, 7),
4903 'processor-manufacturer': (4, 7),
4904 'processor-version': (4, 16),
4906 if(not os.path.exists(mempath)):
4908 doError('file does not exist: %s' % mempath)
4910 if(not os.access(mempath, os.R_OK)):
4912 doError('file is not readable: %s' % mempath)
4915 # by default use legacy scan, but try to use EFI first
4918 for ep in ['/sys/firmware/efi/systab', '/proc/efi/systab']:
4919 if not os.path.exists(ep) or not os.access(ep, os.R_OK):
4924 i = buf.find('SMBIOS=')
4927 memaddr = int(buf[i+7:], 16)
4932 # read in the memory for scanning
4933 fp = open(mempath, 'rb')
4936 buf = fp.read(memsize)
4939 doError('DMI table is unreachable, sorry')
4944 # search for either an SM table or DMI table
4945 i = base = length = num = 0
4947 if buf[i:i+4] == '_SM_' and i < memsize - 16:
4948 length = struct.unpack('H', buf[i+22:i+24])[0]
4949 base, num = struct.unpack('IH', buf[i+24:i+30])
4951 elif buf[i:i+5] == '_DMI_':
4952 length = struct.unpack('H', buf[i+6:i+8])[0]
4953 base, num = struct.unpack('IH', buf[i+8:i+14])
4956 if base == 0 and length == 0 and num == 0:
4958 doError('Neither SMBIOS nor DMI were found')
4962 # read in the SM or DMI table
4963 fp = open(mempath, 'rb')
4966 buf = fp.read(length)
4969 doError('DMI table is unreachable, sorry')
4974 # scan the table for the values we want
4976 while(count < num and i <= len(buf) - 4):
4977 type, size, handle = struct.unpack('BBH', buf[i:i+4])
4979 while n < len(buf) - 1:
4980 if 0 == struct.unpack('H', buf[n:n+2])[0]:
4983 data = buf[i+size:n+2].split('\0')
4985 itype, idxadr = info[name]
4987 idx = struct.unpack('B', buf[i+idxadr])[0]
4988 if idx > 0 and idx < len(data) - 1:
4989 s = data[idx-1].strip()
4990 if s and s.lower() != 'to be filled by o.e.m.':
4991 out[name] = data[idx-1]
4997 p = '/sys/class/power_supply'
4999 for d in os.listdir(p):
5000 type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower()
5001 if type != 'battery':
5003 for v in ['status', 'energy_now', 'capacity_now']:
5004 bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower()
5007 if 'status' in bat and 'discharging' in bat['status']:
5010 for v in ['energy_now', 'capacity_now']:
5011 if v in bat and bat[v]:
5012 charge = int(bat[v])
5017 # Read the acpi bios tables and pull out FPDT, the firmware data
5019 # output: True to output the info to stdout, False otherwise
5020 def getFPDT(output):
5022 rectype[0] = 'Firmware Basic Boot Performance Record'
5023 rectype[1] = 'S3 Performance Table Record'
5025 prectype[0] = 'Basic S3 Resume Performance Record'
5026 prectype[1] = 'Basic S3 Suspend Performance Record'
5028 sysvals.rootCheck(True)
5029 if(not os.path.exists(sysvals.fpdtpath)):
5031 doError('file does not exist: %s' % sysvals.fpdtpath)
5033 if(not os.access(sysvals.fpdtpath, os.R_OK)):
5035 doError('file is not readable: %s' % sysvals.fpdtpath)
5037 if(not os.path.exists(sysvals.mempath)):
5039 doError('file does not exist: %s' % sysvals.mempath)
5041 if(not os.access(sysvals.mempath, os.R_OK)):
5043 doError('file is not readable: %s' % sysvals.mempath)
5046 fp = open(sysvals.fpdtpath, 'rb')
5052 doError('Invalid FPDT table data, should '+\
5053 'be at least 36 bytes')
5056 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
5059 print('Firmware Performance Data Table (%s)' % table[0])
5060 print(' Signature : %s' % table[0])
5061 print(' Table Length : %u' % table[1])
5062 print(' Revision : %u' % table[2])
5063 print(' Checksum : 0x%x' % table[3])
5064 print(' OEM ID : %s' % table[4])
5065 print(' OEM Table ID : %s' % table[5])
5066 print(' OEM Revision : %u' % table[6])
5067 print(' Creator ID : %s' % table[7])
5068 print(' Creator Revision : 0x%x' % table[8])
5071 if(table[0] != 'FPDT'):
5073 doError('Invalid FPDT table')
5080 fp = open(sysvals.mempath, 'rb')
5081 while(i < len(records)):
5082 header = struct.unpack('HBB', records[i:i+4])
5083 if(header[0] not in rectype):
5086 if(header[1] != 16):
5089 addr = struct.unpack('Q', records[i+8:i+16])[0]
5095 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
5097 rechead = struct.unpack('4sI', first)
5098 recdata = fp.read(rechead[1]-8)
5099 if(rechead[0] == 'FBPT'):
5100 record = struct.unpack('HBBIQQQQQ', recdata)
5102 print('%s (%s)' % (rectype[header[0]], rechead[0]))
5103 print(' Reset END : %u ns' % record[4])
5104 print(' OS Loader LoadImage Start : %u ns' % record[5])
5105 print(' OS Loader StartImage Start : %u ns' % record[6])
5106 print(' ExitBootServices Entry : %u ns' % record[7])
5107 print(' ExitBootServices Exit : %u ns' % record[8])
5108 elif(rechead[0] == 'S3PT'):
5110 print('%s (%s)' % (rectype[header[0]], rechead[0]))
5112 while(j < len(recdata)):
5113 prechead = struct.unpack('HBB', recdata[j:j+4])
5114 if(prechead[0] not in prectype):
5116 if(prechead[0] == 0):
5117 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
5118 fwData[1] = record[2]
5120 print(' %s' % prectype[prechead[0]])
5121 print(' Resume Count : %u' % \
5123 print(' FullResume : %u ns' % \
5125 print(' AverageResume : %u ns' % \
5127 elif(prechead[0] == 1):
5128 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
5129 fwData[0] = record[1] - record[0]
5131 print(' %s' % prectype[prechead[0]])
5132 print(' SuspendStart : %u ns' % \
5134 print(' SuspendEnd : %u ns' % \
5136 print(' SuspendTime : %u ns' % \
5145 # Function: statusCheck
5147 # Verify that the requested command and options will work, and
5148 # print the results to the terminal
5150 # True if the test will work, False if not
5151 def statusCheck(probecheck=False):
5154 print('Checking this system (%s)...' % platform.node())
5156 # check we have root access
5157 res = sysvals.colorText('NO (No features of this tool will work!)')
5158 if(sysvals.rootCheck(False)):
5160 print(' have root access: %s' % res)
5162 print(' Try running this script with sudo')
5165 # check sysfs is mounted
5166 res = sysvals.colorText('NO (No features of this tool will work!)')
5167 if(os.path.exists(sysvals.powerfile)):
5169 print(' is sysfs mounted: %s' % res)
5173 # check target mode is a valid mode
5174 if sysvals.suspendmode != 'command':
5175 res = sysvals.colorText('NO')
5177 if(sysvals.suspendmode in modes):
5181 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
5183 print(' valid power modes are: %s' % modes)
5184 print(' please choose one with -m')
5186 # check if ftrace is available
5187 res = sysvals.colorText('NO')
5188 ftgood = sysvals.verifyFtrace()
5191 elif(sysvals.usecallgraph):
5193 print(' is ftrace supported: %s' % res)
5195 # check if kprobes are available
5196 res = sysvals.colorText('NO')
5197 sysvals.usekprobes = sysvals.verifyKprobes()
5198 if(sysvals.usekprobes):
5201 sysvals.usedevsrc = False
5202 print(' are kprobes supported: %s' % res)
5204 # what data source are we using
5207 sysvals.usetraceevents = True
5208 for e in sysvals.traceevents:
5209 if not os.path.exists(sysvals.epath+e):
5210 sysvals.usetraceevents = False
5211 if(sysvals.usetraceevents):
5212 res = 'FTRACE (all trace events found)'
5213 print(' timeline data source: %s' % res)
5216 res = sysvals.colorText('NO')
5217 if(sysvals.rtcpath != ''):
5219 elif(sysvals.rtcwake):
5221 print(' is rtcwake supported: %s' % res)
5227 if sysvals.usekprobes:
5228 for name in sysvals.tracefuncs:
5229 sysvals.defaultKprobe(name, sysvals.tracefuncs[name])
5230 if sysvals.usedevsrc:
5231 for name in sysvals.dev_tracefuncs:
5232 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])
5233 sysvals.addKprobes(True)
5239 # generic error function for catastrphic failures
5241 # msg: the error message to print
5242 # help: True if printHelp should be called after, False otherwise
5243 def doError(msg, help=False):
5246 print('ERROR: %s\n') % msg
5247 sysvals.outputResult({'error':msg})
5250 # Function: getArgInt
5252 # pull out an integer argument from the command line with checks
5253 def getArgInt(name, args, min, max, main=True):
5258 doError(name+': no argument supplied', True)
5264 doError(name+': non-integer value given', True)
5265 if(val < min or val > max):
5266 doError(name+': value should be between %d and %d' % (min, max), True)
5269 # Function: getArgFloat
5271 # pull out a float argument from the command line with checks
5272 def getArgFloat(name, args, min, max, main=True):
5277 doError(name+': no argument supplied', True)
5283 doError(name+': non-numerical value given', True)
5284 if(val < min or val > max):
5285 doError(name+': value should be between %f and %f' % (min, max), True)
5288 def processData(live=False):
5289 print('PROCESSING DATA')
5291 if(sysvals.usetraceevents):
5292 testruns, error = parseTraceLog(live)
5293 if sysvals.dmesgfile:
5294 for data in testruns:
5295 data.extractErrorInfo()
5297 testruns = loadKernelLog()
5298 for data in testruns:
5299 parseKernelLog(data)
5300 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
5301 appendIncompleteTraceLog(testruns)
5302 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
5303 for data in testruns:
5306 for data in testruns:
5309 if len(testruns) < 1:
5310 return (testruns, {'error': 'timeline generation failed'})
5311 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
5312 createHTML(testruns, error)
5316 stamp['suspend'], stamp['resume'] = data.getTimeValues()
5318 stamp['fwsuspend'], stamp['fwresume'] = data.fwSuspend, data.fwResume
5320 stamp['error'] = error
5321 return (testruns, stamp)
5323 # Function: rerunTest
5325 # generate an output from an existing set of ftrace/dmesg logs
5327 if sysvals.ftracefile:
5328 doesTraceLogHaveTraceEvents()
5329 if not sysvals.dmesgfile and not sysvals.usetraceevents:
5330 doError('recreating this html output requires a dmesg file')
5331 sysvals.setOutputFile()
5332 if os.path.exists(sysvals.htmlfile):
5333 if not os.path.isfile(sysvals.htmlfile):
5334 doError('a directory already exists with this name: %s' % sysvals.htmlfile)
5335 elif not os.access(sysvals.htmlfile, os.W_OK):
5336 doError('missing permission to write to %s' % sysvals.htmlfile)
5337 testruns, stamp = processData(False)
5342 # execute a suspend/resume, gather the logs, and generate the output
5344 # prepare for the test
5345 sysvals.initFtrace()
5346 sysvals.initTestOutput('suspend')
5350 sysvals.cleanupFtrace()
5351 if sysvals.skiphtml:
5352 sysvals.sudouser(sysvals.testdir)
5354 testruns, stamp = processData(True)
5355 for data in testruns:
5357 sysvals.sudouser(sysvals.testdir)
5358 sysvals.outputResult(stamp, n)
5360 def find_in_html(html, start, end, firstonly=True):
5362 while n < len(html):
5363 m = re.search(start, html[n:])
5367 m = re.search(end, html[n+i:])
5371 str = html[n+i:n+i+j]
5373 num = re.search(r'[-+]?\d*\.\d+|\d+', str)
5374 str = num.group() if num else 'NaN'
5383 # Function: runSummary
5385 # create a summary of tests in a sub-directory
5386 def runSummary(subdir, local=True, genhtml=False):
5387 inpath = os.path.abspath(subdir)
5390 outpath = os.path.abspath('.')
5391 print('Generating a summary of folder "%s"' % inpath)
5393 for dirname, dirnames, filenames in os.walk(subdir):
5394 sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
5395 for filename in filenames:
5396 if(re.match('.*_dmesg.txt', filename)):
5397 sysvals.dmesgfile = os.path.join(dirname, filename)
5398 elif(re.match('.*_ftrace.txt', filename)):
5399 sysvals.ftracefile = os.path.join(dirname, filename)
5400 sysvals.setOutputFile()
5401 if sysvals.ftracefile and sysvals.htmlfile and \
5402 not os.path.exists(sysvals.htmlfile):
5403 print('FTRACE: %s' % sysvals.ftracefile)
5404 if sysvals.dmesgfile:
5405 print('DMESG : %s' % sysvals.dmesgfile)
5408 for dirname, dirnames, filenames in os.walk(subdir):
5409 for filename in filenames:
5410 if(not re.match('.*.html', filename)):
5412 file = os.path.join(dirname, filename)
5413 html = open(file, 'r').read()
5414 suspend = find_in_html(html, 'Kernel Suspend', 'ms')
5415 resume = find_in_html(html, 'Kernel Resume', 'ms')
5416 line = find_in_html(html, '<div class="stamp">', '</div>')
5418 if not suspend or not resume or len(stmp) != 8:
5421 dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
5424 tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
5425 error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
5426 result = 'fail' if error else 'pass'
5428 e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '→</div>', False)
5429 for i in list(set(e)):
5430 ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
5437 'issues': ','.join(ilist),
5440 'url': os.path.relpath(file, outpath),
5442 testruns.append(data)
5443 outfile = os.path.join(outpath, 'summary.html')
5444 print('Summary file: %s' % outfile)
5445 createHTMLSummarySimple(testruns, outfile, inpath)
5447 # Function: checkArgBool
5449 # check if a boolean string value is true or false
5450 def checkArgBool(name, value):
5451 if value in switchvalues:
5452 if value in switchoff:
5455 doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True)
5458 # Function: configFromFile
5460 # Configure the script via the info in a config file
5461 def configFromFile(file):
5462 Config = ConfigParser.ConfigParser()
5465 sections = Config.sections()
5466 overridekprobes = False
5467 overridedevkprobes = False
5468 if 'Settings' in sections:
5469 for opt in Config.options('Settings'):
5470 value = Config.get('Settings', opt).lower()
5471 option = opt.lower()
5472 if(option == 'verbose'):
5473 sysvals.verbose = checkArgBool(option, value)
5474 elif(option == 'addlogs'):
5475 sysvals.dmesglog = sysvals.ftracelog = checkArgBool(option, value)
5476 elif(option == 'dev'):
5477 sysvals.usedevsrc = checkArgBool(option, value)
5478 elif(option == 'proc'):
5479 sysvals.useprocmon = checkArgBool(option, value)
5480 elif(option == 'x2'):
5481 if checkArgBool(option, value):
5482 sysvals.execcount = 2
5483 elif(option == 'callgraph'):
5484 sysvals.usecallgraph = checkArgBool(option, value)
5485 elif(option == 'override-timeline-functions'):
5486 overridekprobes = checkArgBool(option, value)
5487 elif(option == 'override-dev-timeline-functions'):
5488 overridedevkprobes = checkArgBool(option, value)
5489 elif(option == 'skiphtml'):
5490 sysvals.skiphtml = checkArgBool(option, value)
5491 elif(option == 'sync'):
5492 sysvals.sync = checkArgBool(option, value)
5493 elif(option == 'rs' or option == 'runtimesuspend'):
5494 if value in switchvalues:
5495 if value in switchoff:
5500 doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)
5501 elif(option == 'display'):
5502 if value in switchvalues:
5503 if value in switchoff:
5504 sysvals.display = -1
5508 doError('invalid value --> (%s: %s), use "on/off"' % (option, value), True)
5509 elif(option == 'gzip'):
5510 sysvals.gzip = checkArgBool(option, value)
5511 elif(option == 'cgfilter'):
5512 sysvals.setCallgraphFilter(value)
5513 elif(option == 'cgskip'):
5514 if value in switchoff:
5517 sysvals.cgskip = sysvals.configFile(val)
5518 if(not sysvals.cgskip):
5519 doError('%s does not exist' % sysvals.cgskip)
5520 elif(option == 'cgtest'):
5521 sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)
5522 elif(option == 'cgphase'):
5524 if value not in d.phases:
5525 doError('invalid phase --> (%s: %s), valid phases are %s'\
5526 % (option, value, d.phases), True)
5527 sysvals.cgphase = value
5528 elif(option == 'fadd'):
5529 file = sysvals.configFile(value)
5531 doError('%s does not exist' % value)
5532 sysvals.addFtraceFilterFunctions(file)
5533 elif(option == 'result'):
5534 sysvals.result = value
5535 elif(option == 'multi'):
5536 nums = value.split()
5538 doError('multi requires 2 integers (exec_count and delay)', True)
5539 sysvals.multitest['run'] = True
5540 sysvals.multitest['count'] = getArgInt('multi: n d (exec count)', nums[0], 2, 1000000, False)
5541 sysvals.multitest['delay'] = getArgInt('multi: n d (delay between tests)', nums[1], 0, 3600, False)
5542 elif(option == 'devicefilter'):
5543 sysvals.setDeviceFilter(value)
5544 elif(option == 'expandcg'):
5545 sysvals.cgexp = checkArgBool(option, value)
5546 elif(option == 'srgap'):
5547 if checkArgBool(option, value):
5549 elif(option == 'mode'):
5550 sysvals.suspendmode = value
5551 elif(option == 'command' or option == 'cmd'):
5552 sysvals.testcommand = value
5553 elif(option == 'x2delay'):
5554 sysvals.x2delay = getArgInt('x2delay', value, 0, 60000, False)
5555 elif(option == 'predelay'):
5556 sysvals.predelay = getArgInt('predelay', value, 0, 60000, False)
5557 elif(option == 'postdelay'):
5558 sysvals.postdelay = getArgInt('postdelay', value, 0, 60000, False)
5559 elif(option == 'maxdepth'):
5560 sysvals.max_graph_depth = getArgInt('maxdepth', value, 0, 1000, False)
5561 elif(option == 'rtcwake'):
5562 if value in switchoff:
5563 sysvals.rtcwake = False
5565 sysvals.rtcwake = True
5566 sysvals.rtcwaketime = getArgInt('rtcwake', value, 0, 3600, False)
5567 elif(option == 'timeprec'):
5568 sysvals.setPrecision(getArgInt('timeprec', value, 0, 6, False))
5569 elif(option == 'mindev'):
5570 sysvals.mindevlen = getArgFloat('mindev', value, 0.0, 10000.0, False)
5571 elif(option == 'callloop-maxgap'):
5572 sysvals.callloopmaxgap = getArgFloat('callloop-maxgap', value, 0.0, 1.0, False)
5573 elif(option == 'callloop-maxlen'):
5574 sysvals.callloopmaxgap = getArgFloat('callloop-maxlen', value, 0.0, 1.0, False)
5575 elif(option == 'mincg'):
5576 sysvals.mincglen = getArgFloat('mincg', value, 0.0, 10000.0, False)
5577 elif(option == 'bufsize'):
5578 sysvals.bufsize = getArgInt('bufsize', value, 1, 1024*1024*8, False)
5579 elif(option == 'output-dir'):
5580 sysvals.outdir = sysvals.setOutputFolder(value)
5582 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
5583 doError('No command supplied for mode "command"')
5585 # compatibility errors
5586 if sysvals.usedevsrc and sysvals.usecallgraph:
5587 doError('-dev is not compatible with -f')
5588 if sysvals.usecallgraph and sysvals.useprocmon:
5589 doError('-proc is not compatible with -f')
5592 sysvals.tracefuncs = dict()
5593 if overridedevkprobes:
5594 sysvals.dev_tracefuncs = dict()
5597 kprobesec = 'dev_timeline_functions_'+platform.machine()
5598 if kprobesec in sections:
5599 for name in Config.options(kprobesec):
5600 text = Config.get(kprobesec, name)
5601 kprobes[name] = (text, True)
5602 kprobesec = 'timeline_functions_'+platform.machine()
5603 if kprobesec in sections:
5604 for name in Config.options(kprobesec):
5606 doError('Duplicate timeline function found "%s"' % (name))
5607 text = Config.get(kprobesec, name)
5608 kprobes[name] = (text, False)
5610 for name in kprobes:
5615 text, dev = kprobes[name]
5619 # bracketted strings are special formatting, read them separately
5620 if val[0] == '[' and val[-1] == ']':
5621 for prop in val[1:-1].split(','):
5625 color = int(p[1], 16)
5630 # first real arg should be the format string
5633 # all other args are actual function args
5638 if not function or not format:
5639 doError('Invalid kprobe: %s' % name)
5640 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
5642 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
5643 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
5644 doError('Duplicate timeline function found "%s"' % (name))
5650 sysvals.archargs: args
5655 sysvals.dev_tracefuncs[name] = kp
5657 sysvals.tracefuncs[name] = kp
5659 # Function: printHelp
5661 # print out the help text
5664 print('%s v%s' % (sysvals.title, sysvals.version))
5665 print('Usage: sudo sleepgraph <options> <commands>')
5667 print('Description:')
5668 print(' This tool is designed to assist kernel and OS developers in optimizing')
5669 print(' their linux stack\'s suspend/resume time. Using a kernel image built')
5670 print(' with a few extra options enabled, the tool will execute a suspend and')
5671 print(' capture dmesg and ftrace data until resume is complete. This data is')
5672 print(' transformed into a device timeline and an optional callgraph to give')
5673 print(' a detailed view of which devices/subsystems are taking the most')
5674 print(' time in suspend/resume.')
5676 print(' If no specific command is given, the default behavior is to initiate')
5677 print(' a suspend/resume and capture the dmesg/ftrace output as an html timeline.')
5679 print(' Generates output files in subdirectory: suspend-yymmdd-HHMMSS')
5680 print(' HTML output: <hostname>_<mode>.html')
5681 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
5682 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
5685 print(' -h Print this help text')
5686 print(' -v Print the current tool version')
5687 print(' -config fn Pull arguments and config options from file fn')
5688 print(' -verbose Print extra information during execution and analysis')
5689 print(' -m mode Mode to initiate for suspend (default: %s)') % (sysvals.suspendmode)
5690 print(' -o name Overrides the output subdirectory name when running a new test')
5691 print(' default: suspend-{date}-{time}')
5692 print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)')
5693 print(' -addlogs Add the dmesg and ftrace logs to the html output')
5694 print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
5695 print(' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)')
5696 print(' -result fn Export a results table to a text file for parsing.')
5697 print(' [testprep]')
5698 print(' -sync Sync the filesystems before starting the test')
5699 print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test')
5700 print(' -display on/off Turn the display on or off for the test')
5701 print(' [advanced]')
5702 print(' -gzip Gzip the trace and dmesg logs to save space')
5703 print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"')
5704 print(' -proc Add usermode process info into the timeline (default: disabled)')
5705 print(' -dev Add kernel function calls and threads to the timeline (default: disabled)')
5706 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
5707 print(' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)')
5708 print(' -predelay t Include t ms delay before 1st suspend (default: 0 ms)')
5709 print(' -postdelay t Include t ms delay after last resume (default: 0 ms)')
5710 print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
5711 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
5712 print(' be created in a new subdirectory with a summary page.')
5714 print(' -f Use ftrace to create device callgraphs (default: disabled)')
5715 print(' -maxdepth N limit the callgraph data to N call levels (default: 0=all)')
5716 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
5717 print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
5718 print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names')
5719 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
5720 print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)')
5721 print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
5722 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
5723 print(' -cgfilter S Filter the callgraph output in the timeline')
5724 print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)')
5725 print(' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)')
5727 print('Other commands:')
5728 print(' -modes List available suspend modes')
5729 print(' -status Test to see if the system is enabled to run this tool')
5730 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
5731 print(' -battery Print out battery info (if available)')
5732 print(' -sysinfo Print out system info extracted from BIOS')
5733 print(' -devinfo Print out the pm settings of all devices which support runtime suspend')
5734 print(' -flist Print the list of functions currently being captured in ftrace')
5735 print(' -flistall Print all functions capable of being captured in ftrace')
5736 print(' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]')
5738 print(' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)')
5739 print(' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)')
5743 # ----------------- MAIN --------------------
5744 # exec start (skipped if script is loaded as library)
5745 if __name__ == '__main__':
5748 simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status', '-battery']
5749 if '-f' in sys.argv:
5750 sysvals.cgskip = sysvals.configFile('cgskip.txt')
5751 # loop through the command line arguments
5752 args = iter(sys.argv[1:])
5758 doError('No mode supplied', True)
5759 if val == 'command' and not sysvals.testcommand:
5760 doError('No command supplied for mode "command"', True)
5761 sysvals.suspendmode = val
5762 elif(arg in simplecmds):
5768 print("Version %s" % sysvals.version)
5771 sysvals.execcount = 2
5772 elif(arg == '-x2delay'):
5773 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
5774 elif(arg == '-predelay'):
5775 sysvals.predelay = getArgInt('-predelay', args, 0, 60000)
5776 elif(arg == '-postdelay'):
5777 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
5779 sysvals.usecallgraph = True
5780 elif(arg == '-skiphtml'):
5781 sysvals.skiphtml = True
5782 elif(arg == '-cgdump'):
5783 sysvals.cgdump = True
5784 elif(arg == '-genhtml'):
5786 elif(arg == '-addlogs'):
5787 sysvals.dmesglog = sysvals.ftracelog = True
5788 elif(arg == '-verbose'):
5789 sysvals.verbose = True
5790 elif(arg == '-proc'):
5791 sysvals.useprocmon = True
5792 elif(arg == '-dev'):
5793 sysvals.usedevsrc = True
5794 elif(arg == '-sync'):
5796 elif(arg == '-gzip'):
5802 doError('-rs requires "enable" or "disable"', True)
5803 if val.lower() in switchvalues:
5804 if val.lower() in switchoff:
5809 doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True)
5810 elif(arg == '-display'):
5814 doError('-display requires "on" or "off"', True)
5815 if val.lower() in switchvalues:
5816 if val.lower() in switchoff:
5817 sysvals.display = -1
5821 doError('invalid option: %s, use "on/off"' % val, True)
5822 elif(arg == '-maxdepth'):
5823 sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
5824 elif(arg == '-rtcwake'):
5828 doError('No rtcwake time supplied', True)
5829 if val.lower() in switchoff:
5830 sysvals.rtcwake = False
5832 sysvals.rtcwake = True
5833 sysvals.rtcwaketime = getArgInt('-rtcwake', val, 0, 3600, False)
5834 elif(arg == '-timeprec'):
5835 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
5836 elif(arg == '-mindev'):
5837 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
5838 elif(arg == '-mincg'):
5839 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
5840 elif(arg == '-bufsize'):
5841 sysvals.bufsize = getArgInt('-bufsize', args, 1, 1024*1024*8)
5842 elif(arg == '-cgtest'):
5843 sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
5844 elif(arg == '-cgphase'):
5848 doError('No phase name supplied', True)
5850 if val not in d.phases:
5851 doError('invalid phase --> (%s: %s), valid phases are %s'\
5852 % (arg, val, d.phases), True)
5853 sysvals.cgphase = val
5854 elif(arg == '-cgfilter'):
5858 doError('No callgraph functions supplied', True)
5859 sysvals.setCallgraphFilter(val)
5860 elif(arg == '-cgskip'):
5864 doError('No file supplied', True)
5865 if val.lower() in switchoff:
5868 sysvals.cgskip = sysvals.configFile(val)
5869 if(not sysvals.cgskip):
5870 doError('%s does not exist' % sysvals.cgskip)
5871 elif(arg == '-callloop-maxgap'):
5872 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
5873 elif(arg == '-callloop-maxlen'):
5874 sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)
5875 elif(arg == '-cmd'):
5879 doError('No command string supplied', True)
5880 sysvals.testcommand = val
5881 sysvals.suspendmode = 'command'
5882 elif(arg == '-expandcg'):
5883 sysvals.cgexp = True
5884 elif(arg == '-srgap'):
5886 elif(arg == '-multi'):
5887 sysvals.multitest['run'] = True
5888 sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000)
5889 sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600)
5894 doError('No subdirectory name supplied', True)
5895 sysvals.outdir = sysvals.setOutputFolder(val)
5896 elif(arg == '-config'):
5900 doError('No text file supplied', True)
5901 file = sysvals.configFile(val)
5903 doError('%s does not exist' % val)
5904 configFromFile(file)
5905 elif(arg == '-fadd'):
5909 doError('No text file supplied', True)
5910 file = sysvals.configFile(val)
5912 doError('%s does not exist' % val)
5913 sysvals.addFtraceFilterFunctions(file)
5914 elif(arg == '-dmesg'):
5918 doError('No dmesg file supplied', True)
5919 sysvals.notestrun = True
5920 sysvals.dmesgfile = val
5921 if(os.path.exists(sysvals.dmesgfile) == False):
5922 doError('%s does not exist' % sysvals.dmesgfile)
5923 elif(arg == '-ftrace'):
5927 doError('No ftrace file supplied', True)
5928 sysvals.notestrun = True
5929 sysvals.ftracefile = val
5930 if(os.path.exists(sysvals.ftracefile) == False):
5931 doError('%s does not exist' % sysvals.ftracefile)
5932 elif(arg == '-summary'):
5936 doError('No directory supplied', True)
5938 sysvals.outdir = val
5939 sysvals.notestrun = True
5940 if(os.path.isdir(val) == False):
5941 doError('%s is not accesible' % val)
5942 elif(arg == '-filter'):
5946 doError('No devnames supplied', True)
5947 sysvals.setDeviceFilter(val)
5948 elif(arg == '-result'):
5952 doError('No result file supplied', True)
5953 sysvals.result = val
5955 doError('Invalid argument: '+arg, True)
5957 # compatibility errors
5958 if(sysvals.usecallgraph and sysvals.usedevsrc):
5959 doError('-dev is not compatible with -f')
5960 if(sysvals.usecallgraph and sysvals.useprocmon):
5961 doError('-proc is not compatible with -f')
5963 if sysvals.usecallgraph and sysvals.cgskip:
5964 sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip)
5965 sysvals.setCallgraphBlacklist(sysvals.cgskip)
5967 # callgraph size cannot exceed device size
5968 if sysvals.mincglen < sysvals.mindevlen:
5969 sysvals.mincglen = sysvals.mindevlen
5971 # remove existing buffers before calculating memory
5972 if(sysvals.usecallgraph or sysvals.usedevsrc):
5973 sysvals.fsetVal('16', 'buffer_size_kb')
5976 # just run a utility command and exit
5978 if(cmd == 'status'):
5980 elif(cmd == 'fpdt'):
5982 elif(cmd == 'battery'):
5983 print 'AC Connect: %s\nCharge: %d' % getBattery()
5984 elif(cmd == 'sysinfo'):
5985 sysvals.printSystemInfo(True)
5986 elif(cmd == 'devinfo'):
5988 elif(cmd == 'modes'):
5990 elif(cmd == 'flist'):
5991 sysvals.getFtraceFilterFunctions(True)
5992 elif(cmd == 'flistall'):
5993 sysvals.getFtraceFilterFunctions(False)
5994 elif(cmd == 'summary'):
5995 runSummary(sysvals.outdir, True, genhtml)
5998 # if instructed, re-analyze existing data files
5999 if(sysvals.notestrun):
6001 sysvals.outputResult(stamp)
6004 # verify that we can run a test
6005 if(not statusCheck()):
6006 doError('Check FAILED, aborting the test run!')
6008 # extract mem modes and convert
6009 mode = sysvals.suspendmode
6010 if 'mem' == mode[:3]:
6012 memmode = mode.split('-')[-1]
6015 if memmode == 'shallow':
6017 elif memmode == 's2idle':
6021 sysvals.memmode = memmode
6022 sysvals.suspendmode = mode
6024 sysvals.systemInfo(dmidecode(sysvals.mempath))
6026 setRuntimeSuspend(True)
6028 call('xset -d :0.0 dpms 0 0 0', shell=True)
6029 call('xset -d :0.0 s off', shell=True)
6030 if sysvals.multitest['run']:
6031 # run multiple tests in a separate subdirectory
6032 if not sysvals.outdir:
6033 s = 'suspend-x%d' % sysvals.multitest['count']
6034 sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
6035 if not os.path.isdir(sysvals.outdir):
6036 os.mkdir(sysvals.outdir)
6037 for i in range(sysvals.multitest['count']):
6039 print('Waiting %d seconds...' % (sysvals.multitest['delay']))
6040 time.sleep(sysvals.multitest['delay'])
6041 print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count']))
6042 fmt = 'suspend-%y%m%d-%H%M%S'
6043 sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
6045 print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
6047 if not sysvals.skiphtml:
6048 runSummary(sysvals.outdir, False, False)
6049 sysvals.sudouser(sysvals.outdir)
6052 sysvals.testdir = sysvals.outdir
6053 # run the test in the current directory
6056 call('xset -d :0.0 s reset', shell=True)
6057 setRuntimeSuspend(False)