7184 lines · python
1#!/usr/bin/env python32# SPDX-License-Identifier: GPL-2.0-only3#4# Tool for analyzing suspend/resume timing5# Copyright (c) 2013, Intel Corporation.6#7# This program is free software; you can redistribute it and/or modify it8# under the terms and conditions of the GNU General Public License,9# version 2, as published by the Free Software Foundation.10#11# This program is distributed in the hope it will be useful, but WITHOUT12# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or13# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for14# more details.15#16# Authors:17# Todd Brandt <todd.e.brandt@linux.intel.com>18#19# Links:20# Home Page21# https://01.org/pm-graph22# Source repo23# git@github.com:intel/pm-graph24#25# Description:26# This tool is designed to assist kernel and OS developers in optimizing27# their linux stack's suspend/resume time. Using a kernel image built28# with a few extra options enabled, the tool will execute a suspend and29# will capture dmesg and ftrace data until resume is complete. This data30# is transformed into a device timeline and a callgraph to give a quick31# and detailed view of which devices and callbacks are taking the most32# time in suspend/resume. The output is a single html file which can be33# viewed in firefox or chrome.34#35# The following kernel build options are required:36# CONFIG_DEVMEM=y37# CONFIG_PM_DEBUG=y38# CONFIG_PM_SLEEP_DEBUG=y39# CONFIG_FTRACE=y40# CONFIG_FUNCTION_TRACER=y41# CONFIG_FUNCTION_GRAPH_TRACER=y42# CONFIG_KPROBES=y43# CONFIG_KPROBES_ON_FTRACE=y44#45# For kernel versions older than 3.15:46# The following additional kernel parameters are required:47# (e.g. in file /etc/default/grub)48# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."49#50 51# ----------------- LIBRARIES --------------------52 53import sys54import time55import os56import string57import re58import platform59import signal60import codecs61from datetime import datetime, timedelta62import struct63import configparser64import gzip65from threading import Thread66from subprocess import call, Popen, PIPE67import base6468 69debugtiming = False70mystarttime = time.time()71def pprint(msg):72 if debugtiming:73 print('[%09.3f] %s' % (time.time()-mystarttime, msg))74 else:75 print(msg)76 sys.stdout.flush()77 78def ascii(text):79 return text.decode('ascii', 'ignore')80 81# ----------------- CLASSES --------------------82 83# Class: SystemValues84# Description:85# A global, single-instance container used to86# store system values and test parameters87class SystemValues:88 title = 'SleepGraph'89 version = '5.12'90 ansi = False91 rs = 092 display = ''93 gzip = False94 sync = False95 wifi = False96 netfix = False97 verbose = False98 testlog = True99 dmesglog = True100 ftracelog = False101 acpidebug = True102 tstat = True103 wifitrace = False104 mindevlen = 0.0001105 mincglen = 0.0106 cgphase = ''107 cgtest = -1108 cgskip = ''109 maxfail = 0110 multitest = {'run': False, 'count': 1000000, 'delay': 0}111 max_graph_depth = 0112 callloopmaxgap = 0.0001113 callloopmaxlen = 0.005114 bufsize = 0115 cpucount = 0116 memtotal = 204800117 memfree = 204800118 osversion = ''119 srgap = 0120 cgexp = False121 testdir = ''122 outdir = ''123 tpath = '/sys/kernel/tracing/'124 fpdtpath = '/sys/firmware/acpi/tables/FPDT'125 epath = '/sys/kernel/tracing/events/power/'126 pmdpath = '/sys/power/pm_debug_messages'127 s0ixpath = '/sys/module/intel_pmc_core/parameters/warn_on_s0ix_failures'128 s0ixres = '/sys/devices/system/cpu/cpuidle/low_power_idle_system_residency_us'129 acpipath='/sys/module/acpi/parameters/debug_level'130 traceevents = [131 'suspend_resume',132 'wakeup_source_activate',133 'wakeup_source_deactivate',134 'device_pm_callback_end',135 'device_pm_callback_start'136 ]137 logmsg = ''138 testcommand = ''139 mempath = '/dev/mem'140 powerfile = '/sys/power/state'141 mempowerfile = '/sys/power/mem_sleep'142 diskpowerfile = '/sys/power/disk'143 suspendmode = 'mem'144 memmode = ''145 diskmode = ''146 hostname = 'localhost'147 prefix = 'test'148 teststamp = ''149 sysstamp = ''150 dmesgstart = 0.0151 dmesgfile = ''152 ftracefile = ''153 htmlfile = 'output.html'154 result = ''155 rtcwake = True156 rtcwaketime = 15157 rtcpath = ''158 devicefilter = []159 cgfilter = []160 stamp = 0161 execcount = 1162 x2delay = 0163 skiphtml = False164 usecallgraph = False165 ftopfunc = 'pm_suspend'166 ftop = False167 usetraceevents = False168 usetracemarkers = True169 useftrace = True170 usekprobes = True171 usedevsrc = False172 useprocmon = False173 notestrun = False174 cgdump = False175 devdump = False176 mixedphaseheight = True177 devprops = dict()178 cfgdef = dict()179 platinfo = []180 predelay = 0181 postdelay = 0182 tmstart = 'SUSPEND START %Y%m%d-%H:%M:%S.%f'183 tmend = 'RESUME COMPLETE %Y%m%d-%H:%M:%S.%f'184 tracefuncs = {185 'async_synchronize_full': {},186 'sys_sync': {},187 'ksys_sync': {},188 '__pm_notifier_call_chain': {},189 'pm_prepare_console': {},190 'pm_notifier_call_chain': {},191 'freeze_processes': {},192 'freeze_kernel_threads': {},193 'pm_restrict_gfp_mask': {},194 'acpi_suspend_begin': {},195 'acpi_hibernation_begin': {},196 'acpi_hibernation_enter': {},197 'acpi_hibernation_leave': {},198 'acpi_pm_freeze': {},199 'acpi_pm_thaw': {},200 'acpi_s2idle_end': {},201 'acpi_s2idle_sync': {},202 'acpi_s2idle_begin': {},203 'acpi_s2idle_prepare': {},204 'acpi_s2idle_prepare_late': {},205 'acpi_s2idle_wake': {},206 'acpi_s2idle_wakeup': {},207 'acpi_s2idle_restore': {},208 'acpi_s2idle_restore_early': {},209 'hibernate_preallocate_memory': {},210 'create_basic_memory_bitmaps': {},211 'swsusp_write': {},212 'suspend_console': {},213 'acpi_pm_prepare': {},214 'syscore_suspend': {},215 'arch_enable_nonboot_cpus_end': {},216 'syscore_resume': {},217 'acpi_pm_finish': {},218 'resume_console': {},219 'acpi_pm_end': {},220 'pm_restore_gfp_mask': {},221 'thaw_processes': {},222 'pm_restore_console': {},223 'CPU_OFF': {224 'func':'_cpu_down',225 'args_x86_64': {'cpu':'%di:s32'},226 'format': 'CPU_OFF[{cpu}]'227 },228 'CPU_ON': {229 'func':'_cpu_up',230 'args_x86_64': {'cpu':'%di:s32'},231 'format': 'CPU_ON[{cpu}]'232 },233 }234 dev_tracefuncs = {235 # general wait/delay/sleep236 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },237 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },238 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },239 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },240 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },241 'acpi_os_stall': {'ub': 1},242 'rt_mutex_slowlock': {'ub': 1},243 # ACPI244 'acpi_resume_power_resources': {},245 'acpi_ps_execute_method': { 'args_x86_64': {246 'fullpath':'+0(+40(%di)):string',247 }},248 # mei_me249 'mei_reset': {},250 # filesystem251 'ext4_sync_fs': {},252 # 80211253 'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} },254 'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} },255 'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} },256 'iwlagn_mac_start': {},257 'iwlagn_alloc_bcast_station': {},258 'iwl_trans_pcie_start_hw': {},259 'iwl_trans_pcie_start_fw': {},260 'iwl_run_init_ucode': {},261 'iwl_load_ucode_wait_alive': {},262 'iwl_alive_start': {},263 'iwlagn_mac_stop': {},264 'iwlagn_mac_suspend': {},265 'iwlagn_mac_resume': {},266 'iwlagn_mac_add_interface': {},267 'iwlagn_mac_remove_interface': {},268 'iwlagn_mac_change_interface': {},269 'iwlagn_mac_config': {},270 'iwlagn_configure_filter': {},271 'iwlagn_mac_hw_scan': {},272 'iwlagn_bss_info_changed': {},273 'iwlagn_mac_channel_switch': {},274 'iwlagn_mac_flush': {},275 # ATA276 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },277 # i915278 'i915_gem_resume': {},279 'i915_restore_state': {},280 'intel_opregion_setup': {},281 'g4x_pre_enable_dp': {},282 'vlv_pre_enable_dp': {},283 'chv_pre_enable_dp': {},284 'g4x_enable_dp': {},285 'vlv_enable_dp': {},286 'intel_hpd_init': {},287 'intel_opregion_register': {},288 'intel_dp_detect': {},289 'intel_hdmi_detect': {},290 'intel_opregion_init': {},291 'intel_fbdev_set_suspend': {},292 }293 infocmds = [294 [0, 'sysinfo', 'uname', '-a'],295 [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'],296 [0, 'kparams', 'cat', '/proc/cmdline'],297 [0, 'mcelog', 'mcelog'],298 [0, 'pcidevices', 'lspci', '-tv'],299 [0, 'usbdevices', 'lsusb', '-tv'],300 [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'],301 [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'],302 [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'],303 [0, 'ethtool', 'ethtool', '{ethdev}'],304 [1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'],305 [1, 'interrupts', 'cat', '/proc/interrupts'],306 [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'],307 [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'],308 [2, 'suspendstats', 'sh', '-c', 'grep -v invalid /sys/power/suspend_stats/*'],309 [2, 'cpuidle', 'sh', '-c', 'grep -v invalid /sys/devices/system/cpu/cpu*/cpuidle/state*/s2idle/*'],310 [2, 'battery', 'sh', '-c', 'grep -v invalid /sys/class/power_supply/*/*'],311 [2, 'thermal', 'sh', '-c', 'grep . /sys/class/thermal/thermal_zone*/temp'],312 ]313 cgblacklist = []314 kprobes = dict()315 timeformat = '%.3f'316 cmdline = '%s %s' % \317 (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))318 sudouser = ''319 def __init__(self):320 self.archargs = 'args_'+platform.machine()321 self.hostname = platform.node()322 if(self.hostname == ''):323 self.hostname = 'localhost'324 rtc = "rtc0"325 if os.path.exists('/dev/rtc'):326 rtc = os.readlink('/dev/rtc')327 rtc = '/sys/class/rtc/'+rtc328 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \329 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):330 self.rtcpath = rtc331 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):332 self.ansi = True333 self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')334 if os.getuid() == 0 and 'SUDO_USER' in os.environ and \335 os.environ['SUDO_USER']:336 self.sudouser = os.environ['SUDO_USER']337 def resetlog(self):338 self.logmsg = ''339 self.platinfo = []340 def vprint(self, msg):341 self.logmsg += msg+'\n'342 if self.verbose or msg.startswith('WARNING:'):343 pprint(msg)344 def signalHandler(self, signum, frame):345 if not self.result:346 return347 signame = self.signames[signum] if signum in self.signames else 'UNKNOWN'348 msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno)349 self.outputResult({'error':msg})350 sys.exit(3)351 def signalHandlerInit(self):352 capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT',353 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM']354 self.signames = dict()355 for i in capture:356 s = 'SIG'+i357 try:358 signum = getattr(signal, s)359 signal.signal(signum, self.signalHandler)360 except:361 continue362 self.signames[signum] = s363 def rootCheck(self, fatal=True):364 if(os.access(self.powerfile, os.W_OK)):365 return True366 if fatal:367 msg = 'This command requires sysfs mount and root access'368 pprint('ERROR: %s\n' % msg)369 self.outputResult({'error':msg})370 sys.exit(1)371 return False372 def rootUser(self, fatal=False):373 if 'USER' in os.environ and os.environ['USER'] == 'root':374 return True375 if fatal:376 msg = 'This command must be run as root'377 pprint('ERROR: %s\n' % msg)378 self.outputResult({'error':msg})379 sys.exit(1)380 return False381 def usable(self, file, ishtml=False):382 if not os.path.exists(file) or os.path.getsize(file) < 1:383 return False384 if ishtml:385 try:386 fp = open(file, 'r')387 res = fp.read(1000)388 fp.close()389 except:390 return False391 if '<html>' not in res:392 return False393 return True394 def getExec(self, cmd):395 try:396 fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout397 out = ascii(fp.read()).strip()398 fp.close()399 except:400 out = ''401 if out:402 return out403 for path in ['/sbin', '/bin', '/usr/sbin', '/usr/bin',404 '/usr/local/sbin', '/usr/local/bin']:405 cmdfull = os.path.join(path, cmd)406 if os.path.exists(cmdfull):407 return cmdfull408 return out409 def setPrecision(self, num):410 if num < 0 or num > 6:411 return412 self.timeformat = '%.{0}f'.format(num)413 def setOutputFolder(self, value):414 args = dict()415 n = datetime.now()416 args['date'] = n.strftime('%y%m%d')417 args['time'] = n.strftime('%H%M%S')418 args['hostname'] = args['host'] = self.hostname419 args['mode'] = self.suspendmode420 return value.format(**args)421 def setOutputFile(self):422 if self.dmesgfile != '':423 m = re.match(r'(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)424 if(m):425 self.htmlfile = m.group('name')+'.html'426 if self.ftracefile != '':427 m = re.match(r'(?P<name>.*)_ftrace\.txt.*', self.ftracefile)428 if(m):429 self.htmlfile = m.group('name')+'.html'430 def systemInfo(self, info):431 p = m = ''432 if 'baseboard-manufacturer' in info:433 m = info['baseboard-manufacturer']434 elif 'system-manufacturer' in info:435 m = info['system-manufacturer']436 if 'system-product-name' in info:437 p = info['system-product-name']438 elif 'baseboard-product-name' in info:439 p = info['baseboard-product-name']440 if m[:5].lower() == 'intel' and 'baseboard-product-name' in info:441 p = info['baseboard-product-name']442 c = info['processor-version'] if 'processor-version' in info else ''443 b = info['bios-version'] if 'bios-version' in info else ''444 r = info['bios-release-date'] if 'bios-release-date' in info else ''445 self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \446 (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree)447 if self.osversion:448 self.sysstamp += ' | os:%s' % self.osversion449 def printSystemInfo(self, fatal=False):450 self.rootCheck(True)451 out = dmidecode(self.mempath, fatal)452 if len(out) < 1:453 return454 fmt = '%-24s: %s'455 if self.osversion:456 print(fmt % ('os-version', self.osversion))457 for name in sorted(out):458 print(fmt % (name, out[name]))459 print(fmt % ('cpucount', ('%d' % self.cpucount)))460 print(fmt % ('memtotal', ('%d kB' % self.memtotal)))461 print(fmt % ('memfree', ('%d kB' % self.memfree)))462 def cpuInfo(self):463 self.cpucount = 0464 if os.path.exists('/proc/cpuinfo'):465 with open('/proc/cpuinfo', 'r') as fp:466 for line in fp:467 if re.match(r'^processor[ \t]*:[ \t]*[0-9]*', line):468 self.cpucount += 1469 if os.path.exists('/proc/meminfo'):470 with open('/proc/meminfo', 'r') as fp:471 for line in fp:472 m = re.match(r'^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)473 if m:474 self.memtotal = int(m.group('sz'))475 m = re.match(r'^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)476 if m:477 self.memfree = int(m.group('sz'))478 if os.path.exists('/etc/os-release'):479 with open('/etc/os-release', 'r') as fp:480 for line in fp:481 if line.startswith('PRETTY_NAME='):482 self.osversion = line[12:].strip().replace('"', '')483 def initTestOutput(self, name):484 self.prefix = self.hostname485 v = open('/proc/version', 'r').read().strip()486 kver = v.split()[2]487 fmt = name+'-%m%d%y-%H%M%S'488 testtime = datetime.now().strftime(fmt)489 self.teststamp = \490 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver491 ext = ''492 if self.gzip:493 ext = '.gz'494 self.dmesgfile = \495 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext496 self.ftracefile = \497 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext498 self.htmlfile = \499 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'500 if not os.path.isdir(self.testdir):501 os.makedirs(self.testdir)502 self.sudoUserchown(self.testdir)503 def getValueList(self, value):504 out = []505 for i in value.split(','):506 if i.strip():507 out.append(i.strip())508 return out509 def setDeviceFilter(self, value):510 self.devicefilter = self.getValueList(value)511 def setCallgraphFilter(self, value):512 self.cgfilter = self.getValueList(value)513 def skipKprobes(self, value):514 for k in self.getValueList(value):515 if k in self.tracefuncs:516 del self.tracefuncs[k]517 if k in self.dev_tracefuncs:518 del self.dev_tracefuncs[k]519 def setCallgraphBlacklist(self, file):520 self.cgblacklist = self.listFromFile(file)521 def rtcWakeAlarmOn(self):522 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)523 nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()524 if nowtime:525 nowtime = int(nowtime)526 else:527 # if hardware time fails, use the software time528 nowtime = int(datetime.now().strftime('%s'))529 alarm = nowtime + self.rtcwaketime530 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)531 def rtcWakeAlarmOff(self):532 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)533 def initdmesg(self):534 # get the latest time stamp from the dmesg log535 lines = Popen('dmesg', stdout=PIPE).stdout.readlines()536 ktime = '0'537 for line in reversed(lines):538 line = ascii(line).replace('\r\n', '')539 idx = line.find('[')540 if idx > 1:541 line = line[idx:]542 m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)543 if(m):544 ktime = m.group('ktime')545 break546 self.dmesgstart = float(ktime)547 def getdmesg(self, testdata):548 op = self.writeDatafileHeader(self.dmesgfile, testdata)549 # store all new dmesg lines since initdmesg was called550 fp = Popen('dmesg', stdout=PIPE).stdout551 for line in fp:552 line = ascii(line).replace('\r\n', '')553 idx = line.find('[')554 if idx > 1:555 line = line[idx:]556 m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)557 if(not m):558 continue559 ktime = float(m.group('ktime'))560 if ktime > self.dmesgstart:561 op.write(line)562 fp.close()563 op.close()564 def listFromFile(self, file):565 list = []566 fp = open(file)567 for i in fp.read().split('\n'):568 i = i.strip()569 if i and i[0] != '#':570 list.append(i)571 fp.close()572 return list573 def addFtraceFilterFunctions(self, file):574 for i in self.listFromFile(file):575 if len(i) < 2:576 continue577 self.tracefuncs[i] = dict()578 def getFtraceFilterFunctions(self, current):579 self.rootCheck(True)580 if not current:581 call('cat '+self.tpath+'available_filter_functions', shell=True)582 return583 master = self.listFromFile(self.tpath+'available_filter_functions')584 for i in sorted(self.tracefuncs):585 if 'func' in self.tracefuncs[i]:586 i = self.tracefuncs[i]['func']587 if i in master:588 print(i)589 else:590 print(self.colorText(i))591 def setFtraceFilterFunctions(self, list):592 master = self.listFromFile(self.tpath+'available_filter_functions')593 flist = ''594 for i in list:595 if i not in master:596 continue597 if ' [' in i:598 flist += i.split(' ')[0]+'\n'599 else:600 flist += i+'\n'601 fp = open(self.tpath+'set_graph_function', 'w')602 fp.write(flist)603 fp.close()604 def basicKprobe(self, name):605 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}606 def defaultKprobe(self, name, kdata):607 k = kdata608 for field in ['name', 'format', 'func']:609 if field not in k:610 k[field] = name611 if self.archargs in k:612 k['args'] = k[self.archargs]613 else:614 k['args'] = dict()615 k['format'] = name616 self.kprobes[name] = k617 def kprobeColor(self, name):618 if name not in self.kprobes or 'color' not in self.kprobes[name]:619 return ''620 return self.kprobes[name]['color']621 def kprobeDisplayName(self, name, dataraw):622 if name not in self.kprobes:623 self.basicKprobe(name)624 data = ''625 quote=0626 # first remvoe any spaces inside quotes, and the quotes627 for c in dataraw:628 if c == '"':629 quote = (quote + 1) % 2630 if quote and c == ' ':631 data += '_'632 elif c != '"':633 data += c634 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']635 arglist = dict()636 # now process the args637 for arg in sorted(args):638 arglist[arg] = ''639 m = re.match(r'.* '+arg+'=(?P<arg>.*) ', data);640 if m:641 arglist[arg] = m.group('arg')642 else:643 m = re.match(r'.* '+arg+'=(?P<arg>.*)', data);644 if m:645 arglist[arg] = m.group('arg')646 out = fmt.format(**arglist)647 out = out.replace(' ', '_').replace('"', '')648 return out649 def kprobeText(self, kname, kprobe):650 name = fmt = func = kname651 args = dict()652 if 'name' in kprobe:653 name = kprobe['name']654 if 'format' in kprobe:655 fmt = kprobe['format']656 if 'func' in kprobe:657 func = kprobe['func']658 if self.archargs in kprobe:659 args = kprobe[self.archargs]660 if 'args' in kprobe:661 args = kprobe['args']662 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):663 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))664 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):665 if arg not in args:666 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))667 val = 'p:%s_cal %s' % (name, func)668 for i in sorted(args):669 val += ' %s=%s' % (i, args[i])670 val += '\nr:%s_ret %s $retval\n' % (name, func)671 return val672 def addKprobes(self, output=False):673 if len(self.kprobes) < 1:674 return675 if output:676 pprint(' kprobe functions in this kernel:')677 # first test each kprobe678 rejects = []679 # sort kprobes: trace, ub-dev, custom, dev680 kpl = [[], [], [], []]681 linesout = len(self.kprobes)682 for name in sorted(self.kprobes):683 res = self.colorText('YES', 32)684 if not self.testKprobe(name, self.kprobes[name]):685 res = self.colorText('NO')686 rejects.append(name)687 else:688 if name in self.tracefuncs:689 kpl[0].append(name)690 elif name in self.dev_tracefuncs:691 if 'ub' in self.dev_tracefuncs[name]:692 kpl[1].append(name)693 else:694 kpl[3].append(name)695 else:696 kpl[2].append(name)697 if output:698 pprint(' %s: %s' % (name, res))699 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]700 # remove all failed ones from the list701 for name in rejects:702 self.kprobes.pop(name)703 # set the kprobes all at once704 self.fsetVal('', 'kprobe_events')705 kprobeevents = ''706 for kp in kplist:707 kprobeevents += self.kprobeText(kp, self.kprobes[kp])708 self.fsetVal(kprobeevents, 'kprobe_events')709 if output:710 check = self.fgetVal('kprobe_events')711 linesack = (len(check.split('\n')) - 1) // 2712 pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout))713 self.fsetVal('1', 'events/kprobes/enable')714 def testKprobe(self, kname, kprobe):715 self.fsetVal('0', 'events/kprobes/enable')716 kprobeevents = self.kprobeText(kname, kprobe)717 if not kprobeevents:718 return False719 try:720 self.fsetVal(kprobeevents, 'kprobe_events')721 check = self.fgetVal('kprobe_events')722 except:723 return False724 linesout = len(kprobeevents.split('\n'))725 linesack = len(check.split('\n'))726 if linesack < linesout:727 return False728 return True729 def setVal(self, val, file):730 if not os.path.exists(file):731 return False732 try:733 fp = open(file, 'wb', 0)734 fp.write(val.encode())735 fp.flush()736 fp.close()737 except:738 return False739 return True740 def fsetVal(self, val, path):741 if not self.useftrace:742 return False743 return self.setVal(val, self.tpath+path)744 def getVal(self, file):745 res = ''746 if not os.path.exists(file):747 return res748 try:749 fp = open(file, 'r')750 res = fp.read()751 fp.close()752 except:753 pass754 return res755 def fgetVal(self, path):756 if not self.useftrace:757 return ''758 return self.getVal(self.tpath+path)759 def cleanupFtrace(self):760 if self.useftrace:761 self.fsetVal('0', 'events/kprobes/enable')762 self.fsetVal('', 'kprobe_events')763 self.fsetVal('1024', 'buffer_size_kb')764 def setupAllKprobes(self):765 for name in self.tracefuncs:766 self.defaultKprobe(name, self.tracefuncs[name])767 for name in self.dev_tracefuncs:768 self.defaultKprobe(name, self.dev_tracefuncs[name])769 def isCallgraphFunc(self, name):770 if len(self.tracefuncs) < 1 and self.suspendmode == 'command':771 return True772 for i in self.tracefuncs:773 if 'func' in self.tracefuncs[i]:774 f = self.tracefuncs[i]['func']775 else:776 f = i777 if name == f:778 return True779 return False780 def initFtrace(self, quiet=False):781 if not self.useftrace:782 return783 if not quiet:784 sysvals.printSystemInfo(False)785 pprint('INITIALIZING FTRACE')786 # turn trace off787 self.fsetVal('0', 'tracing_on')788 self.cleanupFtrace()789 # set the trace clock to global790 self.fsetVal('global', 'trace_clock')791 self.fsetVal('nop', 'current_tracer')792 # set trace buffer to an appropriate value793 cpus = max(1, self.cpucount)794 if self.bufsize > 0:795 tgtsize = self.bufsize796 elif self.usecallgraph or self.usedevsrc:797 bmax = (1*1024*1024) if self.suspendmode in ['disk', 'command'] \798 else (3*1024*1024)799 tgtsize = min(self.memfree, bmax)800 else:801 tgtsize = 65536802 while not self.fsetVal('%d' % (tgtsize // cpus), 'buffer_size_kb'):803 # if the size failed to set, lower it and keep trying804 tgtsize -= 65536805 if tgtsize < 65536:806 tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus807 break808 self.vprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus))809 # initialize the callgraph trace810 if(self.usecallgraph):811 # set trace type812 self.fsetVal('function_graph', 'current_tracer')813 self.fsetVal('', 'set_ftrace_filter')814 # temporary hack to fix https://bugzilla.kernel.org/show_bug.cgi?id=212761815 fp = open(self.tpath+'set_ftrace_notrace', 'w')816 fp.write('native_queued_spin_lock_slowpath\ndev_driver_string')817 fp.close()818 # set trace format options819 self.fsetVal('print-parent', 'trace_options')820 self.fsetVal('funcgraph-abstime', 'trace_options')821 self.fsetVal('funcgraph-cpu', 'trace_options')822 self.fsetVal('funcgraph-duration', 'trace_options')823 self.fsetVal('funcgraph-proc', 'trace_options')824 self.fsetVal('funcgraph-tail', 'trace_options')825 self.fsetVal('nofuncgraph-overhead', 'trace_options')826 self.fsetVal('context-info', 'trace_options')827 self.fsetVal('graph-time', 'trace_options')828 self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')829 cf = ['dpm_run_callback']830 if(self.usetraceevents):831 cf += ['dpm_prepare', 'dpm_complete']832 for fn in self.tracefuncs:833 if 'func' in self.tracefuncs[fn]:834 cf.append(self.tracefuncs[fn]['func'])835 else:836 cf.append(fn)837 if self.ftop:838 self.setFtraceFilterFunctions([self.ftopfunc])839 else:840 self.setFtraceFilterFunctions(cf)841 # initialize the kprobe trace842 elif self.usekprobes:843 for name in self.tracefuncs:844 self.defaultKprobe(name, self.tracefuncs[name])845 if self.usedevsrc:846 for name in self.dev_tracefuncs:847 self.defaultKprobe(name, self.dev_tracefuncs[name])848 if not quiet:849 pprint('INITIALIZING KPROBES')850 self.addKprobes(self.verbose)851 if(self.usetraceevents):852 # turn trace events on853 events = iter(self.traceevents)854 for e in events:855 self.fsetVal('1', 'events/power/'+e+'/enable')856 # clear the trace buffer857 self.fsetVal('', 'trace')858 def verifyFtrace(self):859 # files needed for any trace data860 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',861 'trace_marker', 'trace_options', 'tracing_on']862 # files needed for callgraph trace data863 tp = self.tpath864 if(self.usecallgraph):865 files += [866 'available_filter_functions',867 'set_ftrace_filter',868 'set_graph_function'869 ]870 for f in files:871 if(os.path.exists(tp+f) == False):872 return False873 return True874 def verifyKprobes(self):875 # files needed for kprobes to work876 files = ['kprobe_events', 'events']877 tp = self.tpath878 for f in files:879 if(os.path.exists(tp+f) == False):880 return False881 return True882 def colorText(self, str, color=31):883 if not self.ansi:884 return str885 return '\x1B[%d;40m%s\x1B[m' % (color, str)886 def writeDatafileHeader(self, filename, testdata):887 fp = self.openlog(filename, 'w')888 fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))889 for test in testdata:890 if 'fw' in test:891 fw = test['fw']892 if(fw):893 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))894 if 'turbo' in test:895 fp.write('# turbostat %s\n' % test['turbo'])896 if 'wifi' in test:897 fp.write('# wifi %s\n' % test['wifi'])898 if 'netfix' in test:899 fp.write('# netfix %s\n' % test['netfix'])900 if test['error'] or len(testdata) > 1:901 fp.write('# enter_sleep_error %s\n' % test['error'])902 return fp903 def sudoUserchown(self, dir):904 if os.path.exists(dir) and self.sudouser:905 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'906 call(cmd.format(self.sudouser, dir), shell=True)907 def outputResult(self, testdata, num=0):908 if not self.result:909 return910 n = ''911 if num > 0:912 n = '%d' % num913 fp = open(self.result, 'a')914 if 'error' in testdata:915 fp.write('result%s: fail\n' % n)916 fp.write('error%s: %s\n' % (n, testdata['error']))917 else:918 fp.write('result%s: pass\n' % n)919 if 'mode' in testdata:920 fp.write('mode%s: %s\n' % (n, testdata['mode']))921 for v in ['suspend', 'resume', 'boot', 'lastinit']:922 if v in testdata:923 fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))924 for v in ['fwsuspend', 'fwresume']:925 if v in testdata:926 fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0))927 if 'bugurl' in testdata:928 fp.write('url%s: %s\n' % (n, testdata['bugurl']))929 fp.close()930 self.sudoUserchown(self.result)931 def configFile(self, file):932 dir = os.path.dirname(os.path.realpath(__file__))933 if os.path.exists(file):934 return file935 elif os.path.exists(dir+'/'+file):936 return dir+'/'+file937 elif os.path.exists(dir+'/config/'+file):938 return dir+'/config/'+file939 return ''940 def openlog(self, filename, mode):941 isgz = self.gzip942 if mode == 'r':943 try:944 with gzip.open(filename, mode+'t') as fp:945 test = fp.read(64)946 isgz = True947 except:948 isgz = False949 if isgz:950 return gzip.open(filename, mode+'t')951 return open(filename, mode)952 def putlog(self, filename, text):953 with self.openlog(filename, 'a') as fp:954 fp.write(text)955 fp.close()956 def dlog(self, text):957 if not self.dmesgfile:958 return959 self.putlog(self.dmesgfile, '# %s\n' % text)960 def flog(self, text):961 self.putlog(self.ftracefile, text)962 def b64unzip(self, data):963 try:964 out = codecs.decode(base64.b64decode(data), 'zlib').decode()965 except:966 out = data967 return out968 def b64zip(self, data):969 out = base64.b64encode(codecs.encode(data.encode(), 'zlib')).decode()970 return out971 def platforminfo(self, cmdafter):972 # add platform info on to a completed ftrace file973 if not os.path.exists(self.ftracefile):974 return False975 footer = '#\n'976 977 # add test command string line if need be978 if self.suspendmode == 'command' and self.testcommand:979 footer += '# platform-testcmd: %s\n' % (self.testcommand)980 981 # get a list of target devices from the ftrace file982 props = dict()983 tp = TestProps()984 tf = self.openlog(self.ftracefile, 'r')985 for line in tf:986 if tp.stampInfo(line, self):987 continue988 # parse only valid lines, if this is not one move on989 m = re.match(tp.ftrace_line_fmt, line)990 if(not m or 'device_pm_callback_start' not in line):991 continue992 m = re.match(r'.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));993 if(not m):994 continue995 dev = m.group('d')996 if dev not in props:997 props[dev] = DevProps()998 tf.close()999 1000 # now get the syspath for each target device1001 for dirname, dirnames, filenames in os.walk('/sys/devices'):1002 if(re.match(r'.*/power', dirname) and 'async' in filenames):1003 dev = dirname.split('/')[-2]1004 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):1005 props[dev].syspath = dirname[:-6]1006 1007 # now fill in the properties for our target devices1008 for dev in sorted(props):1009 dirname = props[dev].syspath1010 if not dirname or not os.path.exists(dirname):1011 continue1012 props[dev].isasync = False1013 if os.path.exists(dirname+'/power/async'):1014 fp = open(dirname+'/power/async')1015 if 'enabled' in fp.read():1016 props[dev].isasync = True1017 fp.close()1018 fields = os.listdir(dirname)1019 for file in ['product', 'name', 'model', 'description', 'id', 'idVendor']:1020 if file not in fields:1021 continue1022 try:1023 with open(os.path.join(dirname, file), 'rb') as fp:1024 props[dev].altname = ascii(fp.read())1025 except:1026 continue1027 if file == 'idVendor':1028 idv, idp = props[dev].altname.strip(), ''1029 try:1030 with open(os.path.join(dirname, 'idProduct'), 'rb') as fp:1031 idp = ascii(fp.read()).strip()1032 except:1033 props[dev].altname = ''1034 break1035 props[dev].altname = '%s:%s' % (idv, idp)1036 break1037 if props[dev].altname:1038 out = props[dev].altname.strip().replace('\n', ' ')\1039 .replace(',', ' ').replace(';', ' ')1040 props[dev].altname = out1041 1042 # add a devinfo line to the bottom of ftrace1043 out = ''1044 for dev in sorted(props):1045 out += props[dev].out(dev)1046 footer += '# platform-devinfo: %s\n' % self.b64zip(out)1047 1048 # add a line for each of these commands with their outputs1049 for name, cmdline, info in cmdafter:1050 footer += '# platform-%s: %s | %s\n' % (name, cmdline, self.b64zip(info))1051 self.flog(footer)1052 return True1053 def commonPrefix(self, list):1054 if len(list) < 2:1055 return ''1056 prefix = list[0]1057 for s in list[1:]:1058 while s[:len(prefix)] != prefix and prefix:1059 prefix = prefix[:len(prefix)-1]1060 if not prefix:1061 break1062 if '/' in prefix and prefix[-1] != '/':1063 prefix = prefix[0:prefix.rfind('/')+1]1064 return prefix1065 def dictify(self, text, format):1066 out = dict()1067 header = True if format == 1 else False1068 delim = ' ' if format == 1 else ':'1069 for line in text.split('\n'):1070 if header:1071 header, out['@'] = False, line1072 continue1073 line = line.strip()1074 if delim in line:1075 data = line.split(delim, 1)1076 num = re.search(r'[\d]+', data[1])1077 if format == 2 and num:1078 out[data[0].strip()] = num.group()1079 else:1080 out[data[0].strip()] = data[1]1081 return out1082 def cmdinfovar(self, arg):1083 if arg == 'ethdev':1084 try:1085 cmd = [self.getExec('ip'), '-4', '-o', '-br', 'addr']1086 fp = Popen(cmd, stdout=PIPE, stderr=PIPE).stdout1087 info = ascii(fp.read()).strip()1088 fp.close()1089 except:1090 return 'iptoolcrash'1091 for line in info.split('\n'):1092 if line[0] == 'e' and 'UP' in line:1093 return line.split()[0]1094 return 'nodevicefound'1095 return 'unknown'1096 def cmdinfo(self, begin, debug=False):1097 out = []1098 if begin:1099 self.cmd1 = dict()1100 for cargs in self.infocmds:1101 delta, name, args = cargs[0], cargs[1], cargs[2:]1102 for i in range(len(args)):1103 if args[i][0] == '{' and args[i][-1] == '}':1104 args[i] = self.cmdinfovar(args[i][1:-1])1105 cmdline, cmdpath = ' '.join(args[0:]), self.getExec(args[0])1106 if not cmdpath or (begin and not delta):1107 continue1108 self.dlog('[%s]' % cmdline)1109 try:1110 fp = Popen([cmdpath]+args[1:], stdout=PIPE, stderr=PIPE).stdout1111 info = ascii(fp.read()).strip()1112 fp.close()1113 except:1114 continue1115 if not debug and begin:1116 self.cmd1[name] = self.dictify(info, delta)1117 elif not debug and delta and name in self.cmd1:1118 before, after = self.cmd1[name], self.dictify(info, delta)1119 dinfo = ('\t%s\n' % before['@']) if '@' in before and len(before) > 1 else ''1120 prefix = self.commonPrefix(list(before.keys()))1121 for key in sorted(before):1122 if key in after and before[key] != after[key]:1123 title = key.replace(prefix, '')1124 if delta == 2:1125 dinfo += '\t%s : %s -> %s\n' % \1126 (title, before[key].strip(), after[key].strip())1127 else:1128 dinfo += '%10s (start) : %s\n%10s (after) : %s\n' % \1129 (title, before[key], title, after[key])1130 dinfo = '\tnothing changed' if not dinfo else dinfo.rstrip()1131 out.append((name, cmdline, dinfo))1132 else:1133 out.append((name, cmdline, '\tnothing' if not info else info))1134 return out1135 def testVal(self, file, fmt='basic', value=''):1136 if file == 'restoreall':1137 for f in self.cfgdef:1138 if os.path.exists(f):1139 fp = open(f, 'w')1140 fp.write(self.cfgdef[f])1141 fp.close()1142 self.cfgdef = dict()1143 elif value and os.path.exists(file):1144 fp = open(file, 'r+')1145 if fmt == 'radio':1146 m = re.match(r'.*\[(?P<v>.*)\].*', fp.read())1147 if m:1148 self.cfgdef[file] = m.group('v')1149 elif fmt == 'acpi':1150 line = fp.read().strip().split('\n')[-1]1151 m = re.match(r'.* (?P<v>[0-9A-Fx]*) .*', line)1152 if m:1153 self.cfgdef[file] = m.group('v')1154 else:1155 self.cfgdef[file] = fp.read().strip()1156 fp.write(value)1157 fp.close()1158 def s0ixSupport(self):1159 if not os.path.exists(self.s0ixres) or not os.path.exists(self.mempowerfile):1160 return False1161 fp = open(sysvals.mempowerfile, 'r')1162 data = fp.read().strip()1163 fp.close()1164 if '[s2idle]' in data:1165 return True1166 return False1167 def haveTurbostat(self):1168 if not self.tstat:1169 return False1170 cmd = self.getExec('turbostat')1171 if not cmd:1172 return False1173 fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr1174 out = ascii(fp.read()).strip()1175 fp.close()1176 if re.match(r'turbostat version .*', out):1177 self.vprint(out)1178 return True1179 return False1180 def turbostat(self, s0ixready):1181 cmd = self.getExec('turbostat')1182 rawout = keyline = valline = ''1183 fullcmd = '%s -q -S echo freeze > %s' % (cmd, self.powerfile)1184 fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE)1185 for line in fp.stderr:1186 line = ascii(line)1187 rawout += line1188 if keyline and valline:1189 continue1190 if re.match(r'(?i)Avg_MHz.*', line):1191 keyline = line.strip().split()1192 elif keyline:1193 valline = line.strip().split()1194 fp.wait()1195 if not keyline or not valline or len(keyline) != len(valline):1196 errmsg = 'unrecognized turbostat output:\n'+rawout.strip()1197 self.vprint(errmsg)1198 if not self.verbose:1199 pprint(errmsg)1200 return (fp.returncode, '')1201 if self.verbose:1202 pprint(rawout.strip())1203 out = []1204 for key in keyline:1205 idx = keyline.index(key)1206 val = valline[idx]1207 if key == 'SYS%LPI' and not s0ixready and re.match(r'^[0\.]*$', val):1208 continue1209 out.append('%s=%s' % (key, val))1210 return (fp.returncode, '|'.join(out))1211 def netfixon(self, net='both'):1212 cmd = self.getExec('netfix')1213 if not cmd:1214 return ''1215 fp = Popen([cmd, '-s', net, 'on'], stdout=PIPE, stderr=PIPE).stdout1216 out = ascii(fp.read()).strip()1217 fp.close()1218 return out1219 def wifiDetails(self, dev):1220 try:1221 info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip()1222 except:1223 return dev1224 vals = [dev]1225 for prop in info.split('\n'):1226 if prop.startswith('DRIVER=') or prop.startswith('PCI_ID='):1227 vals.append(prop.split('=')[-1])1228 return ':'.join(vals)1229 def checkWifi(self, dev=''):1230 try:1231 w = open('/proc/net/wireless', 'r').read().strip()1232 except:1233 return ''1234 for line in reversed(w.split('\n')):1235 m = re.match(r' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', line)1236 if not m or (dev and dev != m.group('dev')):1237 continue1238 return m.group('dev')1239 return ''1240 def pollWifi(self, dev, timeout=10):1241 start = time.time()1242 while (time.time() - start) < timeout:1243 w = self.checkWifi(dev)1244 if w:1245 return '%s reconnected %.2f' % \1246 (self.wifiDetails(dev), max(0, time.time() - start))1247 time.sleep(0.01)1248 return '%s timeout %d' % (self.wifiDetails(dev), timeout)1249 def errorSummary(self, errinfo, msg):1250 found = False1251 for entry in errinfo:1252 if re.match(entry['match'], msg):1253 entry['count'] += 11254 if self.hostname not in entry['urls']:1255 entry['urls'][self.hostname] = [self.htmlfile]1256 elif self.htmlfile not in entry['urls'][self.hostname]:1257 entry['urls'][self.hostname].append(self.htmlfile)1258 found = True1259 break1260 if found:1261 return1262 arr = msg.split()1263 for j in range(len(arr)):1264 if re.match(r'^[0-9,\-\.]*$', arr[j]):1265 arr[j] = r'[0-9,\-\.]*'1266 else:1267 arr[j] = arr[j]\1268 .replace('\\', r'\\\\').replace(']', r'\]').replace('[', r'\[')\1269 .replace('.', r'\.').replace('+', r'\+').replace('*', r'\*')\1270 .replace('(', r'\(').replace(')', r'\)').replace('}', r'\}')\1271 .replace('{', r'\{')1272 mstr = ' *'.join(arr)1273 entry = {1274 'line': msg,1275 'match': mstr,1276 'count': 1,1277 'urls': {self.hostname: [self.htmlfile]}1278 }1279 errinfo.append(entry)1280 def multistat(self, start, idx, finish):1281 if 'time' in self.multitest:1282 id = '%d Duration=%dmin' % (idx+1, self.multitest['time'])1283 else:1284 id = '%d/%d' % (idx+1, self.multitest['count'])1285 t = time.time()1286 if 'start' not in self.multitest:1287 self.multitest['start'] = self.multitest['last'] = t1288 self.multitest['total'] = 0.01289 pprint('TEST (%s) START' % id)1290 return1291 dt = t - self.multitest['last']1292 if not start:1293 if idx == 0 and self.multitest['delay'] > 0:1294 self.multitest['total'] += self.multitest['delay']1295 pprint('TEST (%s) COMPLETE -- Duration %.1fs' % (id, dt))1296 return1297 self.multitest['total'] += dt1298 self.multitest['last'] = t1299 avg = self.multitest['total'] / idx1300 if 'time' in self.multitest:1301 left = finish - datetime.now()1302 left -= timedelta(microseconds=left.microseconds)1303 else:1304 left = timedelta(seconds=((self.multitest['count'] - idx) * int(avg)))1305 pprint('TEST (%s) START - Avg Duration %.1fs, Time left %s' % \1306 (id, avg, str(left)))1307 def multiinit(self, c, d):1308 sz, unit = 'count', 'm'1309 if c.endswith('d') or c.endswith('h') or c.endswith('m'):1310 sz, unit, c = 'time', c[-1], c[:-1]1311 self.multitest['run'] = True1312 self.multitest[sz] = getArgInt('multi: n d (exec count)', c, 1, 1000000, False)1313 self.multitest['delay'] = getArgInt('multi: n d (delay between tests)', d, 0, 3600, False)1314 if unit == 'd':1315 self.multitest[sz] *= 14401316 elif unit == 'h':1317 self.multitest[sz] *= 601318 def displayControl(self, cmd):1319 xset, ret = 'timeout 10 xset -d :0.0 {0}', 01320 if self.sudouser:1321 xset = 'sudo -u %s %s' % (self.sudouser, xset)1322 if cmd == 'init':1323 ret = call(xset.format('dpms 0 0 0'), shell=True)1324 if not ret:1325 ret = call(xset.format('s off'), shell=True)1326 elif cmd == 'reset':1327 ret = call(xset.format('s reset'), shell=True)1328 elif cmd in ['on', 'off', 'standby', 'suspend']:1329 b4 = self.displayControl('stat')1330 ret = call(xset.format('dpms force %s' % cmd), shell=True)1331 if not ret:1332 curr = self.displayControl('stat')1333 self.vprint('Display Switched: %s -> %s' % (b4, curr))1334 if curr != cmd:1335 self.vprint('WARNING: Display failed to change to %s' % cmd)1336 if ret:1337 self.vprint('WARNING: Display failed to change to %s with xset' % cmd)1338 return ret1339 elif cmd == 'stat':1340 fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout1341 ret = 'unknown'1342 for line in fp:1343 m = re.match(r'[\s]*Monitor is (?P<m>.*)', ascii(line))1344 if(m and len(m.group('m')) >= 2):1345 out = m.group('m').lower()1346 ret = out[3:] if out[0:2] == 'in' else out1347 break1348 fp.close()1349 return ret1350 def setRuntimeSuspend(self, before=True):1351 if before:1352 # runtime suspend disable or enable1353 if self.rs > 0:1354 self.rstgt, self.rsval, self.rsdir = 'on', 'auto', 'enabled'1355 else:1356 self.rstgt, self.rsval, self.rsdir = 'auto', 'on', 'disabled'1357 pprint('CONFIGURING RUNTIME SUSPEND...')1358 self.rslist = deviceInfo(self.rstgt)1359 for i in self.rslist:1360 self.setVal(self.rsval, i)1361 pprint('runtime suspend %s on all devices (%d changed)' % (self.rsdir, len(self.rslist)))1362 pprint('waiting 5 seconds...')1363 time.sleep(5)1364 else:1365 # runtime suspend re-enable or re-disable1366 for i in self.rslist:1367 self.setVal(self.rstgt, i)1368 pprint('runtime suspend settings restored on %d devices' % len(self.rslist))1369 def start(self, pm):1370 if self.useftrace:1371 self.dlog('start ftrace tracing')1372 self.fsetVal('1', 'tracing_on')1373 if self.useprocmon:1374 self.dlog('start the process monitor')1375 pm.start()1376 def stop(self, pm):1377 if self.useftrace:1378 if self.useprocmon:1379 self.dlog('stop the process monitor')1380 pm.stop()1381 self.dlog('stop ftrace tracing')1382 self.fsetVal('0', 'tracing_on')1383 1384sysvals = SystemValues()1385switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']1386switchoff = ['disable', 'off', 'false', '0']1387suspendmodename = {1388 'standby': 'standby (S1)',1389 'freeze': 'freeze (S2idle)',1390 'mem': 'suspend (S3)',1391 'disk': 'hibernate (S4)'1392}1393 1394# Class: DevProps1395# Description:1396# Simple class which holds property values collected1397# for all the devices used in the timeline.1398class DevProps:1399 def __init__(self):1400 self.syspath = ''1401 self.altname = ''1402 self.isasync = True1403 self.xtraclass = ''1404 self.xtrainfo = ''1405 def out(self, dev):1406 return '%s,%s,%d;' % (dev, self.altname, self.isasync)1407 def debug(self, dev):1408 pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.isasync))1409 def altName(self, dev):1410 if not self.altname or self.altname == dev:1411 return dev1412 return '%s [%s]' % (self.altname, dev)1413 def xtraClass(self):1414 if self.xtraclass:1415 return ' '+self.xtraclass1416 if not self.isasync:1417 return ' sync'1418 return ''1419 def xtraInfo(self):1420 if self.xtraclass:1421 return ' '+self.xtraclass1422 if self.isasync:1423 return ' (async)'1424 return ' (sync)'1425 1426# Class: DeviceNode1427# Description:1428# A container used to create a device hierachy, with a single root node1429# and a tree of child nodes. Used by Data.deviceTopology()1430class DeviceNode:1431 def __init__(self, nodename, nodedepth):1432 self.name = nodename1433 self.children = []1434 self.depth = nodedepth1435 1436# Class: Data1437# Description:1438# The primary container for suspend/resume test data. There is one for1439# each test run. The data is organized into a cronological hierarchy:1440# Data.dmesg {1441# phases {1442# 10 sequential, non-overlapping phases of S/R1443# contents: times for phase start/end, order/color data for html1444# devlist {1445# device callback or action list for this phase1446# device {1447# a single device callback or generic action1448# contents: start/stop times, pid/cpu/driver info1449# parents/children, html id for timeline/callgraph1450# optionally includes an ftrace callgraph1451# optionally includes dev/ps data1452# }1453# }1454# }1455# }1456#1457class Data:1458 phasedef = {1459 'suspend_prepare': {'order': 0, 'color': '#CCFFCC'},1460 'suspend': {'order': 1, 'color': '#88FF88'},1461 'suspend_late': {'order': 2, 'color': '#00AA00'},1462 'suspend_noirq': {'order': 3, 'color': '#008888'},1463 'suspend_machine': {'order': 4, 'color': '#0000FF'},1464 'resume_machine': {'order': 5, 'color': '#FF0000'},1465 'resume_noirq': {'order': 6, 'color': '#FF9900'},1466 'resume_early': {'order': 7, 'color': '#FFCC00'},1467 'resume': {'order': 8, 'color': '#FFFF88'},1468 'resume_complete': {'order': 9, 'color': '#FFFFCC'},1469 }1470 errlist = {1471 'HWERROR' : r'.*\[ *Hardware Error *\].*',1472 'FWBUG' : r'.*\[ *Firmware Bug *\].*',1473 'TASKFAIL': r'.*Freezing .*after *.*',1474 'BUG' : r'(?i).*\bBUG\b.*',1475 'ERROR' : r'(?i).*\bERROR\b.*',1476 'WARNING' : r'(?i).*\bWARNING\b.*',1477 'FAULT' : r'(?i).*\bFAULT\b.*',1478 'FAIL' : r'(?i).*\bFAILED\b.*',1479 'INVALID' : r'(?i).*\bINVALID\b.*',1480 'CRASH' : r'(?i).*\bCRASHED\b.*',1481 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*',1482 'ABORT' : r'(?i).*\bABORT\b.*',1483 'IRQ' : r'.*\bgenirq: .*',1484 'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*',1485 'DISKFULL': r'.*\bNo space left on device.*',1486 'USBERR' : r'.*usb .*device .*, error [0-9-]*',1487 'ATAERR' : r' *ata[0-9\.]*: .*failed.*',1488 'MEIERR' : r' *mei.*: .*failed.*',1489 'TPMERR' : r'(?i) *tpm *tpm[0-9]*: .*error.*',1490 }1491 def __init__(self, num):1492 idchar = 'abcdefghij'1493 self.start = 0.0 # test start1494 self.end = 0.0 # test end1495 self.hwstart = 0 # rtc test start1496 self.hwend = 0 # rtc test end1497 self.tSuspended = 0.0 # low-level suspend start1498 self.tResumed = 0.0 # low-level resume start1499 self.tKernSus = 0.0 # kernel level suspend start1500 self.tKernRes = 0.0 # kernel level resume end1501 self.fwValid = False # is firmware data available1502 self.fwSuspend = 0 # time spent in firmware suspend1503 self.fwResume = 0 # time spent in firmware resume1504 self.html_device_id = 01505 self.stamp = 01506 self.outfile = ''1507 self.kerror = False1508 self.wifi = dict()1509 self.turbostat = 01510 self.enterfail = ''1511 self.currphase = ''1512 self.pstl = dict() # process timeline1513 self.testnumber = num1514 self.idstr = idchar[num]1515 self.dmesgtext = [] # dmesg text file in memory1516 self.dmesg = dict() # root data structure1517 self.errorinfo = {'suspend':[],'resume':[]}1518 self.tLow = [] # time spent in low-level suspends (standby/freeze)1519 self.devpids = []1520 self.devicegroups = 01521 def sortedPhases(self):1522 return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order'])1523 def initDevicegroups(self):1524 # called when phases are all finished being added1525 for phase in sorted(self.dmesg.keys()):1526 if '*' in phase:1527 p = phase.split('*')1528 pnew = '%s%d' % (p[0], len(p))1529 self.dmesg[pnew] = self.dmesg.pop(phase)1530 self.devicegroups = []1531 for phase in self.sortedPhases():1532 self.devicegroups.append([phase])1533 def nextPhase(self, phase, offset):1534 order = self.dmesg[phase]['order'] + offset1535 for p in self.dmesg:1536 if self.dmesg[p]['order'] == order:1537 return p1538 return ''1539 def lastPhase(self, depth=1):1540 plist = self.sortedPhases()1541 if len(plist) < depth:1542 return ''1543 return plist[-1*depth]1544 def turbostatInfo(self):1545 tp = TestProps()1546 out = {'syslpi':'N/A','pkgpc10':'N/A'}1547 for line in self.dmesgtext:1548 m = re.match(tp.tstatfmt, line)1549 if not m:1550 continue1551 for i in m.group('t').split('|'):1552 if 'SYS%LPI' in i:1553 out['syslpi'] = i.split('=')[-1]+'%'1554 elif 'pc10' in i:1555 out['pkgpc10'] = i.split('=')[-1]+'%'1556 break1557 return out1558 def extractErrorInfo(self):1559 lf = self.dmesgtext1560 if len(self.dmesgtext) < 1 and sysvals.dmesgfile:1561 lf = sysvals.openlog(sysvals.dmesgfile, 'r')1562 i = 01563 tp = TestProps()1564 list = []1565 for line in lf:1566 i += 11567 if tp.stampInfo(line, sysvals):1568 continue1569 m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)1570 if not m:1571 continue1572 t = float(m.group('ktime'))1573 if t < self.start or t > self.end:1574 continue1575 dir = 'suspend' if t < self.tSuspended else 'resume'1576 msg = m.group('msg')1577 if re.match(r'capability: warning: .*', msg):1578 continue1579 for err in self.errlist:1580 if re.match(self.errlist[err], msg):1581 list.append((msg, err, dir, t, i, i))1582 self.kerror = True1583 break1584 tp.msglist = []1585 for msg, type, dir, t, idx1, idx2 in list:1586 tp.msglist.append(msg)1587 self.errorinfo[dir].append((type, t, idx1, idx2))1588 if self.kerror:1589 sysvals.dmesglog = True1590 if len(self.dmesgtext) < 1 and sysvals.dmesgfile:1591 lf.close()1592 return tp1593 def setStart(self, time, msg=''):1594 self.start = time1595 if msg:1596 try:1597 self.hwstart = datetime.strptime(msg, sysvals.tmstart)1598 except:1599 self.hwstart = 01600 def setEnd(self, time, msg=''):1601 self.end = time1602 if msg:1603 try:1604 self.hwend = datetime.strptime(msg, sysvals.tmend)1605 except:1606 self.hwend = 01607 def isTraceEventOutsideDeviceCalls(self, pid, time):1608 for phase in self.sortedPhases():1609 list = self.dmesg[phase]['list']1610 for dev in list:1611 d = list[dev]1612 if(d['pid'] == pid and time >= d['start'] and1613 time < d['end']):1614 return False1615 return True1616 def sourcePhase(self, start):1617 for phase in self.sortedPhases():1618 if 'machine' in phase:1619 continue1620 pend = self.dmesg[phase]['end']1621 if start <= pend:1622 return phase1623 return 'resume_complete' if 'resume_complete' in self.dmesg else ''1624 def sourceDevice(self, phaselist, start, end, pid, type):1625 tgtdev = ''1626 for phase in phaselist:1627 list = self.dmesg[phase]['list']1628 for devname in list:1629 dev = list[devname]1630 # pid must match1631 if dev['pid'] != pid:1632 continue1633 devS = dev['start']1634 devE = dev['end']1635 if type == 'device':1636 # device target event is entirely inside the source boundary1637 if(start < devS or start >= devE or end <= devS or end > devE):1638 continue1639 elif type == 'thread':1640 # thread target event will expand the source boundary1641 if start < devS:1642 dev['start'] = start1643 if end > devE:1644 dev['end'] = end1645 tgtdev = dev1646 break1647 return tgtdev1648 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):1649 # try to place the call in a device1650 phases = self.sortedPhases()1651 tgtdev = self.sourceDevice(phases, start, end, pid, 'device')1652 # calls with device pids that occur outside device bounds are dropped1653 # TODO: include these somehow1654 if not tgtdev and pid in self.devpids:1655 return False1656 # try to place the call in a thread1657 if not tgtdev:1658 tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')1659 # create new thread blocks, expand as new calls are found1660 if not tgtdev:1661 if proc == '<...>':1662 threadname = 'kthread-%d' % (pid)1663 else:1664 threadname = '%s-%d' % (proc, pid)1665 tgtphase = self.sourcePhase(start)1666 if not tgtphase:1667 return False1668 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')1669 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)1670 # this should not happen1671 if not tgtdev:1672 sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \1673 (start, end, proc, pid, kprobename, cdata, rdata))1674 return False1675 # place the call data inside the src element of the tgtdev1676 if('src' not in tgtdev):1677 tgtdev['src'] = []1678 dtf = sysvals.dev_tracefuncs1679 ubiquitous = False1680 if kprobename in dtf and 'ub' in dtf[kprobename]:1681 ubiquitous = True1682 mc = re.match(r'\(.*\) *(?P<args>.*)', cdata)1683 mr = re.match(r'\((?P<caller>\S*).* arg1=(?P<ret>.*)', rdata)1684 if mc and mr:1685 c = mr.group('caller').split('+')[0]1686 a = mc.group('args').strip()1687 r = mr.group('ret')1688 if len(r) > 6:1689 r = ''1690 else:1691 r = 'ret=%s ' % r1692 if ubiquitous and c in dtf and 'ub' in dtf[c]:1693 return False1694 else:1695 return False1696 color = sysvals.kprobeColor(kprobename)1697 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)1698 tgtdev['src'].append(e)1699 return True1700 def overflowDevices(self):1701 # get a list of devices that extend beyond the end of this test run1702 devlist = []1703 for phase in self.sortedPhases():1704 list = self.dmesg[phase]['list']1705 for devname in list:1706 dev = list[devname]1707 if dev['end'] > self.end:1708 devlist.append(dev)1709 return devlist1710 def mergeOverlapDevices(self, devlist):1711 # merge any devices that overlap devlist1712 for dev in devlist:1713 devname = dev['name']1714 for phase in self.sortedPhases():1715 list = self.dmesg[phase]['list']1716 if devname not in list:1717 continue1718 tdev = list[devname]1719 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])1720 if o <= 0:1721 continue1722 dev['end'] = tdev['end']1723 if 'src' not in dev or 'src' not in tdev:1724 continue1725 dev['src'] += tdev['src']1726 del list[devname]1727 def usurpTouchingThread(self, name, dev):1728 # the caller test has priority of this thread, give it to him1729 for phase in self.sortedPhases():1730 list = self.dmesg[phase]['list']1731 if name in list:1732 tdev = list[name]1733 if tdev['start'] - dev['end'] < 0.1:1734 dev['end'] = tdev['end']1735 if 'src' not in dev:1736 dev['src'] = []1737 if 'src' in tdev:1738 dev['src'] += tdev['src']1739 del list[name]1740 break1741 def stitchTouchingThreads(self, testlist):1742 # merge any threads between tests that touch1743 for phase in self.sortedPhases():1744 list = self.dmesg[phase]['list']1745 for devname in list:1746 dev = list[devname]1747 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:1748 continue1749 for data in testlist:1750 data.usurpTouchingThread(devname, dev)1751 def optimizeDevSrc(self):1752 # merge any src call loops to reduce timeline size1753 for phase in self.sortedPhases():1754 list = self.dmesg[phase]['list']1755 for dev in list:1756 if 'src' not in list[dev]:1757 continue1758 src = list[dev]['src']1759 p = 01760 for e in sorted(src, key=lambda event: event.time):1761 if not p or not e.repeat(p):1762 p = e1763 continue1764 # e is another iteration of p, move it into p1765 p.end = e.end1766 p.length = p.end - p.time1767 p.count += 11768 src.remove(e)1769 def trimTimeVal(self, t, t0, dT, left):1770 if left:1771 if(t > t0):1772 if(t - dT < t0):1773 return t01774 return t - dT1775 else:1776 return t1777 else:1778 if(t < t0 + dT):1779 if(t > t0):1780 return t0 + dT1781 return t + dT1782 else:1783 return t1784 def trimTime(self, t0, dT, left):1785 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)1786 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)1787 self.start = self.trimTimeVal(self.start, t0, dT, left)1788 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)1789 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)1790 self.end = self.trimTimeVal(self.end, t0, dT, left)1791 for phase in self.sortedPhases():1792 p = self.dmesg[phase]1793 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)1794 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)1795 list = p['list']1796 for name in list:1797 d = list[name]1798 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)1799 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)1800 d['length'] = d['end'] - d['start']1801 if('ftrace' in d):1802 cg = d['ftrace']1803 cg.start = self.trimTimeVal(cg.start, t0, dT, left)1804 cg.end = self.trimTimeVal(cg.end, t0, dT, left)1805 for line in cg.list:1806 line.time = self.trimTimeVal(line.time, t0, dT, left)1807 if('src' in d):1808 for e in d['src']:1809 e.time = self.trimTimeVal(e.time, t0, dT, left)1810 e.end = self.trimTimeVal(e.end, t0, dT, left)1811 e.length = e.end - e.time1812 if('cpuexec' in d):1813 cpuexec = dict()1814 for e in d['cpuexec']:1815 c0, cN = e1816 c0 = self.trimTimeVal(c0, t0, dT, left)1817 cN = self.trimTimeVal(cN, t0, dT, left)1818 cpuexec[(c0, cN)] = d['cpuexec'][e]1819 d['cpuexec'] = cpuexec1820 for dir in ['suspend', 'resume']:1821 list = []1822 for e in self.errorinfo[dir]:1823 type, tm, idx1, idx2 = e1824 tm = self.trimTimeVal(tm, t0, dT, left)1825 list.append((type, tm, idx1, idx2))1826 self.errorinfo[dir] = list1827 def trimFreezeTime(self, tZero):1828 # trim out any standby or freeze clock time1829 lp = ''1830 for phase in self.sortedPhases():1831 if 'resume_machine' in phase and 'suspend_machine' in lp:1832 tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start']1833 tL = tR - tS1834 if tL <= 0:1835 continue1836 left = True if tR > tZero else False1837 self.trimTime(tS, tL, left)1838 if 'waking' in self.dmesg[lp]:1839 tCnt = self.dmesg[lp]['waking'][0]1840 if self.dmesg[lp]['waking'][1] >= 0.001:1841 tTry = '%.0f' % (round(self.dmesg[lp]['waking'][1] * 1000))1842 else:1843 tTry = '%.3f' % (self.dmesg[lp]['waking'][1] * 1000)1844 text = '%.0f (%s ms waking %d times)' % (tL * 1000, tTry, tCnt)1845 else:1846 text = '%.0f' % (tL * 1000)1847 self.tLow.append(text)1848 lp = phase1849 def getMemTime(self):1850 if not self.hwstart or not self.hwend:1851 return1852 stime = (self.tSuspended - self.start) * 10000001853 rtime = (self.end - self.tResumed) * 10000001854 hws = self.hwstart + timedelta(microseconds=stime)1855 hwr = self.hwend - timedelta(microseconds=rtime)1856 self.tLow.append('%.0f'%((hwr - hws).total_seconds() * 1000))1857 def getTimeValues(self):1858 s = (self.tSuspended - self.tKernSus) * 10001859 r = (self.tKernRes - self.tResumed) * 10001860 return (max(s, 0), max(r, 0))1861 def setPhase(self, phase, ktime, isbegin, order=-1):1862 if(isbegin):1863 # phase start over current phase1864 if self.currphase:1865 if 'resume_machine' not in self.currphase:1866 sysvals.vprint('WARNING: phase %s failed to end' % self.currphase)1867 self.dmesg[self.currphase]['end'] = ktime1868 phases = self.dmesg.keys()1869 color = self.phasedef[phase]['color']1870 count = len(phases) if order < 0 else order1871 # create unique name for every new phase1872 while phase in phases:1873 phase += '*'1874 self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0,1875 'row': 0, 'color': color, 'order': count}1876 self.dmesg[phase]['start'] = ktime1877 self.currphase = phase1878 else:1879 # phase end without a start1880 if phase not in self.currphase:1881 if self.currphase:1882 sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))1883 else:1884 sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)1885 return phase1886 phase = self.currphase1887 self.dmesg[phase]['end'] = ktime1888 self.currphase = ''1889 return phase1890 def sortedDevices(self, phase):1891 list = self.dmesg[phase]['list']1892 return sorted(list, key=lambda k:list[k]['start'])1893 def fixupInitcalls(self, phase):1894 # if any calls never returned, clip them at system resume end1895 phaselist = self.dmesg[phase]['list']1896 for devname in phaselist:1897 dev = phaselist[devname]1898 if(dev['end'] < 0):1899 for p in self.sortedPhases():1900 if self.dmesg[p]['end'] > dev['start']:1901 dev['end'] = self.dmesg[p]['end']1902 break1903 sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))1904 def deviceFilter(self, devicefilter):1905 for phase in self.sortedPhases():1906 list = self.dmesg[phase]['list']1907 rmlist = []1908 for name in list:1909 keep = False1910 for filter in devicefilter:1911 if filter in name or \1912 ('drv' in list[name] and filter in list[name]['drv']):1913 keep = True1914 if not keep:1915 rmlist.append(name)1916 for name in rmlist:1917 del list[name]1918 def fixupInitcallsThatDidntReturn(self):1919 # if any calls never returned, clip them at system resume end1920 for phase in self.sortedPhases():1921 self.fixupInitcalls(phase)1922 def phaseOverlap(self, phases):1923 rmgroups = []1924 newgroup = []1925 for group in self.devicegroups:1926 for phase in phases:1927 if phase not in group:1928 continue1929 for p in group:1930 if p not in newgroup:1931 newgroup.append(p)1932 if group not in rmgroups:1933 rmgroups.append(group)1934 for group in rmgroups:1935 self.devicegroups.remove(group)1936 self.devicegroups.append(newgroup)1937 def newActionGlobal(self, name, start, end, pid=-1, color=''):1938 # which phase is this device callback or action in1939 phases = self.sortedPhases()1940 targetphase = 'none'1941 htmlclass = ''1942 overlap = 0.01943 myphases = []1944 for phase in phases:1945 pstart = self.dmesg[phase]['start']1946 pend = self.dmesg[phase]['end']1947 # see if the action overlaps this phase1948 o = max(0, min(end, pend) - max(start, pstart))1949 if o > 0:1950 myphases.append(phase)1951 # set the target phase to the one that overlaps most1952 if o > overlap:1953 if overlap > 0 and phase == 'post_resume':1954 continue1955 targetphase = phase1956 overlap = o1957 # if no target phase was found, pin it to the edge1958 if targetphase == 'none':1959 p0start = self.dmesg[phases[0]]['start']1960 if start <= p0start:1961 targetphase = phases[0]1962 else:1963 targetphase = phases[-1]1964 if pid == -2:1965 htmlclass = ' bg'1966 elif pid == -3:1967 htmlclass = ' ps'1968 if len(myphases) > 1:1969 htmlclass = ' bg'1970 self.phaseOverlap(myphases)1971 if targetphase in phases:1972 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)1973 return (targetphase, newname)1974 return False1975 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):1976 # new device callback for a specific phase1977 self.html_device_id += 11978 devid = '%s%d' % (self.idstr, self.html_device_id)1979 list = self.dmesg[phase]['list']1980 length = -1.01981 if(start >= 0 and end >= 0):1982 length = end - start1983 if pid == -2 or name not in sysvals.tracefuncs.keys():1984 i = 21985 origname = name1986 while(name in list):1987 name = '%s[%d]' % (origname, i)1988 i += 11989 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,1990 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }1991 if htmlclass:1992 list[name]['htmlclass'] = htmlclass1993 if color:1994 list[name]['color'] = color1995 return name1996 def findDevice(self, phase, name):1997 list = self.dmesg[phase]['list']1998 mydev = ''1999 for devname in sorted(list):2000 if name == devname or re.match(r'^%s\[(?P<num>[0-9]*)\]$' % name, devname):2001 mydev = devname2002 if mydev:2003 return list[mydev]2004 return False2005 def deviceChildren(self, devname, phase):2006 devlist = []2007 list = self.dmesg[phase]['list']2008 for child in list:2009 if(list[child]['par'] == devname):2010 devlist.append(child)2011 return devlist2012 def maxDeviceNameSize(self, phase):2013 size = 02014 for name in self.dmesg[phase]['list']:2015 if len(name) > size:2016 size = len(name)2017 return size2018 def printDetails(self):2019 sysvals.vprint('Timeline Details:')2020 sysvals.vprint(' test start: %f' % self.start)2021 sysvals.vprint('kernel suspend start: %f' % self.tKernSus)2022 tS = tR = False2023 for phase in self.sortedPhases():2024 devlist = self.dmesg[phase]['list']2025 dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end']2026 if not tS and ps >= self.tSuspended:2027 sysvals.vprint(' machine suspended: %f' % self.tSuspended)2028 tS = True2029 if not tR and ps >= self.tResumed:2030 sysvals.vprint(' machine resumed: %f' % self.tResumed)2031 tR = True2032 sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc))2033 if sysvals.devdump:2034 sysvals.vprint(''.join('-' for i in range(80)))2035 maxname = '%d' % self.maxDeviceNameSize(phase)2036 fmt = '%3d) %'+maxname+'s - %f - %f'2037 c = 12038 for name in sorted(devlist):2039 s = devlist[name]['start']2040 e = devlist[name]['end']2041 sysvals.vprint(fmt % (c, name, s, e))2042 c += 12043 sysvals.vprint(''.join('-' for i in range(80)))2044 sysvals.vprint(' kernel resume end: %f' % self.tKernRes)2045 sysvals.vprint(' test end: %f' % self.end)2046 def deviceChildrenAllPhases(self, devname):2047 devlist = []2048 for phase in self.sortedPhases():2049 list = self.deviceChildren(devname, phase)2050 for dev in sorted(list):2051 if dev not in devlist:2052 devlist.append(dev)2053 return devlist2054 def masterTopology(self, name, list, depth):2055 node = DeviceNode(name, depth)2056 for cname in list:2057 # avoid recursions2058 if name == cname:2059 continue2060 clist = self.deviceChildrenAllPhases(cname)2061 cnode = self.masterTopology(cname, clist, depth+1)2062 node.children.append(cnode)2063 return node2064 def printTopology(self, node):2065 html = ''2066 if node.name:2067 info = ''2068 drv = ''2069 for phase in self.sortedPhases():2070 list = self.dmesg[phase]['list']2071 if node.name in list:2072 s = list[node.name]['start']2073 e = list[node.name]['end']2074 if list[node.name]['drv']:2075 drv = ' {'+list[node.name]['drv']+'}'2076 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))2077 html += '<li><b>'+node.name+drv+'</b>'2078 if info:2079 html += '<ul>'+info+'</ul>'2080 html += '</li>'2081 if len(node.children) > 0:2082 html += '<ul>'2083 for cnode in node.children:2084 html += self.printTopology(cnode)2085 html += '</ul>'2086 return html2087 def rootDeviceList(self):2088 # list of devices graphed2089 real = []2090 for phase in self.sortedPhases():2091 list = self.dmesg[phase]['list']2092 for dev in sorted(list):2093 if list[dev]['pid'] >= 0 and dev not in real:2094 real.append(dev)2095 # list of top-most root devices2096 rootlist = []2097 for phase in self.sortedPhases():2098 list = self.dmesg[phase]['list']2099 for dev in sorted(list):2100 pdev = list[dev]['par']2101 pid = list[dev]['pid']2102 if(pid < 0 or re.match(r'[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):2103 continue2104 if pdev and pdev not in real and pdev not in rootlist:2105 rootlist.append(pdev)2106 return rootlist2107 def deviceTopology(self):2108 rootlist = self.rootDeviceList()2109 master = self.masterTopology('', rootlist, 0)2110 return self.printTopology(master)2111 def selectTimelineDevices(self, widfmt, tTotal, mindevlen):2112 # only select devices that will actually show up in html2113 self.tdevlist = dict()2114 for phase in self.dmesg:2115 devlist = []2116 list = self.dmesg[phase]['list']2117 for dev in list:2118 length = (list[dev]['end'] - list[dev]['start']) * 10002119 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)2120 if length >= mindevlen:2121 devlist.append(dev)2122 self.tdevlist[phase] = devlist2123 def addHorizontalDivider(self, devname, devend):2124 phase = 'suspend_prepare'2125 self.newAction(phase, devname, -2, '', \2126 self.start, devend, '', ' sec', '')2127 if phase not in self.tdevlist:2128 self.tdevlist[phase] = []2129 self.tdevlist[phase].append(devname)2130 d = DevItem(0, phase, self.dmesg[phase]['list'][devname])2131 return d2132 def addProcessUsageEvent(self, name, times):2133 # get the start and end times for this process2134 cpuexec = dict()2135 tlast = start = end = -12136 for t in sorted(times):2137 if tlast < 0:2138 tlast = t2139 continue2140 if name in self.pstl[t] and self.pstl[t][name] > 0:2141 if start < 0:2142 start = tlast2143 end, key = t, (tlast, t)2144 maxj = (t - tlast) * 1024.02145 cpuexec[key] = min(1.0, float(self.pstl[t][name]) / maxj)2146 tlast = t2147 if start < 0 or end < 0:2148 return2149 # add a new action for this process and get the object2150 out = self.newActionGlobal(name, start, end, -3)2151 if out:2152 phase, devname = out2153 dev = self.dmesg[phase]['list'][devname]2154 dev['cpuexec'] = cpuexec2155 def createProcessUsageEvents(self):2156 # get an array of process names and times2157 proclist = {'sus': dict(), 'res': dict()}2158 tdata = {'sus': [], 'res': []}2159 for t in sorted(self.pstl):2160 dir = 'sus' if t < self.tSuspended else 'res'2161 for ps in sorted(self.pstl[t]):2162 if ps not in proclist[dir]:2163 proclist[dir][ps] = 02164 tdata[dir].append(t)2165 # process the events for suspend and resume2166 if len(proclist['sus']) > 0 or len(proclist['res']) > 0:2167 sysvals.vprint('Process Execution:')2168 for dir in ['sus', 'res']:2169 for ps in sorted(proclist[dir]):2170 self.addProcessUsageEvent(ps, tdata[dir])2171 def handleEndMarker(self, time, msg=''):2172 dm = self.dmesg2173 self.setEnd(time, msg)2174 self.initDevicegroups()2175 # give suspend_prepare an end if needed2176 if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0:2177 dm['suspend_prepare']['end'] = time2178 # assume resume machine ends at next phase start2179 if 'resume_machine' in dm and dm['resume_machine']['end'] < 0:2180 np = self.nextPhase('resume_machine', 1)2181 if np:2182 dm['resume_machine']['end'] = dm[np]['start']2183 # if kernel resume end not found, assume its the end marker2184 if self.tKernRes == 0.0:2185 self.tKernRes = time2186 # if kernel suspend start not found, assume its the end marker2187 if self.tKernSus == 0.0:2188 self.tKernSus = time2189 # set resume complete to end at end marker2190 if 'resume_complete' in dm:2191 dm['resume_complete']['end'] = time2192 def initcall_debug_call(self, line, quick=False):2193 m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\2194 r'PM: *calling .* @ (?P<n>.*), parent: (?P<p>.*)', line)2195 if not m:2196 m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\2197 r'calling .* @ (?P<n>.*), parent: (?P<p>.*)', line)2198 if not m:2199 m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\2200 r'(?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)', line)2201 if m:2202 return True if quick else m.group('t', 'f', 'n', 'p')2203 return False if quick else ('', '', '', '')2204 def initcall_debug_return(self, line, quick=False):2205 m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: PM: '+\2206 r'.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line)2207 if not m:2208 m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\2209 r'.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line)2210 if not m:2211 m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\2212 r'(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', line)2213 if m:2214 return True if quick else m.group('t', 'f', 'dt')2215 return False if quick else ('', '', '')2216 def debugPrint(self):2217 for p in self.sortedPhases():2218 list = self.dmesg[p]['list']2219 for devname in sorted(list):2220 dev = list[devname]2221 if 'ftrace' in dev:2222 dev['ftrace'].debugPrint(' [%s]' % devname)2223 2224# Class: DevFunction2225# Description:2226# A container for kprobe function data we want in the dev timeline2227class DevFunction:2228 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):2229 self.row = 02230 self.count = 12231 self.name = name2232 self.args = args2233 self.caller = caller2234 self.ret = ret2235 self.time = start2236 self.length = end - start2237 self.end = end2238 self.ubiquitous = u2239 self.proc = proc2240 self.pid = pid2241 self.color = color2242 def title(self):2243 cnt = ''2244 if self.count > 1:2245 cnt = '(x%d)' % self.count2246 l = '%0.3fms' % (self.length * 1000)2247 if self.ubiquitous:2248 title = '%s(%s)%s <- %s, %s(%s)' % \2249 (self.name, self.args, cnt, self.caller, self.ret, l)2250 else:2251 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)2252 return title.replace('"', '')2253 def text(self):2254 if self.count > 1:2255 text = '%s(x%d)' % (self.name, self.count)2256 else:2257 text = self.name2258 return text2259 def repeat(self, tgt):2260 # is the tgt call just a repeat of this call (e.g. are we in a loop)2261 dt = self.time - tgt.end2262 # only combine calls if -all- attributes are identical2263 if tgt.caller == self.caller and \2264 tgt.name == self.name and tgt.args == self.args and \2265 tgt.proc == self.proc and tgt.pid == self.pid and \2266 tgt.ret == self.ret and dt >= 0 and \2267 dt <= sysvals.callloopmaxgap and \2268 self.length < sysvals.callloopmaxlen:2269 return True2270 return False2271 2272# Class: FTraceLine2273# Description:2274# A container for a single line of ftrace data. There are six basic types:2275# callgraph line:2276# call: " dpm_run_callback() {"2277# return: " }"2278# leaf: " dpm_run_callback();"2279# trace event:2280# tracing_mark_write: SUSPEND START or RESUME COMPLETE2281# suspend_resume: phase or custom exec block data2282# device_pm_callback: device callback info2283class FTraceLine:2284 def __init__(self, t, m='', d=''):2285 self.length = 0.02286 self.fcall = False2287 self.freturn = False2288 self.fevent = False2289 self.fkprobe = False2290 self.depth = 02291 self.name = ''2292 self.type = ''2293 self.time = float(t)2294 if not m and not d:2295 return2296 # is this a trace event2297 if(d == 'traceevent' or re.match(r'^ *\/\* *(?P<msg>.*) \*\/ *$', m)):2298 if(d == 'traceevent'):2299 # nop format trace event2300 msg = m2301 else:2302 # function_graph format trace event2303 em = re.match(r'^ *\/\* *(?P<msg>.*) \*\/ *$', m)2304 msg = em.group('msg')2305 2306 emm = re.match(r'^(?P<call>.*?): (?P<msg>.*)', msg)2307 if(emm):2308 self.name = emm.group('msg')2309 self.type = emm.group('call')2310 else:2311 self.name = msg2312 km = re.match(r'^(?P<n>.*)_cal$', self.type)2313 if km:2314 self.fcall = True2315 self.fkprobe = True2316 self.type = km.group('n')2317 return2318 km = re.match(r'^(?P<n>.*)_ret$', self.type)2319 if km:2320 self.freturn = True2321 self.fkprobe = True2322 self.type = km.group('n')2323 return2324 self.fevent = True2325 return2326 # convert the duration to seconds2327 if(d):2328 self.length = float(d)/10000002329 # the indentation determines the depth2330 match = re.match(r'^(?P<d> *)(?P<o>.*)$', m)2331 if(not match):2332 return2333 self.depth = self.getDepth(match.group('d'))2334 m = match.group('o')2335 # function return2336 if(m[0] == '}'):2337 self.freturn = True2338 if(len(m) > 1):2339 # includes comment with function name2340 match = re.match(r'^} *\/\* *(?P<n>.*) *\*\/$', m)2341 if(match):2342 self.name = match.group('n').strip()2343 # function call2344 else:2345 self.fcall = True2346 # function call with children2347 if(m[-1] == '{'):2348 match = re.match(r'^(?P<n>.*) *\(.*', m)2349 if(match):2350 self.name = match.group('n').strip()2351 # function call with no children (leaf)2352 elif(m[-1] == ';'):2353 self.freturn = True2354 match = re.match(r'^(?P<n>.*) *\(.*', m)2355 if(match):2356 self.name = match.group('n').strip()2357 # something else (possibly a trace marker)2358 else:2359 self.name = m2360 def isCall(self):2361 return self.fcall and not self.freturn2362 def isReturn(self):2363 return self.freturn and not self.fcall2364 def isLeaf(self):2365 return self.fcall and self.freturn2366 def getDepth(self, str):2367 return len(str)/22368 def debugPrint(self, info=''):2369 if self.isLeaf():2370 pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \2371 self.depth, self.name, self.length*1000000, info))2372 elif self.freturn:2373 pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \2374 self.depth, self.name, self.length*1000000, info))2375 else:2376 pprint(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \2377 self.depth, self.name, self.length*1000000, info))2378 def startMarker(self):2379 # Is this the starting line of a suspend?2380 if not self.fevent:2381 return False2382 if sysvals.usetracemarkers:2383 if(self.name.startswith('SUSPEND START')):2384 return True2385 return False2386 else:2387 if(self.type == 'suspend_resume' and2388 re.match(r'suspend_enter\[.*\] begin', self.name)):2389 return True2390 return False2391 def endMarker(self):2392 # Is this the ending line of a resume?2393 if not self.fevent:2394 return False2395 if sysvals.usetracemarkers:2396 if(self.name.startswith('RESUME COMPLETE')):2397 return True2398 return False2399 else:2400 if(self.type == 'suspend_resume' and2401 re.match(r'thaw_processes\[.*\] end', self.name)):2402 return True2403 return False2404 2405# Class: FTraceCallGraph2406# Description:2407# A container for the ftrace callgraph of a single recursive function.2408# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph2409# Each instance is tied to a single device in a single phase, and is2410# comprised of an ordered list of FTraceLine objects2411class FTraceCallGraph:2412 vfname = 'missing_function_name'2413 def __init__(self, pid, sv):2414 self.id = ''2415 self.invalid = False2416 self.name = ''2417 self.partial = False2418 self.ignore = False2419 self.start = -1.02420 self.end = -1.02421 self.list = []2422 self.depth = 02423 self.pid = pid2424 self.sv = sv2425 def addLine(self, line):2426 # if this is already invalid, just leave2427 if(self.invalid):2428 if(line.depth == 0 and line.freturn):2429 return 12430 return 02431 # invalidate on bad depth2432 if(self.depth < 0):2433 self.invalidate(line)2434 return 02435 # ignore data til we return to the current depth2436 if self.ignore:2437 if line.depth > self.depth:2438 return 02439 else:2440 self.list[-1].freturn = True2441 self.list[-1].length = line.time - self.list[-1].time2442 self.ignore = False2443 # if this is a return at self.depth, no more work is needed2444 if line.depth == self.depth and line.isReturn():2445 if line.depth == 0:2446 self.end = line.time2447 return 12448 return 02449 # compare current depth with this lines pre-call depth2450 prelinedep = line.depth2451 if line.isReturn():2452 prelinedep += 12453 last = 02454 lasttime = line.time2455 if len(self.list) > 0:2456 last = self.list[-1]2457 lasttime = last.time2458 if last.isLeaf():2459 lasttime += last.length2460 # handle low misalignments by inserting returns2461 mismatch = prelinedep - self.depth2462 warning = self.sv.verbose and abs(mismatch) > 12463 info = []2464 if mismatch < 0:2465 idx = 02466 # add return calls to get the depth down2467 while prelinedep < self.depth:2468 self.depth -= 12469 if idx == 0 and last and last.isCall():2470 # special case, turn last call into a leaf2471 last.depth = self.depth2472 last.freturn = True2473 last.length = line.time - last.time2474 if warning:2475 info.append(('[make leaf]', last))2476 else:2477 vline = FTraceLine(lasttime)2478 vline.depth = self.depth2479 vline.name = self.vfname2480 vline.freturn = True2481 self.list.append(vline)2482 if warning:2483 if idx == 0:2484 info.append(('', last))2485 info.append(('[add return]', vline))2486 idx += 12487 if warning:2488 info.append(('', line))2489 # handle high misalignments by inserting calls2490 elif mismatch > 0:2491 idx = 02492 if warning:2493 info.append(('', last))2494 # add calls to get the depth up2495 while prelinedep > self.depth:2496 if idx == 0 and line.isReturn():2497 # special case, turn this return into a leaf2498 line.fcall = True2499 prelinedep -= 12500 if warning:2501 info.append(('[make leaf]', line))2502 else:2503 vline = FTraceLine(lasttime)2504 vline.depth = self.depth2505 vline.name = self.vfname2506 vline.fcall = True2507 self.list.append(vline)2508 self.depth += 12509 if not last:2510 self.start = vline.time2511 if warning:2512 info.append(('[add call]', vline))2513 idx += 12514 if warning and ('[make leaf]', line) not in info:2515 info.append(('', line))2516 if warning:2517 pprint('WARNING: ftrace data missing, corrections made:')2518 for i in info:2519 t, obj = i2520 if obj:2521 obj.debugPrint(t)2522 # process the call and set the new depth2523 skipadd = False2524 md = self.sv.max_graph_depth2525 if line.isCall():2526 # ignore blacklisted/overdepth funcs2527 if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):2528 self.ignore = True2529 else:2530 self.depth += 12531 elif line.isReturn():2532 self.depth -= 12533 # remove blacklisted/overdepth/empty funcs that slipped through2534 if (last and last.isCall() and last.depth == line.depth) or \2535 (md and last and last.depth >= md) or \2536 (line.name in self.sv.cgblacklist):2537 while len(self.list) > 0 and self.list[-1].depth > line.depth:2538 self.list.pop(-1)2539 if len(self.list) == 0:2540 self.invalid = True2541 return 12542 self.list[-1].freturn = True2543 self.list[-1].length = line.time - self.list[-1].time2544 self.list[-1].name = line.name2545 skipadd = True2546 if len(self.list) < 1:2547 self.start = line.time2548 # check for a mismatch that returned all the way to callgraph end2549 res = 12550 if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn:2551 line = self.list[-1]2552 skipadd = True2553 res = -12554 if not skipadd:2555 self.list.append(line)2556 if(line.depth == 0 and line.freturn):2557 if(self.start < 0):2558 self.start = line.time2559 self.end = line.time2560 if line.fcall:2561 self.end += line.length2562 if self.list[0].name == self.vfname:2563 self.invalid = True2564 if res == -1:2565 self.partial = True2566 return res2567 return 02568 def invalidate(self, line):2569 if(len(self.list) > 0):2570 first = self.list[0]2571 self.list = []2572 self.list.append(first)2573 self.invalid = True2574 id = 'task %s' % (self.pid)2575 window = '(%f - %f)' % (self.start, line.time)2576 if(self.depth < 0):2577 pprint('Data misalignment for '+id+\2578 ' (buffer overflow), ignoring this callback')2579 else:2580 pprint('Too much data for '+id+\2581 ' '+window+', ignoring this callback')2582 def slice(self, dev):2583 minicg = FTraceCallGraph(dev['pid'], self.sv)2584 minicg.name = self.name2585 mydepth = -12586 good = False2587 for l in self.list:2588 if(l.time < dev['start'] or l.time > dev['end']):2589 continue2590 if mydepth < 0:2591 if l.name == 'mutex_lock' and l.freturn:2592 mydepth = l.depth2593 continue2594 elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall:2595 good = True2596 break2597 l.depth -= mydepth2598 minicg.addLine(l)2599 if not good or len(minicg.list) < 1:2600 return 02601 return minicg2602 def repair(self, enddepth):2603 # bring the depth back to 0 with additional returns2604 fixed = False2605 last = self.list[-1]2606 for i in reversed(range(enddepth)):2607 t = FTraceLine(last.time)2608 t.depth = i2609 t.freturn = True2610 fixed = self.addLine(t)2611 if fixed != 0:2612 self.end = last.time2613 return True2614 return False2615 def postProcess(self):2616 if len(self.list) > 0:2617 self.name = self.list[0].name2618 stack = dict()2619 cnt = 02620 last = 02621 for l in self.list:2622 # ftrace bug: reported duration is not reliable2623 # check each leaf and clip it at max possible length2624 if last and last.isLeaf():2625 if last.length > l.time - last.time:2626 last.length = l.time - last.time2627 if l.isCall():2628 stack[l.depth] = l2629 cnt += 12630 elif l.isReturn():2631 if(l.depth not in stack):2632 if self.sv.verbose:2633 pprint('Post Process Error: Depth missing')2634 l.debugPrint()2635 return False2636 # calculate call length from call/return lines2637 cl = stack[l.depth]2638 cl.length = l.time - cl.time2639 if cl.name == self.vfname:2640 cl.name = l.name2641 stack.pop(l.depth)2642 l.length = 02643 cnt -= 12644 last = l2645 if(cnt == 0):2646 # trace caught the whole call tree2647 return True2648 elif(cnt < 0):2649 if self.sv.verbose:2650 pprint('Post Process Error: Depth is less than 0')2651 return False2652 # trace ended before call tree finished2653 return self.repair(cnt)2654 def deviceMatch(self, pid, data):2655 found = ''2656 # add the callgraph data to the device hierarchy2657 borderphase = {2658 'dpm_prepare': 'suspend_prepare',2659 'dpm_complete': 'resume_complete'2660 }2661 if(self.name in borderphase):2662 p = borderphase[self.name]2663 list = data.dmesg[p]['list']2664 for devname in list:2665 dev = list[devname]2666 if(pid == dev['pid'] and2667 self.start <= dev['start'] and2668 self.end >= dev['end']):2669 cg = self.slice(dev)2670 if cg:2671 dev['ftrace'] = cg2672 found = devname2673 return found2674 for p in data.sortedPhases():2675 if(data.dmesg[p]['start'] <= self.start and2676 self.start <= data.dmesg[p]['end']):2677 list = data.dmesg[p]['list']2678 for devname in sorted(list, key=lambda k:list[k]['start']):2679 dev = list[devname]2680 if(pid == dev['pid'] and2681 self.start <= dev['start'] and2682 self.end >= dev['end']):2683 dev['ftrace'] = self2684 found = devname2685 break2686 break2687 return found2688 def newActionFromFunction(self, data):2689 name = self.name2690 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:2691 return2692 fs = self.start2693 fe = self.end2694 if fs < data.start or fe > data.end:2695 return2696 phase = ''2697 for p in data.sortedPhases():2698 if(data.dmesg[p]['start'] <= self.start and2699 self.start < data.dmesg[p]['end']):2700 phase = p2701 break2702 if not phase:2703 return2704 out = data.newActionGlobal(name, fs, fe, -2)2705 if out:2706 phase, myname = out2707 data.dmesg[phase]['list'][myname]['ftrace'] = self2708 def debugPrint(self, info=''):2709 pprint('%s pid=%d [%f - %f] %.3f us' % \2710 (self.name, self.pid, self.start, self.end,2711 (self.end - self.start)*1000000))2712 for l in self.list:2713 if l.isLeaf():2714 pprint('%f (%02d): %s(); (%.3f us)%s' % (l.time, \2715 l.depth, l.name, l.length*1000000, info))2716 elif l.freturn:2717 pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \2718 l.depth, l.name, l.length*1000000, info))2719 else:2720 pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \2721 l.depth, l.name, l.length*1000000, info))2722 pprint(' ')2723 2724class DevItem:2725 def __init__(self, test, phase, dev):2726 self.test = test2727 self.phase = phase2728 self.dev = dev2729 def isa(self, cls):2730 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:2731 return True2732 return False2733 2734# Class: Timeline2735# Description:2736# A container for a device timeline which calculates2737# all the html properties to display it correctly2738class Timeline:2739 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'2740 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'2741 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'2742 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'2743 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}"> {2}</div>\n'2744 def __init__(self, rowheight, scaleheight):2745 self.html = ''2746 self.height = 0 # total timeline height2747 self.scaleH = scaleheight # timescale (top) row height2748 self.rowH = rowheight # device row height2749 self.bodyH = 0 # body height2750 self.rows = 0 # total timeline rows2751 self.rowlines = dict()2752 self.rowheight = dict()2753 def createHeader(self, sv, stamp):2754 if(not stamp['time']):2755 return2756 self.html += '<div class="version"><a href="https://01.org/pm-graph">%s v%s</a></div>' \2757 % (sv.title, sv.version)2758 if sv.logmsg and sv.testlog:2759 self.html += '<button id="showtest" class="logbtn btnfmt">log</button>'2760 if sv.dmesglog:2761 self.html += '<button id="showdmesg" class="logbtn btnfmt">dmesg</button>'2762 if sv.ftracelog:2763 self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>'2764 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'2765 self.html += headline_stamp.format(stamp['host'], stamp['kernel'],2766 stamp['mode'], stamp['time'])2767 if 'man' in stamp and 'plat' in stamp and 'cpu' in stamp and \2768 stamp['man'] and stamp['plat'] and stamp['cpu']:2769 headline_sysinfo = '<div class="stamp sysinfo">{0} {1} <i>with</i> {2}</div>\n'2770 self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu'])2771 2772 # Function: getDeviceRows2773 # Description:2774 # determine how may rows the device funcs will take2775 # Arguments:2776 # rawlist: the list of devices/actions for a single phase2777 # Output:2778 # The total number of rows needed to display this phase of the timeline2779 def getDeviceRows(self, rawlist):2780 # clear all rows and set them to undefined2781 sortdict = dict()2782 for item in rawlist:2783 item.row = -12784 sortdict[item] = item.length2785 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)2786 remaining = len(sortlist)2787 rowdata = dict()2788 row = 12789 # try to pack each row with as many ranges as possible2790 while(remaining > 0):2791 if(row not in rowdata):2792 rowdata[row] = []2793 for i in sortlist:2794 if(i.row >= 0):2795 continue2796 s = i.time2797 e = i.time + i.length2798 valid = True2799 for ritem in rowdata[row]:2800 rs = ritem.time2801 re = ritem.time + ritem.length2802 if(not (((s <= rs) and (e <= rs)) or2803 ((s >= re) and (e >= re)))):2804 valid = False2805 break2806 if(valid):2807 rowdata[row].append(i)2808 i.row = row2809 remaining -= 12810 row += 12811 return row2812 # Function: getPhaseRows2813 # Description:2814 # Organize the timeline entries into the smallest2815 # number of rows possible, with no entry overlapping2816 # Arguments:2817 # devlist: the list of devices/actions in a group of contiguous phases2818 # Output:2819 # The total number of rows needed to display this phase of the timeline2820 def getPhaseRows(self, devlist, row=0, sortby='length'):2821 # clear all rows and set them to undefined2822 remaining = len(devlist)2823 rowdata = dict()2824 sortdict = dict()2825 myphases = []2826 # initialize all device rows to -1 and calculate devrows2827 for item in devlist:2828 dev = item.dev2829 tp = (item.test, item.phase)2830 if tp not in myphases:2831 myphases.append(tp)2832 dev['row'] = -12833 if sortby == 'start':2834 # sort by start 1st, then length 2nd2835 sortdict[item] = (-1*float(dev['start']), float(dev['end']) - float(dev['start']))2836 else:2837 # sort by length 1st, then name 2nd2838 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])2839 if 'src' in dev:2840 dev['devrows'] = self.getDeviceRows(dev['src'])2841 # sort the devlist by length so that large items graph on top2842 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)2843 orderedlist = []2844 for item in sortlist:2845 if item.dev['pid'] == -2:2846 orderedlist.append(item)2847 for item in sortlist:2848 if item not in orderedlist:2849 orderedlist.append(item)2850 # try to pack each row with as many devices as possible2851 while(remaining > 0):2852 rowheight = 12853 if(row not in rowdata):2854 rowdata[row] = []2855 for item in orderedlist:2856 dev = item.dev2857 if(dev['row'] < 0):2858 s = dev['start']2859 e = dev['end']2860 valid = True2861 for ritem in rowdata[row]:2862 rs = ritem.dev['start']2863 re = ritem.dev['end']2864 if(not (((s <= rs) and (e <= rs)) or2865 ((s >= re) and (e >= re)))):2866 valid = False2867 break2868 if(valid):2869 rowdata[row].append(item)2870 dev['row'] = row2871 remaining -= 12872 if 'devrows' in dev and dev['devrows'] > rowheight:2873 rowheight = dev['devrows']2874 for t, p in myphases:2875 if t not in self.rowlines or t not in self.rowheight:2876 self.rowlines[t] = dict()2877 self.rowheight[t] = dict()2878 if p not in self.rowlines[t] or p not in self.rowheight[t]:2879 self.rowlines[t][p] = dict()2880 self.rowheight[t][p] = dict()2881 rh = self.rowH2882 # section headers should use a different row height2883 if len(rowdata[row]) == 1 and \2884 'htmlclass' in rowdata[row][0].dev and \2885 'sec' in rowdata[row][0].dev['htmlclass']:2886 rh = 152887 self.rowlines[t][p][row] = rowheight2888 self.rowheight[t][p][row] = rowheight * rh2889 row += 12890 if(row > self.rows):2891 self.rows = int(row)2892 return row2893 def phaseRowHeight(self, test, phase, row):2894 return self.rowheight[test][phase][row]2895 def phaseRowTop(self, test, phase, row):2896 top = 02897 for i in sorted(self.rowheight[test][phase]):2898 if i >= row:2899 break2900 top += self.rowheight[test][phase][i]2901 return top2902 def calcTotalRows(self):2903 # Calculate the heights and offsets for the header and rows2904 maxrows = 02905 standardphases = []2906 for t in self.rowlines:2907 for p in self.rowlines[t]:2908 total = 02909 for i in sorted(self.rowlines[t][p]):2910 total += self.rowlines[t][p][i]2911 if total > maxrows:2912 maxrows = total2913 if total == len(self.rowlines[t][p]):2914 standardphases.append((t, p))2915 self.height = self.scaleH + (maxrows*self.rowH)2916 self.bodyH = self.height - self.scaleH2917 # if there is 1 line per row, draw them the standard way2918 for t, p in standardphases:2919 for i in sorted(self.rowheight[t][p]):2920 self.rowheight[t][p][i] = float(self.bodyH)/len(self.rowlines[t][p])2921 def createZoomBox(self, mode='command', testcount=1):2922 # Create bounding box, add buttons2923 html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n'2924 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'2925 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail{0}</button>'2926 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'2927 if mode != 'command':2928 if testcount > 1:2929 self.html += html_devlist22930 self.html += html_devlist1.format('1')2931 else:2932 self.html += html_devlist1.format('')2933 self.html += html_zoombox2934 self.html += html_timeline.format('dmesg', self.height)2935 # Function: createTimeScale2936 # Description:2937 # Create the timescale for a timeline block2938 # Arguments:2939 # m0: start time (mode begin)2940 # mMax: end time (mode end)2941 # tTotal: total timeline time2942 # mode: suspend or resume2943 # Output:2944 # The html code needed to display the time scale2945 def createTimeScale(self, m0, mMax, tTotal, mode):2946 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'2947 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">{0}</div>\n'2948 output = '<div class="timescale">\n'2949 # set scale for timeline2950 mTotal = mMax - m02951 tS = 0.12952 if(tTotal <= 0):2953 return output+'</div>\n'2954 if(tTotal > 4):2955 tS = 12956 divTotal = int(mTotal/tS) + 12957 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal2958 for i in range(divTotal):2959 htmlline = ''2960 if(mode == 'suspend'):2961 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)2962 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)2963 if(i == divTotal - 1):2964 val = mode2965 htmlline = timescale.format(pos, val)2966 else:2967 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))2968 val = '%0.fms' % (float(i)*tS*1000)2969 htmlline = timescale.format(pos, val)2970 if(i == 0):2971 htmlline = rline.format(mode)2972 output += htmlline2973 self.html += output+'</div>\n'2974 2975# Class: TestProps2976# Description:2977# A list of values describing the properties of these test runs2978class TestProps:2979 stampfmt = r'# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\2980 r'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\2981 r' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'2982 wififmt = r'^# wifi *(?P<d>\S*) *(?P<s>\S*) *(?P<t>[0-9\.]+).*'2983 tstatfmt = r'^# turbostat (?P<t>\S*)'2984 testerrfmt = r'^# enter_sleep_error (?P<e>.*)'2985 sysinfofmt = r'^# sysinfo .*'2986 cmdlinefmt = r'^# command \| (?P<cmd>.*)'2987 kparamsfmt = r'^# kparams \| (?P<kp>.*)'2988 devpropfmt = r'# Device Properties: .*'2989 pinfofmt = r'# platform-(?P<val>[a-z,A-Z,0-9,_]*): (?P<info>.*)'2990 tracertypefmt = r'# tracer: (?P<t>.*)'2991 firmwarefmt = r'# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'2992 procexecfmt = r'ps - (?P<ps>.*)$'2993 procmultifmt = r'@(?P<n>[0-9]*)\|(?P<ps>.*)$'2994 ftrace_line_fmt_fg = \2995 r'^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\2996 r' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\2997 r'[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'2998 ftrace_line_fmt_nop = \2999 r' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\3000 r'(?P<flags>\S*) *(?P<time>[0-9\.]*): *'+\3001 r'(?P<msg>.*)'3002 machinesuspend = r'machine_suspend\[.*'3003 multiproclist = dict()3004 multiproctime = 0.03005 multiproccnt = 03006 def __init__(self):3007 self.stamp = ''3008 self.sysinfo = ''3009 self.cmdline = ''3010 self.testerror = []3011 self.turbostat = []3012 self.wifi = []3013 self.fwdata = []3014 self.ftrace_line_fmt = self.ftrace_line_fmt_nop3015 self.cgformat = False3016 self.data = 03017 self.ktemp = dict()3018 def setTracerType(self, tracer):3019 if(tracer == 'function_graph'):3020 self.cgformat = True3021 self.ftrace_line_fmt = self.ftrace_line_fmt_fg3022 elif(tracer == 'nop'):3023 self.ftrace_line_fmt = self.ftrace_line_fmt_nop3024 else:3025 doError('Invalid tracer format: [%s]' % tracer)3026 def stampInfo(self, line, sv):3027 if re.match(self.stampfmt, line):3028 self.stamp = line3029 return True3030 elif re.match(self.sysinfofmt, line):3031 self.sysinfo = line3032 return True3033 elif re.match(self.tstatfmt, line):3034 self.turbostat.append(line)3035 return True3036 elif re.match(self.wififmt, line):3037 self.wifi.append(line)3038 return True3039 elif re.match(self.testerrfmt, line):3040 self.testerror.append(line)3041 return True3042 elif re.match(self.firmwarefmt, line):3043 self.fwdata.append(line)3044 return True3045 elif(re.match(self.devpropfmt, line)):3046 self.parseDevprops(line, sv)3047 return True3048 elif(re.match(self.pinfofmt, line)):3049 self.parsePlatformInfo(line, sv)3050 return True3051 m = re.match(self.cmdlinefmt, line)3052 if m:3053 self.cmdline = m.group('cmd')3054 return True3055 m = re.match(self.tracertypefmt, line)3056 if(m):3057 self.setTracerType(m.group('t'))3058 return True3059 return False3060 def parseStamp(self, data, sv):3061 # global test data3062 m = re.match(self.stampfmt, self.stamp)3063 if not self.stamp or not m:3064 doError('data does not include the expected stamp')3065 data.stamp = {'time': '', 'host': '', 'mode': ''}3066 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),3067 int(m.group('d')), int(m.group('H')), int(m.group('M')),3068 int(m.group('S')))3069 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')3070 data.stamp['host'] = m.group('host')3071 data.stamp['mode'] = m.group('mode')3072 data.stamp['kernel'] = m.group('kernel')3073 if re.match(self.sysinfofmt, self.sysinfo):3074 for f in self.sysinfo.split('|'):3075 if '#' in f:3076 continue3077 tmp = f.strip().split(':', 1)3078 key = tmp[0]3079 val = tmp[1]3080 data.stamp[key] = val3081 sv.hostname = data.stamp['host']3082 sv.suspendmode = data.stamp['mode']3083 if sv.suspendmode == 'freeze':3084 self.machinesuspend = r'timekeeping_freeze\[.*'3085 else:3086 self.machinesuspend = r'machine_suspend\[.*'3087 if sv.suspendmode == 'command' and sv.ftracefile != '':3088 modes = ['on', 'freeze', 'standby', 'mem', 'disk']3089 fp = sv.openlog(sv.ftracefile, 'r')3090 for line in fp:3091 m = re.match(r'.* machine_suspend\[(?P<mode>.*)\]', line)3092 if m and m.group('mode') in ['1', '2', '3', '4']:3093 sv.suspendmode = modes[int(m.group('mode'))]3094 data.stamp['mode'] = sv.suspendmode3095 break3096 fp.close()3097 sv.cmdline = self.cmdline3098 if not sv.stamp:3099 sv.stamp = data.stamp3100 # firmware data3101 if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber:3102 m = re.match(self.firmwarefmt, self.fwdata[data.testnumber])3103 if m:3104 data.fwSuspend, data.fwResume = int(m.group('s')), int(m.group('r'))3105 if(data.fwSuspend > 0 or data.fwResume > 0):3106 data.fwValid = True3107 # turbostat data3108 if len(self.turbostat) > data.testnumber:3109 m = re.match(self.tstatfmt, self.turbostat[data.testnumber])3110 if m:3111 data.turbostat = m.group('t')3112 # wifi data3113 if len(self.wifi) > data.testnumber:3114 m = re.match(self.wififmt, self.wifi[data.testnumber])3115 if m:3116 data.wifi = {'dev': m.group('d'), 'stat': m.group('s'),3117 'time': float(m.group('t'))}3118 data.stamp['wifi'] = m.group('d')3119 # sleep mode enter errors3120 if len(self.testerror) > data.testnumber:3121 m = re.match(self.testerrfmt, self.testerror[data.testnumber])3122 if m:3123 data.enterfail = m.group('e')3124 def devprops(self, data):3125 props = dict()3126 devlist = data.split(';')3127 for dev in devlist:3128 f = dev.split(',')3129 if len(f) < 3:3130 continue3131 dev = f[0]3132 props[dev] = DevProps()3133 props[dev].altname = f[1]3134 if int(f[2]):3135 props[dev].isasync = True3136 else:3137 props[dev].isasync = False3138 return props3139 def parseDevprops(self, line, sv):3140 idx = line.index(': ') + 23141 if idx >= len(line):3142 return3143 props = self.devprops(line[idx:])3144 if sv.suspendmode == 'command' and 'testcommandstring' in props:3145 sv.testcommand = props['testcommandstring'].altname3146 sv.devprops = props3147 def parsePlatformInfo(self, line, sv):3148 m = re.match(self.pinfofmt, line)3149 if not m:3150 return3151 name, info = m.group('val'), m.group('info')3152 if name == 'devinfo':3153 sv.devprops = self.devprops(sv.b64unzip(info))3154 return3155 elif name == 'testcmd':3156 sv.testcommand = info3157 return3158 field = info.split('|')3159 if len(field) < 2:3160 return3161 cmdline = field[0].strip()3162 output = sv.b64unzip(field[1].strip())3163 sv.platinfo.append([name, cmdline, output])3164 3165# Class: TestRun3166# Description:3167# A container for a suspend/resume test run. This is necessary as3168# there could be more than one, and they need to be separate.3169class TestRun:3170 def __init__(self, dataobj):3171 self.data = dataobj3172 self.ftemp = dict()3173 self.ttemp = dict()3174 3175class ProcessMonitor:3176 maxchars = 5123177 def __init__(self):3178 self.proclist = dict()3179 self.running = False3180 def procstat(self):3181 c = ['cat /proc/[1-9]*/stat 2>/dev/null']3182 process = Popen(c, shell=True, stdout=PIPE)3183 running = dict()3184 for line in process.stdout:3185 data = ascii(line).split()3186 pid = data[0]3187 name = re.sub('[()]', '', data[1])3188 user = int(data[13])3189 kern = int(data[14])3190 kjiff = ujiff = 03191 if pid not in self.proclist:3192 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern}3193 else:3194 val = self.proclist[pid]3195 ujiff = user - val['user']3196 kjiff = kern - val['kern']3197 val['user'] = user3198 val['kern'] = kern3199 if ujiff > 0 or kjiff > 0:3200 running[pid] = ujiff + kjiff3201 process.wait()3202 out = ['']3203 for pid in running:3204 jiffies = running[pid]3205 val = self.proclist[pid]3206 if len(out[-1]) > self.maxchars:3207 out.append('')3208 elif len(out[-1]) > 0:3209 out[-1] += ','3210 out[-1] += '%s-%s %d' % (val['name'], pid, jiffies)3211 if len(out) > 1:3212 for line in out:3213 sysvals.fsetVal('ps - @%d|%s' % (len(out), line), 'trace_marker')3214 else:3215 sysvals.fsetVal('ps - %s' % out[0], 'trace_marker')3216 def processMonitor(self, tid):3217 while self.running:3218 self.procstat()3219 def start(self):3220 self.thread = Thread(target=self.processMonitor, args=(0,))3221 self.running = True3222 self.thread.start()3223 def stop(self):3224 self.running = False3225 3226# ----------------- FUNCTIONS --------------------3227 3228# Function: doesTraceLogHaveTraceEvents3229# Description:3230# Quickly determine if the ftrace log has all of the trace events,3231# markers, and/or kprobes required for primary parsing.3232def doesTraceLogHaveTraceEvents():3233 kpcheck = ['_cal: (', '_ret: (']3234 techeck = ['suspend_resume', 'device_pm_callback', 'tracing_mark_write']3235 tmcheck = ['SUSPEND START', 'RESUME COMPLETE']3236 sysvals.usekprobes = False3237 fp = sysvals.openlog(sysvals.ftracefile, 'r')3238 for line in fp:3239 # check for kprobes3240 if not sysvals.usekprobes:3241 for i in kpcheck:3242 if i in line:3243 sysvals.usekprobes = True3244 # check for all necessary trace events3245 check = techeck[:]3246 for i in techeck:3247 if i in line:3248 check.remove(i)3249 techeck = check3250 # check for all necessary trace markers3251 check = tmcheck[:]3252 for i in tmcheck:3253 if i in line:3254 check.remove(i)3255 tmcheck = check3256 fp.close()3257 sysvals.usetraceevents = True if len(techeck) < 3 else False3258 sysvals.usetracemarkers = True if len(tmcheck) == 0 else False3259 3260# Function: appendIncompleteTraceLog3261# Description:3262# Adds callgraph data which lacks trace event data. This is only3263# for timelines generated from 3.15 or older3264# Arguments:3265# testruns: the array of Data objects obtained from parseKernelLog3266def appendIncompleteTraceLog(testruns):3267 # create TestRun vessels for ftrace parsing3268 testcnt = len(testruns)3269 testidx = 03270 testrun = []3271 for data in testruns:3272 testrun.append(TestRun(data))3273 3274 # extract the callgraph and traceevent data3275 sysvals.vprint('Analyzing the ftrace data (%s)...' % \3276 os.path.basename(sysvals.ftracefile))3277 tp = TestProps()3278 tf = sysvals.openlog(sysvals.ftracefile, 'r')3279 data = 03280 for line in tf:3281 # remove any latent carriage returns3282 line = line.replace('\r\n', '')3283 if tp.stampInfo(line, sysvals):3284 continue3285 # parse only valid lines, if this is not one move on3286 m = re.match(tp.ftrace_line_fmt, line)3287 if(not m):3288 continue3289 # gather the basic message data from the line3290 m_time = m.group('time')3291 m_pid = m.group('pid')3292 m_msg = m.group('msg')3293 if(tp.cgformat):3294 m_param3 = m.group('dur')3295 else:3296 m_param3 = 'traceevent'3297 if(m_time and m_pid and m_msg):3298 t = FTraceLine(m_time, m_msg, m_param3)3299 pid = int(m_pid)3300 else:3301 continue3302 # the line should be a call, return, or event3303 if(not t.fcall and not t.freturn and not t.fevent):3304 continue3305 # look for the suspend start marker3306 if(t.startMarker()):3307 data = testrun[testidx].data3308 tp.parseStamp(data, sysvals)3309 data.setStart(t.time, t.name)3310 continue3311 if(not data):3312 continue3313 # find the end of resume3314 if(t.endMarker()):3315 data.setEnd(t.time, t.name)3316 testidx += 13317 if(testidx >= testcnt):3318 break3319 continue3320 # trace event processing3321 if(t.fevent):3322 continue3323 # call/return processing3324 elif sysvals.usecallgraph:3325 # create a callgraph object for the data3326 if(pid not in testrun[testidx].ftemp):3327 testrun[testidx].ftemp[pid] = []3328 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))3329 # when the call is finished, see which device matches it3330 cg = testrun[testidx].ftemp[pid][-1]3331 res = cg.addLine(t)3332 if(res != 0):3333 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))3334 if(res == -1):3335 testrun[testidx].ftemp[pid][-1].addLine(t)3336 tf.close()3337 3338 for test in testrun:3339 # add the callgraph data to the device hierarchy3340 for pid in test.ftemp:3341 for cg in test.ftemp[pid]:3342 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):3343 continue3344 if(not cg.postProcess()):3345 id = 'task %s cpu %s' % (pid, m.group('cpu'))3346 sysvals.vprint('Sanity check failed for '+\3347 id+', ignoring this callback')3348 continue3349 callstart = cg.start3350 callend = cg.end3351 for p in test.data.sortedPhases():3352 if(test.data.dmesg[p]['start'] <= callstart and3353 callstart <= test.data.dmesg[p]['end']):3354 list = test.data.dmesg[p]['list']3355 for devname in list:3356 dev = list[devname]3357 if(pid == dev['pid'] and3358 callstart <= dev['start'] and3359 callend >= dev['end']):3360 dev['ftrace'] = cg3361 break3362 3363# Function: loadTraceLog3364# Description:3365# load the ftrace file into memory and fix up any ordering issues3366# Output:3367# TestProps instance and an array of lines in proper order3368def loadTraceLog():3369 tp, data, lines, trace = TestProps(), dict(), [], []3370 tf = sysvals.openlog(sysvals.ftracefile, 'r')3371 for line in tf:3372 # remove any latent carriage returns3373 line = line.replace('\r\n', '')3374 if tp.stampInfo(line, sysvals):3375 continue3376 # ignore all other commented lines3377 if line[0] == '#':3378 continue3379 # ftrace line: parse only valid lines3380 m = re.match(tp.ftrace_line_fmt, line)3381 if(not m):3382 continue3383 dur = m.group('dur') if tp.cgformat else 'traceevent'3384 info = (m.group('time'), m.group('proc'), m.group('pid'),3385 m.group('msg'), dur)3386 # group the data by timestamp3387 t = float(info[0])3388 if t in data:3389 data[t].append(info)3390 else:3391 data[t] = [info]3392 # we only care about trace event ordering3393 if (info[3].startswith('suspend_resume:') or \3394 info[3].startswith('tracing_mark_write:')) and t not in trace:3395 trace.append(t)3396 tf.close()3397 for t in sorted(data):3398 first, last, blk = [], [], data[t]3399 if len(blk) > 1 and t in trace:3400 # move certain lines to the start or end of a timestamp block3401 for i in range(len(blk)):3402 if 'SUSPEND START' in blk[i][3]:3403 first.append(i)3404 elif re.match(r'.* timekeeping_freeze.*begin', blk[i][3]):3405 last.append(i)3406 elif re.match(r'.* timekeeping_freeze.*end', blk[i][3]):3407 first.append(i)3408 elif 'RESUME COMPLETE' in blk[i][3]:3409 last.append(i)3410 if len(first) == 1 and len(last) == 0:3411 blk.insert(0, blk.pop(first[0]))3412 elif len(last) == 1 and len(first) == 0:3413 blk.append(blk.pop(last[0]))3414 for info in blk:3415 lines.append(info)3416 return (tp, lines)3417 3418# Function: parseTraceLog3419# Description:3420# Analyze an ftrace log output file generated from this app during3421# the execution phase. Used when the ftrace log is the primary data source3422# and includes the suspend_resume and device_pm_callback trace events3423# The ftrace filename is taken from sysvals3424# Output:3425# An array of Data objects3426def parseTraceLog(live=False):3427 sysvals.vprint('Analyzing the ftrace data (%s)...' % \3428 os.path.basename(sysvals.ftracefile))3429 if(os.path.exists(sysvals.ftracefile) == False):3430 doError('%s does not exist' % sysvals.ftracefile)3431 if not live:3432 sysvals.setupAllKprobes()3433 ksuscalls = ['ksys_sync', 'pm_prepare_console']3434 krescalls = ['pm_restore_console']3435 tracewatch = ['irq_wakeup']3436 if sysvals.usekprobes:3437 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',3438 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON',3439 'CPU_OFF', 'acpi_suspend']3440 3441 # extract the callgraph and traceevent data3442 s2idle_enter = hwsus = False3443 testruns, testdata = [], []3444 testrun, data, limbo = 0, 0, True3445 phase = 'suspend_prepare'3446 tp, tf = loadTraceLog()3447 for m_time, m_proc, m_pid, m_msg, m_param3 in tf:3448 # gather the basic message data from the line3449 if(m_time and m_pid and m_msg):3450 t = FTraceLine(m_time, m_msg, m_param3)3451 pid = int(m_pid)3452 else:3453 continue3454 # the line should be a call, return, or event3455 if(not t.fcall and not t.freturn and not t.fevent):3456 continue3457 # find the start of suspend3458 if(t.startMarker()):3459 data, limbo = Data(len(testdata)), False3460 testdata.append(data)3461 testrun = TestRun(data)3462 testruns.append(testrun)3463 tp.parseStamp(data, sysvals)3464 data.setStart(t.time, t.name)3465 data.first_suspend_prepare = True3466 phase = data.setPhase('suspend_prepare', t.time, True)3467 continue3468 if(not data or limbo):3469 continue3470 # process cpu exec line3471 if t.type == 'tracing_mark_write':3472 if t.name == 'CMD COMPLETE' and data.tKernRes == 0:3473 data.tKernRes = t.time3474 m = re.match(tp.procexecfmt, t.name)3475 if(m):3476 parts, msg = 1, m.group('ps')3477 m = re.match(tp.procmultifmt, msg)3478 if(m):3479 parts, msg = int(m.group('n')), m.group('ps')3480 if tp.multiproccnt == 0:3481 tp.multiproctime = t.time3482 tp.multiproclist = dict()3483 proclist = tp.multiproclist3484 tp.multiproccnt += 13485 else:3486 proclist = dict()3487 tp.multiproccnt = 03488 for ps in msg.split(','):3489 val = ps.split()3490 if not val or len(val) != 2:3491 continue3492 name = val[0].replace('--', '-')3493 proclist[name] = int(val[1])3494 if parts == 1:3495 data.pstl[t.time] = proclist3496 elif parts == tp.multiproccnt:3497 data.pstl[tp.multiproctime] = proclist3498 tp.multiproccnt = 03499 continue3500 # find the end of resume3501 if(t.endMarker()):3502 if data.tKernRes == 0:3503 data.tKernRes = t.time3504 data.handleEndMarker(t.time, t.name)3505 if(not sysvals.usetracemarkers):3506 # no trace markers? then quit and be sure to finish recording3507 # the event we used to trigger resume end3508 if('thaw_processes' in testrun.ttemp and len(testrun.ttemp['thaw_processes']) > 0):3509 # if an entry exists, assume this is its end3510 testrun.ttemp['thaw_processes'][-1]['end'] = t.time3511 limbo = True3512 continue3513 # trace event processing3514 if(t.fevent):3515 if(t.type == 'suspend_resume'):3516 # suspend_resume trace events have two types, begin and end3517 if(re.match(r'(?P<name>.*) begin$', t.name)):3518 isbegin = True3519 elif(re.match(r'(?P<name>.*) end$', t.name)):3520 isbegin = False3521 else:3522 continue3523 if '[' in t.name:3524 m = re.match(r'(?P<name>.*)\[.*', t.name)3525 else:3526 m = re.match(r'(?P<name>.*) .*', t.name)3527 name = m.group('name')3528 # ignore these events3529 if(name.split('[')[0] in tracewatch):3530 continue3531 # -- phase changes --3532 # start of kernel suspend3533 if(re.match(r'suspend_enter\[.*', t.name)):3534 if(isbegin and data.tKernSus == 0):3535 data.tKernSus = t.time3536 continue3537 # suspend_prepare start3538 elif(re.match(r'dpm_prepare\[.*', t.name)):3539 if isbegin and data.first_suspend_prepare:3540 data.first_suspend_prepare = False3541 if data.tKernSus == 0:3542 data.tKernSus = t.time3543 continue3544 phase = data.setPhase('suspend_prepare', t.time, isbegin)3545 continue3546 # suspend start3547 elif(re.match(r'dpm_suspend\[.*', t.name)):3548 phase = data.setPhase('suspend', t.time, isbegin)3549 continue3550 # suspend_late start3551 elif(re.match(r'dpm_suspend_late\[.*', t.name)):3552 phase = data.setPhase('suspend_late', t.time, isbegin)3553 continue3554 # suspend_noirq start3555 elif(re.match(r'dpm_suspend_noirq\[.*', t.name)):3556 phase = data.setPhase('suspend_noirq', t.time, isbegin)3557 continue3558 # suspend_machine/resume_machine3559 elif(re.match(tp.machinesuspend, t.name)):3560 lp = data.lastPhase()3561 if(isbegin):3562 hwsus = True3563 if lp.startswith('resume_machine'):3564 # trim out s2idle loops, track time trying to freeze3565 llp = data.lastPhase(2)3566 if llp.startswith('suspend_machine'):3567 if 'waking' not in data.dmesg[llp]:3568 data.dmesg[llp]['waking'] = [0, 0.0]3569 data.dmesg[llp]['waking'][0] += 13570 data.dmesg[llp]['waking'][1] += \3571 t.time - data.dmesg[lp]['start']3572 data.currphase = ''3573 del data.dmesg[lp]3574 continue3575 phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True)3576 data.setPhase(phase, t.time, False)3577 if data.tSuspended == 0:3578 data.tSuspended = t.time3579 else:3580 if lp.startswith('resume_machine'):3581 data.dmesg[lp]['end'] = t.time3582 continue3583 phase = data.setPhase('resume_machine', t.time, True)3584 if(sysvals.suspendmode in ['mem', 'disk']):3585 susp = phase.replace('resume', 'suspend')3586 if susp in data.dmesg:3587 data.dmesg[susp]['end'] = t.time3588 data.tSuspended = t.time3589 data.tResumed = t.time3590 continue3591 # resume_noirq start3592 elif(re.match(r'dpm_resume_noirq\[.*', t.name)):3593 phase = data.setPhase('resume_noirq', t.time, isbegin)3594 continue3595 # resume_early start3596 elif(re.match(r'dpm_resume_early\[.*', t.name)):3597 phase = data.setPhase('resume_early', t.time, isbegin)3598 continue3599 # resume start3600 elif(re.match(r'dpm_resume\[.*', t.name)):3601 phase = data.setPhase('resume', t.time, isbegin)3602 continue3603 # resume complete start3604 elif(re.match(r'dpm_complete\[.*', t.name)):3605 phase = data.setPhase('resume_complete', t.time, isbegin)3606 continue3607 # skip trace events inside devices calls3608 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):3609 continue3610 # global events (outside device calls) are graphed3611 if(name not in testrun.ttemp):3612 testrun.ttemp[name] = []3613 # special handling for s2idle_enter3614 if name == 'machine_suspend':3615 if hwsus:3616 s2idle_enter = hwsus = False3617 elif s2idle_enter and not isbegin:3618 if(len(testrun.ttemp[name]) > 0):3619 testrun.ttemp[name][-1]['end'] = t.time3620 testrun.ttemp[name][-1]['loop'] += 13621 elif not s2idle_enter and isbegin:3622 s2idle_enter = True3623 testrun.ttemp[name].append({'begin': t.time,3624 'end': t.time, 'pid': pid, 'loop': 0})3625 continue3626 if(isbegin):3627 # create a new list entry3628 testrun.ttemp[name].append(\3629 {'begin': t.time, 'end': t.time, 'pid': pid})3630 else:3631 if(len(testrun.ttemp[name]) > 0):3632 # if an entry exists, assume this is its end3633 testrun.ttemp[name][-1]['end'] = t.time3634 # device callback start3635 elif(t.type == 'device_pm_callback_start'):3636 if phase not in data.dmesg:3637 continue3638 m = re.match(r'(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\3639 t.name);3640 if(not m):3641 continue3642 drv = m.group('drv')3643 n = m.group('d')3644 p = m.group('p')3645 if(n and p):3646 data.newAction(phase, n, pid, p, t.time, -1, drv)3647 if pid not in data.devpids:3648 data.devpids.append(pid)3649 # device callback finish3650 elif(t.type == 'device_pm_callback_end'):3651 if phase not in data.dmesg:3652 continue3653 m = re.match(r'(?P<drv>.*) (?P<d>.*), err.*', t.name);3654 if(not m):3655 continue3656 n = m.group('d')3657 dev = data.findDevice(phase, n)3658 if dev:3659 dev['length'] = t.time - dev['start']3660 dev['end'] = t.time3661 # kprobe event processing3662 elif(t.fkprobe):3663 kprobename = t.type3664 kprobedata = t.name3665 key = (kprobename, pid)3666 # displayname is generated from kprobe data3667 displayname = ''3668 if(t.fcall):3669 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)3670 if not displayname:3671 continue3672 if(key not in tp.ktemp):3673 tp.ktemp[key] = []3674 tp.ktemp[key].append({3675 'pid': pid,3676 'begin': t.time,3677 'end': -1,3678 'name': displayname,3679 'cdata': kprobedata,3680 'proc': m_proc,3681 })3682 # start of kernel resume3683 if(data.tKernSus == 0 and phase == 'suspend_prepare' \3684 and kprobename in ksuscalls):3685 data.tKernSus = t.time3686 elif(t.freturn):3687 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:3688 continue3689 e = next((x for x in reversed(tp.ktemp[key]) if x['end'] < 0), 0)3690 if not e:3691 continue3692 if (t.time - e['begin']) * 1000 < sysvals.mindevlen:3693 tp.ktemp[key].pop()3694 continue3695 e['end'] = t.time3696 e['rdata'] = kprobedata3697 # end of kernel resume3698 if(phase != 'suspend_prepare' and kprobename in krescalls):3699 if phase in data.dmesg:3700 data.dmesg[phase]['end'] = t.time3701 data.tKernRes = t.time3702 3703 # callgraph processing3704 elif sysvals.usecallgraph:3705 # create a callgraph object for the data3706 key = (m_proc, pid)3707 if(key not in testrun.ftemp):3708 testrun.ftemp[key] = []3709 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))3710 # when the call is finished, see which device matches it3711 cg = testrun.ftemp[key][-1]3712 res = cg.addLine(t)3713 if(res != 0):3714 testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))3715 if(res == -1):3716 testrun.ftemp[key][-1].addLine(t)3717 if len(testdata) < 1:3718 sysvals.vprint('WARNING: ftrace start marker is missing')3719 if data and not data.devicegroups:3720 sysvals.vprint('WARNING: ftrace end marker is missing')3721 data.handleEndMarker(t.time, t.name)3722 3723 if sysvals.suspendmode == 'command':3724 for test in testruns:3725 for p in test.data.sortedPhases():3726 if p == 'suspend_prepare':3727 test.data.dmesg[p]['start'] = test.data.start3728 test.data.dmesg[p]['end'] = test.data.end3729 else:3730 test.data.dmesg[p]['start'] = test.data.end3731 test.data.dmesg[p]['end'] = test.data.end3732 test.data.tSuspended = test.data.end3733 test.data.tResumed = test.data.end3734 test.data.fwValid = False3735 3736 # dev source and procmon events can be unreadable with mixed phase height3737 if sysvals.usedevsrc or sysvals.useprocmon:3738 sysvals.mixedphaseheight = False3739 3740 # expand phase boundaries so there are no gaps3741 for data in testdata:3742 lp = data.sortedPhases()[0]3743 for p in data.sortedPhases():3744 if(p != lp and not ('machine' in p and 'machine' in lp)):3745 data.dmesg[lp]['end'] = data.dmesg[p]['start']3746 lp = p3747 3748 for i in range(len(testruns)):3749 test = testruns[i]3750 data = test.data3751 # find the total time range for this test (begin, end)3752 tlb, tle = data.start, data.end3753 if i < len(testruns) - 1:3754 tle = testruns[i+1].data.start3755 # add the process usage data to the timeline3756 if sysvals.useprocmon:3757 data.createProcessUsageEvents()3758 # add the traceevent data to the device hierarchy3759 if(sysvals.usetraceevents):3760 # add actual trace funcs3761 for name in sorted(test.ttemp):3762 for event in test.ttemp[name]:3763 if event['end'] - event['begin'] <= 0:3764 continue3765 title = name3766 if name == 'machine_suspend' and 'loop' in event:3767 title = 's2idle_enter_%dx' % event['loop']3768 data.newActionGlobal(title, event['begin'], event['end'], event['pid'])3769 # add the kprobe based virtual tracefuncs as actual devices3770 for key in sorted(tp.ktemp):3771 name, pid = key3772 if name not in sysvals.tracefuncs:3773 continue3774 if pid not in data.devpids:3775 data.devpids.append(pid)3776 for e in tp.ktemp[key]:3777 kb, ke = e['begin'], e['end']3778 if ke - kb < 0.000001 or tlb > kb or tle <= kb:3779 continue3780 color = sysvals.kprobeColor(name)3781 data.newActionGlobal(e['name'], kb, ke, pid, color)3782 # add config base kprobes and dev kprobes3783 if sysvals.usedevsrc:3784 for key in sorted(tp.ktemp):3785 name, pid = key3786 if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs:3787 continue3788 for e in tp.ktemp[key]:3789 kb, ke = e['begin'], e['end']3790 if ke - kb < 0.000001 or tlb > kb or tle <= kb:3791 continue3792 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,3793 ke, e['cdata'], e['rdata'])3794 if sysvals.usecallgraph:3795 # add the callgraph data to the device hierarchy3796 sortlist = dict()3797 for key in sorted(test.ftemp):3798 proc, pid = key3799 for cg in test.ftemp[key]:3800 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):3801 continue3802 if(not cg.postProcess()):3803 id = 'task %s' % (pid)3804 sysvals.vprint('Sanity check failed for '+\3805 id+', ignoring this callback')3806 continue3807 # match cg data to devices3808 devname = ''3809 if sysvals.suspendmode != 'command':3810 devname = cg.deviceMatch(pid, data)3811 if not devname:3812 sortkey = '%f%f%d' % (cg.start, cg.end, pid)3813 sortlist[sortkey] = cg3814 elif len(cg.list) > 1000000 and cg.name != sysvals.ftopfunc:3815 sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\3816 (devname, len(cg.list)))3817 # create blocks for orphan cg data3818 for sortkey in sorted(sortlist):3819 cg = sortlist[sortkey]3820 name = cg.name3821 if sysvals.isCallgraphFunc(name):3822 sysvals.vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))3823 cg.newActionFromFunction(data)3824 if sysvals.suspendmode == 'command':3825 return (testdata, '')3826 3827 # fill in any missing phases3828 error = []3829 for data in testdata:3830 tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))3831 terr = ''3832 phasedef = data.phasedef3833 lp = 'suspend_prepare'3834 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):3835 if p not in data.dmesg:3836 if not terr:3837 ph = p if 'machine' in p else lp3838 if p == 'suspend_machine':3839 sm = sysvals.suspendmode3840 if sm in suspendmodename:3841 sm = suspendmodename[sm]3842 terr = 'test%s did not enter %s power mode' % (tn, sm)3843 else:3844 terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph)3845 pprint('TEST%s FAILED: %s' % (tn, terr))3846 error.append(terr)3847 if data.tSuspended == 0:3848 data.tSuspended = data.dmesg[lp]['end']3849 if data.tResumed == 0:3850 data.tResumed = data.dmesg[lp]['end']3851 data.fwValid = False3852 sysvals.vprint('WARNING: phase "%s" is missing!' % p)3853 lp = p3854 if not terr and 'dev' in data.wifi and data.wifi['stat'] == 'timeout':3855 terr = '%s%s failed in wifi_resume <i>(%s %.0fs timeout)</i>' % \3856 (sysvals.suspendmode, tn, data.wifi['dev'], data.wifi['time'])3857 error.append(terr)3858 if not terr and data.enterfail:3859 pprint('test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail))3860 terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode)3861 error.append(terr)3862 if data.tSuspended == 0:3863 data.tSuspended = data.tKernRes3864 if data.tResumed == 0:3865 data.tResumed = data.tSuspended3866 3867 if(len(sysvals.devicefilter) > 0):3868 data.deviceFilter(sysvals.devicefilter)3869 data.fixupInitcallsThatDidntReturn()3870 if sysvals.usedevsrc:3871 data.optimizeDevSrc()3872 3873 # x2: merge any overlapping devices between test runs3874 if sysvals.usedevsrc and len(testdata) > 1:3875 tc = len(testdata)3876 for i in range(tc - 1):3877 devlist = testdata[i].overflowDevices()3878 for j in range(i + 1, tc):3879 testdata[j].mergeOverlapDevices(devlist)3880 testdata[0].stitchTouchingThreads(testdata[1:])3881 return (testdata, ', '.join(error))3882 3883# Function: loadKernelLog3884# Description:3885# load the dmesg file into memory and fix up any ordering issues3886# Output:3887# An array of empty Data objects with only their dmesgtext attributes set3888def loadKernelLog():3889 sysvals.vprint('Analyzing the dmesg data (%s)...' % \3890 os.path.basename(sysvals.dmesgfile))3891 if(os.path.exists(sysvals.dmesgfile) == False):3892 doError('%s does not exist' % sysvals.dmesgfile)3893 3894 # there can be multiple test runs in a single file3895 tp = TestProps()3896 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')3897 testruns = []3898 data = 03899 lf = sysvals.openlog(sysvals.dmesgfile, 'r')3900 for line in lf:3901 line = line.replace('\r\n', '')3902 idx = line.find('[')3903 if idx > 1:3904 line = line[idx:]3905 if tp.stampInfo(line, sysvals):3906 continue3907 m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)3908 if(not m):3909 continue3910 msg = m.group("msg")3911 if re.match(r'PM: Syncing filesystems.*', msg) or \3912 re.match(r'PM: suspend entry.*', msg):3913 if(data):3914 testruns.append(data)3915 data = Data(len(testruns))3916 tp.parseStamp(data, sysvals)3917 if(not data):3918 continue3919 m = re.match(r'.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)3920 if(m):3921 sysvals.stamp['kernel'] = m.group('k')3922 m = re.match(r'PM: Preparing system for (?P<m>.*) sleep', msg)3923 if not m:3924 m = re.match(r'PM: Preparing system for sleep \((?P<m>.*)\)', msg)3925 if m:3926 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')3927 data.dmesgtext.append(line)3928 lf.close()3929 3930 if sysvals.suspendmode == 's2idle':3931 sysvals.suspendmode = 'freeze'3932 elif sysvals.suspendmode == 'deep':3933 sysvals.suspendmode = 'mem'3934 if data:3935 testruns.append(data)3936 if len(testruns) < 1:3937 doError('dmesg log has no suspend/resume data: %s' \3938 % sysvals.dmesgfile)3939 3940 # fix lines with same timestamp/function with the call and return swapped3941 for data in testruns:3942 last = ''3943 for line in data.dmesgtext:3944 ct, cf, n, p = data.initcall_debug_call(line)3945 rt, rf, l = data.initcall_debug_return(last)3946 if ct and rt and ct == rt and cf == rf:3947 i = data.dmesgtext.index(last)3948 j = data.dmesgtext.index(line)3949 data.dmesgtext[i] = line3950 data.dmesgtext[j] = last3951 last = line3952 return testruns3953 3954# Function: parseKernelLog3955# Description:3956# Analyse a dmesg log output file generated from this app during3957# the execution phase. Create a set of device structures in memory3958# for subsequent formatting in the html output file3959# This call is only for legacy support on kernels where the ftrace3960# data lacks the suspend_resume or device_pm_callbacks trace events.3961# Arguments:3962# data: an empty Data object (with dmesgtext) obtained from loadKernelLog3963# Output:3964# The filled Data object3965def parseKernelLog(data):3966 phase = 'suspend_runtime'3967 3968 if(data.fwValid):3969 sysvals.vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \3970 (data.fwSuspend, data.fwResume))3971 3972 # dmesg phase match table3973 dm = {3974 'suspend_prepare': ['PM: Syncing filesystems.*', 'PM: suspend entry.*'],3975 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*',3976 'PM: Suspending system .*'],3977 'suspend_late': ['PM: suspend of devices complete after.*',3978 'PM: freeze of devices complete after.*'],3979 'suspend_noirq': ['PM: late suspend of devices complete after.*',3980 'PM: late freeze of devices complete after.*'],3981 'suspend_machine': ['PM: suspend-to-idle',3982 'PM: noirq suspend of devices complete after.*',3983 'PM: noirq freeze of devices complete after.*'],3984 'resume_machine': ['[PM: ]*Timekeeping suspended for.*',3985 'ACPI: Low-level resume complete.*',3986 'ACPI: resume from mwait',3987 r'Suspended for [0-9\.]* seconds'],3988 'resume_noirq': ['PM: resume from suspend-to-idle',3989 'ACPI: Waking up from system sleep state.*'],3990 'resume_early': ['PM: noirq resume of devices complete after.*',3991 'PM: noirq restore of devices complete after.*'],3992 'resume': ['PM: early resume of devices complete after.*',3993 'PM: early restore of devices complete after.*'],3994 'resume_complete': ['PM: resume of devices complete after.*',3995 'PM: restore of devices complete after.*'],3996 'post_resume': [r'.*Restarting tasks \.\.\..*'],3997 }3998 3999 # action table (expected events that occur and show up in dmesg)4000 at = {4001 'sync_filesystems': {4002 'smsg': '.*[Ff]+ilesystems.*',4003 'emsg': 'PM: Preparing system for[a-z]* sleep.*' },4004 'freeze_user_processes': {4005 'smsg': 'Freezing user space processes.*',4006 'emsg': 'Freezing remaining freezable tasks.*' },4007 'freeze_tasks': {4008 'smsg': 'Freezing remaining freezable tasks.*',4009 'emsg': 'PM: Suspending system.*' },4010 'ACPI prepare': {4011 'smsg': 'ACPI: Preparing to enter system sleep state.*',4012 'emsg': 'PM: Saving platform NVS memory.*' },4013 'PM vns': {4014 'smsg': 'PM: Saving platform NVS memory.*',4015 'emsg': 'Disabling non-boot CPUs .*' },4016 }4017 4018 t0 = -1.04019 cpu_start = -1.04020 prevktime = -1.04021 actions = dict()4022 for line in data.dmesgtext:4023 # parse each dmesg line into the time and message4024 m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)4025 if(m):4026 val = m.group('ktime')4027 try:4028 ktime = float(val)4029 except:4030 continue4031 msg = m.group('msg')4032 # initialize data start to first line time4033 if t0 < 0:4034 data.setStart(ktime)4035 t0 = ktime4036 else:4037 continue4038 4039 # check for a phase change line4040 phasechange = False4041 for p in dm:4042 for s in dm[p]:4043 if(re.match(s, msg)):4044 phasechange, phase = True, p4045 dm[p] = [s]4046 break4047 4048 # hack for determining resume_machine end for freeze4049 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \4050 and phase == 'resume_machine' and \4051 data.initcall_debug_call(line, True)):4052 data.setPhase(phase, ktime, False)4053 phase = 'resume_noirq'4054 data.setPhase(phase, ktime, True)4055 4056 if phasechange:4057 if phase == 'suspend_prepare':4058 data.setPhase(phase, ktime, True)4059 data.setStart(ktime)4060 data.tKernSus = ktime4061 elif phase == 'suspend':4062 lp = data.lastPhase()4063 if lp:4064 data.setPhase(lp, ktime, False)4065 data.setPhase(phase, ktime, True)4066 elif phase == 'suspend_late':4067 lp = data.lastPhase()4068 if lp:4069 data.setPhase(lp, ktime, False)4070 data.setPhase(phase, ktime, True)4071 elif phase == 'suspend_noirq':4072 lp = data.lastPhase()4073 if lp:4074 data.setPhase(lp, ktime, False)4075 data.setPhase(phase, ktime, True)4076 elif phase == 'suspend_machine':4077 lp = data.lastPhase()4078 if lp:4079 data.setPhase(lp, ktime, False)4080 data.setPhase(phase, ktime, True)4081 elif phase == 'resume_machine':4082 lp = data.lastPhase()4083 if(sysvals.suspendmode in ['freeze', 'standby']):4084 data.tSuspended = prevktime4085 if lp:4086 data.setPhase(lp, prevktime, False)4087 else:4088 data.tSuspended = ktime4089 if lp:4090 data.setPhase(lp, prevktime, False)4091 data.tResumed = ktime4092 data.setPhase(phase, ktime, True)4093 elif phase == 'resume_noirq':4094 lp = data.lastPhase()4095 if lp:4096 data.setPhase(lp, ktime, False)4097 data.setPhase(phase, ktime, True)4098 elif phase == 'resume_early':4099 lp = data.lastPhase()4100 if lp:4101 data.setPhase(lp, ktime, False)4102 data.setPhase(phase, ktime, True)4103 elif phase == 'resume':4104 lp = data.lastPhase()4105 if lp:4106 data.setPhase(lp, ktime, False)4107 data.setPhase(phase, ktime, True)4108 elif phase == 'resume_complete':4109 lp = data.lastPhase()4110 if lp:4111 data.setPhase(lp, ktime, False)4112 data.setPhase(phase, ktime, True)4113 elif phase == 'post_resume':4114 lp = data.lastPhase()4115 if lp:4116 data.setPhase(lp, ktime, False)4117 data.setEnd(ktime)4118 data.tKernRes = ktime4119 break4120 4121 # -- device callbacks --4122 if(phase in data.sortedPhases()):4123 # device init call4124 t, f, n, p = data.initcall_debug_call(line)4125 if t and f and n and p:4126 data.newAction(phase, f, int(n), p, ktime, -1, '')4127 else:4128 # device init return4129 t, f, l = data.initcall_debug_return(line)4130 if t and f and l:4131 list = data.dmesg[phase]['list']4132 if(f in list):4133 dev = list[f]4134 dev['length'] = int(l)4135 dev['end'] = ktime4136 4137 # if trace events are not available, these are better than nothing4138 if(not sysvals.usetraceevents):4139 # look for known actions4140 for a in sorted(at):4141 if(re.match(at[a]['smsg'], msg)):4142 if(a not in actions):4143 actions[a] = [{'begin': ktime, 'end': ktime}]4144 if(re.match(at[a]['emsg'], msg)):4145 if(a in actions and actions[a][-1]['begin'] == actions[a][-1]['end']):4146 actions[a][-1]['end'] = ktime4147 # now look for CPU on/off events4148 if(re.match(r'Disabling non-boot CPUs .*', msg)):4149 # start of first cpu suspend4150 cpu_start = ktime4151 elif(re.match(r'Enabling non-boot CPUs .*', msg)):4152 # start of first cpu resume4153 cpu_start = ktime4154 elif(re.match(r'smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) \4155 or re.match(r'psci: CPU(?P<cpu>[0-9]*) killed.*', msg)):4156 # end of a cpu suspend, start of the next4157 m = re.match(r'smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)4158 if(not m):4159 m = re.match(r'psci: CPU(?P<cpu>[0-9]*) killed.*', msg)4160 cpu = 'CPU'+m.group('cpu')4161 if(cpu not in actions):4162 actions[cpu] = []4163 actions[cpu].append({'begin': cpu_start, 'end': ktime})4164 cpu_start = ktime4165 elif(re.match(r'CPU(?P<cpu>[0-9]*) is up', msg)):4166 # end of a cpu resume, start of the next4167 m = re.match(r'CPU(?P<cpu>[0-9]*) is up', msg)4168 cpu = 'CPU'+m.group('cpu')4169 if(cpu not in actions):4170 actions[cpu] = []4171 actions[cpu].append({'begin': cpu_start, 'end': ktime})4172 cpu_start = ktime4173 prevktime = ktime4174 data.initDevicegroups()4175 4176 # fill in any missing phases4177 phasedef = data.phasedef4178 terr, lp = '', 'suspend_prepare'4179 if lp not in data.dmesg:4180 doError('dmesg log format has changed, could not find start of suspend')4181 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):4182 if p not in data.dmesg:4183 if not terr:4184 pprint('TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp))4185 terr = '%s failed in %s phase' % (sysvals.suspendmode, lp)4186 if data.tSuspended == 0:4187 data.tSuspended = data.dmesg[lp]['end']4188 if data.tResumed == 0:4189 data.tResumed = data.dmesg[lp]['end']4190 sysvals.vprint('WARNING: phase "%s" is missing!' % p)4191 lp = p4192 lp = data.sortedPhases()[0]4193 for p in data.sortedPhases():4194 if(p != lp and not ('machine' in p and 'machine' in lp)):4195 data.dmesg[lp]['end'] = data.dmesg[p]['start']4196 lp = p4197 if data.tSuspended == 0:4198 data.tSuspended = data.tKernRes4199 if data.tResumed == 0:4200 data.tResumed = data.tSuspended4201 4202 # fill in any actions we've found4203 for name in sorted(actions):4204 for event in actions[name]:4205 data.newActionGlobal(name, event['begin'], event['end'])4206 4207 if(len(sysvals.devicefilter) > 0):4208 data.deviceFilter(sysvals.devicefilter)4209 data.fixupInitcallsThatDidntReturn()4210 return True4211 4212def callgraphHTML(sv, hf, num, cg, title, color, devid):4213 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'4214 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'4215 html_func_end = '</article>\n'4216 html_func_leaf = '<article>{0} {1}</article>\n'4217 4218 cgid = devid4219 if cg.id:4220 cgid += cg.id4221 cglen = (cg.end - cg.start) * 10004222 if cglen < sv.mincglen:4223 return num4224 4225 fmt = '<r>(%.3f ms @ '+sv.timeformat+' to '+sv.timeformat+')</r>'4226 flen = fmt % (cglen, cg.start, cg.end)4227 hf.write(html_func_top.format(cgid, color, num, title, flen))4228 num += 14229 for line in cg.list:4230 if(line.length < 0.000000001):4231 flen = ''4232 else:4233 fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'4234 flen = fmt % (line.length*1000, line.time)4235 if line.isLeaf():4236 if line.length * 1000 < sv.mincglen:4237 continue4238 hf.write(html_func_leaf.format(line.name, flen))4239 elif line.freturn:4240 hf.write(html_func_end)4241 else:4242 hf.write(html_func_start.format(num, line.name, flen))4243 num += 14244 hf.write(html_func_end)4245 return num4246 4247def addCallgraphs(sv, hf, data):4248 hf.write('<section id="callgraphs" class="callgraph">\n')4249 # write out the ftrace data converted to html4250 num = 04251 for p in data.sortedPhases():4252 if sv.cgphase and p != sv.cgphase:4253 continue4254 list = data.dmesg[p]['list']4255 for d in data.sortedDevices(p):4256 if len(sv.cgfilter) > 0 and d not in sv.cgfilter:4257 continue4258 dev = list[d]4259 color = 'white'4260 if 'color' in data.dmesg[p]:4261 color = data.dmesg[p]['color']4262 if 'color' in dev:4263 color = dev['color']4264 name = d if '[' not in d else d.split('[')[0]4265 if(d in sv.devprops):4266 name = sv.devprops[d].altName(d)4267 if 'drv' in dev and dev['drv']:4268 name += ' {%s}' % dev['drv']4269 if sv.suspendmode in suspendmodename:4270 name += ' '+p4271 if('ftrace' in dev):4272 cg = dev['ftrace']4273 if cg.name == sv.ftopfunc:4274 name = 'top level suspend/resume call'4275 num = callgraphHTML(sv, hf, num, cg,4276 name, color, dev['id'])4277 if('ftraces' in dev):4278 for cg in dev['ftraces']:4279 num = callgraphHTML(sv, hf, num, cg,4280 name+' → '+cg.name, color, dev['id'])4281 hf.write('\n\n </section>\n')4282 4283def summaryCSS(title, center=True):4284 tdcenter = 'text-align:center;' if center else ''4285 out = '<!DOCTYPE html>\n<html>\n<head>\n\4286 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\4287 <title>'+title+'</title>\n\4288 <style type=\'text/css\'>\n\4289 .stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\4290 table {width:100%;border-collapse: collapse;border:1px solid;}\n\4291 th {border: 1px solid black;background:#222;color:white;}\n\4292 td {font: 14px "Times New Roman";'+tdcenter+'}\n\4293 tr.head td {border: 1px solid black;background:#aaa;}\n\4294 tr.alt {background-color:#ddd;}\n\4295 tr.notice {color:red;}\n\4296 .minval {background-color:#BBFFBB;}\n\4297 .medval {background-color:#BBBBFF;}\n\4298 .maxval {background-color:#FFBBBB;}\n\4299 .head a {color:#000;text-decoration: none;}\n\4300 </style>\n</head>\n<body>\n'4301 return out4302 4303# Function: createHTMLSummarySimple4304# Description:4305# Create summary html file for a series of tests4306# Arguments:4307# testruns: array of Data objects from parseTraceLog4308def createHTMLSummarySimple(testruns, htmlfile, title):4309 # write the html header first (html head, css code, up to body start)4310 html = summaryCSS('Summary - SleepGraph')4311 4312 # extract the test data into list4313 list = dict()4314 tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()]4315 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]4316 num = 04317 useturbo = usewifi = False4318 lastmode = ''4319 cnt = dict()4320 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):4321 mode = data['mode']4322 if mode not in list:4323 list[mode] = {'data': [], 'avg': [0,0], 'min': [0,0], 'max': [0,0], 'med': [0,0]}4324 if lastmode and lastmode != mode and num > 0:4325 for i in range(2):4326 s = sorted(tMed[i])4327 list[lastmode]['med'][i] = s[int(len(s)//2)]4328 iMed[i] = tMed[i][list[lastmode]['med'][i]]4329 list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]4330 list[lastmode]['min'] = tMin4331 list[lastmode]['max'] = tMax4332 list[lastmode]['idx'] = (iMin, iMed, iMax)4333 tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()]4334 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]4335 num = 04336 pkgpc10 = syslpi = wifi = ''4337 if 'pkgpc10' in data and 'syslpi' in data:4338 pkgpc10, syslpi, useturbo = data['pkgpc10'], data['syslpi'], True4339 if 'wifi' in data:4340 wifi, usewifi = data['wifi'], True4341 res = data['result']4342 tVal = [float(data['suspend']), float(data['resume'])]4343 list[mode]['data'].append([data['host'], data['kernel'],4344 data['time'], tVal[0], tVal[1], data['url'], res,4345 data['issues'], data['sus_worst'], data['sus_worsttime'],4346 data['res_worst'], data['res_worsttime'], pkgpc10, syslpi, wifi,4347 (data['fullmode'] if 'fullmode' in data else mode)])4348 idx = len(list[mode]['data']) - 14349 if res.startswith('fail in'):4350 res = 'fail'4351 if res not in cnt:4352 cnt[res] = 14353 else:4354 cnt[res] += 14355 if res == 'pass':4356 for i in range(2):4357 tMed[i][tVal[i]] = idx4358 tAvg[i] += tVal[i]4359 if tMin[i] == 0 or tVal[i] < tMin[i]:4360 iMin[i] = idx4361 tMin[i] = tVal[i]4362 if tMax[i] == 0 or tVal[i] > tMax[i]:4363 iMax[i] = idx4364 tMax[i] = tVal[i]4365 num += 14366 lastmode = mode4367 if lastmode and num > 0:4368 for i in range(2):4369 s = sorted(tMed[i])4370 list[lastmode]['med'][i] = s[int(len(s)//2)]4371 iMed[i] = tMed[i][list[lastmode]['med'][i]]4372 list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]4373 list[lastmode]['min'] = tMin4374 list[lastmode]['max'] = tMax4375 list[lastmode]['idx'] = (iMin, iMed, iMax)4376 4377 # group test header4378 desc = []4379 for ilk in sorted(cnt, reverse=True):4380 if cnt[ilk] > 0:4381 desc.append('%d %s' % (cnt[ilk], ilk))4382 html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (title, len(testruns), ', '.join(desc))4383 th = '\t<th>{0}</th>\n'4384 td = '\t<td>{0}</td>\n'4385 tdh = '\t<td{1}>{0}</td>\n'4386 tdlink = '\t<td><a href="{0}">html</a></td>\n'4387 cols = 124388 if useturbo:4389 cols += 24390 if usewifi:4391 cols += 14392 colspan = '%d' % cols4393 4394 # table header4395 html += '<table>\n<tr>\n' + th.format('#') +\4396 th.format('Mode') + th.format('Host') + th.format('Kernel') +\4397 th.format('Test Time') + th.format('Result') + th.format('Issues') +\4398 th.format('Suspend') + th.format('Resume') +\4399 th.format('Worst Suspend Device') + th.format('SD Time') +\4400 th.format('Worst Resume Device') + th.format('RD Time')4401 if useturbo:4402 html += th.format('PkgPC10') + th.format('SysLPI')4403 if usewifi:4404 html += th.format('Wifi')4405 html += th.format('Detail')+'</tr>\n'4406 # export list into html4407 head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\4408 '<td colspan='+colspan+' class="sus">Suspend Avg={2} '+\4409 '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\4410 '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\4411 '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\4412 'Resume Avg={6} '+\4413 '<span class=minval><a href="#r{10}min">Min={7}</a></span> '+\4414 '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\4415 '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\4416 '</tr>\n'4417 headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan='+\4418 colspan+'></td></tr>\n'4419 for mode in sorted(list):4420 # header line for each suspend mode4421 num = 04422 tAvg, tMin, tMax, tMed = list[mode]['avg'], list[mode]['min'],\4423 list[mode]['max'], list[mode]['med']4424 count = len(list[mode]['data'])4425 if 'idx' in list[mode]:4426 iMin, iMed, iMax = list[mode]['idx']4427 html += head.format('%d' % count, mode.upper(),4428 '%.3f' % tAvg[0], '%.3f' % tMin[0], '%.3f' % tMed[0], '%.3f' % tMax[0],4429 '%.3f' % tAvg[1], '%.3f' % tMin[1], '%.3f' % tMed[1], '%.3f' % tMax[1],4430 mode.lower()4431 )4432 else:4433 iMin = iMed = iMax = [-1, -1, -1]4434 html += headnone.format('%d' % count, mode.upper())4435 for d in list[mode]['data']:4436 # row classes - alternate row color4437 rcls = ['alt'] if num % 2 == 1 else []4438 if d[6] != 'pass':4439 rcls.append('notice')4440 html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'4441 # figure out if the line has sus or res highlighted4442 idx = list[mode]['data'].index(d)4443 tHigh = ['', '']4444 for i in range(2):4445 tag = 's%s' % mode if i == 0 else 'r%s' % mode4446 if idx == iMin[i]:4447 tHigh[i] = ' id="%smin" class=minval title="Minimum"' % tag4448 elif idx == iMax[i]:4449 tHigh[i] = ' id="%smax" class=maxval title="Maximum"' % tag4450 elif idx == iMed[i]:4451 tHigh[i] = ' id="%smed" class=medval title="Median"' % tag4452 html += td.format("%d" % (list[mode]['data'].index(d) + 1)) # row4453 html += td.format(d[15]) # mode4454 html += td.format(d[0]) # host4455 html += td.format(d[1]) # kernel4456 html += td.format(d[2]) # time4457 html += td.format(d[6]) # result4458 html += td.format(d[7]) # issues4459 html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend4460 html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume4461 html += td.format(d[8]) # sus_worst4462 html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time4463 html += td.format(d[10]) # res_worst4464 html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time4465 if useturbo:4466 html += td.format(d[12]) # pkg_pc104467 html += td.format(d[13]) # syslpi4468 if usewifi:4469 html += td.format(d[14]) # wifi4470 html += tdlink.format(d[5]) if d[5] else td.format('') # url4471 html += '</tr>\n'4472 num += 14473 4474 # flush the data to file4475 hf = open(htmlfile, 'w')4476 hf.write(html+'</table>\n</body>\n</html>\n')4477 hf.close()4478 4479def createHTMLDeviceSummary(testruns, htmlfile, title):4480 html = summaryCSS('Device Summary - SleepGraph', False)4481 4482 # create global device list from all tests4483 devall = dict()4484 for data in testruns:4485 host, url, devlist = data['host'], data['url'], data['devlist']4486 for type in devlist:4487 if type not in devall:4488 devall[type] = dict()4489 mdevlist, devlist = devall[type], data['devlist'][type]4490 for name in devlist:4491 length = devlist[name]4492 if name not in mdevlist:4493 mdevlist[name] = {'name': name, 'host': host,4494 'worst': length, 'total': length, 'count': 1,4495 'url': url}4496 else:4497 if length > mdevlist[name]['worst']:4498 mdevlist[name]['worst'] = length4499 mdevlist[name]['url'] = url4500 mdevlist[name]['host'] = host4501 mdevlist[name]['total'] += length4502 mdevlist[name]['count'] += 14503 4504 # generate the html4505 th = '\t<th>{0}</th>\n'4506 td = '\t<td align=center>{0}</td>\n'4507 tdr = '\t<td align=right>{0}</td>\n'4508 tdlink = '\t<td align=center><a href="{0}">html</a></td>\n'4509 limit = 14510 for type in sorted(devall, reverse=True):4511 num = 04512 devlist = devall[type]4513 # table header4514 html += '<div class="stamp">%s (%s devices > %d ms)</div><table>\n' % \4515 (title, type.upper(), limit)4516 html += '<tr>\n' + '<th align=right>Device Name</th>' +\4517 th.format('Average Time') + th.format('Count') +\4518 th.format('Worst Time') + th.format('Host (worst time)') +\4519 th.format('Link (worst time)') + '</tr>\n'4520 for name in sorted(devlist, key=lambda k:(devlist[k]['worst'], \4521 devlist[k]['total'], devlist[k]['name']), reverse=True):4522 data = devall[type][name]4523 data['average'] = data['total'] / data['count']4524 if data['average'] < limit:4525 continue4526 # row classes - alternate row color4527 rcls = ['alt'] if num % 2 == 1 else []4528 html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'4529 html += tdr.format(data['name']) # name4530 html += td.format('%.3f ms' % data['average']) # average4531 html += td.format(data['count']) # count4532 html += td.format('%.3f ms' % data['worst']) # worst4533 html += td.format(data['host']) # host4534 html += tdlink.format(data['url']) # url4535 html += '</tr>\n'4536 num += 14537 html += '</table>\n'4538 4539 # flush the data to file4540 hf = open(htmlfile, 'w')4541 hf.write(html+'</body>\n</html>\n')4542 hf.close()4543 return devall4544 4545def createHTMLIssuesSummary(testruns, issues, htmlfile, title, extra=''):4546 multihost = len([e for e in issues if len(e['urls']) > 1]) > 04547 html = summaryCSS('Issues Summary - SleepGraph', False)4548 total = len(testruns)4549 4550 # generate the html4551 th = '\t<th>{0}</th>\n'4552 td = '\t<td align={0}>{1}</td>\n'4553 tdlink = '<a href="{1}">{0}</a>'4554 subtitle = '%d issues' % len(issues) if len(issues) > 0 else 'no issues'4555 html += '<div class="stamp">%s (%s)</div><table>\n' % (title, subtitle)4556 html += '<tr>\n' + th.format('Issue') + th.format('Count')4557 if multihost:4558 html += th.format('Hosts')4559 html += th.format('Tests') + th.format('Fail Rate') +\4560 th.format('First Instance') + '</tr>\n'4561 4562 num = 04563 for e in sorted(issues, key=lambda v:v['count'], reverse=True):4564 testtotal = 04565 links = []4566 for host in sorted(e['urls']):4567 links.append(tdlink.format(host, e['urls'][host][0]))4568 testtotal += len(e['urls'][host])4569 rate = '%d/%d (%.2f%%)' % (testtotal, total, 100*float(testtotal)/float(total))4570 # row classes - alternate row color4571 rcls = ['alt'] if num % 2 == 1 else []4572 html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'4573 html += td.format('left', e['line']) # issue4574 html += td.format('center', e['count']) # count4575 if multihost:4576 html += td.format('center', len(e['urls'])) # hosts4577 html += td.format('center', testtotal) # test count4578 html += td.format('center', rate) # test rate4579 html += td.format('center nowrap', '<br>'.join(links)) # links4580 html += '</tr>\n'4581 num += 14582 4583 # flush the data to file4584 hf = open(htmlfile, 'w')4585 hf.write(html+'</table>\n'+extra+'</body>\n</html>\n')4586 hf.close()4587 return issues4588 4589def ordinal(value):4590 suffix = 'th'4591 if value < 10 or value > 19:4592 if value % 10 == 1:4593 suffix = 'st'4594 elif value % 10 == 2:4595 suffix = 'nd'4596 elif value % 10 == 3:4597 suffix = 'rd'4598 return '%d%s' % (value, suffix)4599 4600# Function: createHTML4601# Description:4602# Create the output html file from the resident test data4603# Arguments:4604# testruns: array of Data objects from parseKernelLog or parseTraceLog4605# Output:4606# True if the html file was created, false if it failed4607def createHTML(testruns, testfail):4608 if len(testruns) < 1:4609 pprint('ERROR: Not enough test data to build a timeline')4610 return4611 4612 kerror = False4613 for data in testruns:4614 if data.kerror:4615 kerror = True4616 if(sysvals.suspendmode in ['freeze', 'standby']):4617 data.trimFreezeTime(testruns[-1].tSuspended)4618 else:4619 data.getMemTime()4620 4621 # html function templates4622 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</div>\n'4623 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'4624 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'4625 html_timetotal = '<table class="time1">\n<tr>'\4626 '<td class="green" title="{3}">{2} Suspend Time: <b>{0} ms</b></td>'\4627 '<td class="yellow" title="{4}">{2} Resume Time: <b>{1} ms</b></td>'\4628 '</tr>\n</table>\n'4629 html_timetotal2 = '<table class="time1">\n<tr>'\4630 '<td class="green" title="{4}">{3} Suspend Time: <b>{0} ms</b></td>'\4631 '<td class="gray" title="time spent in low-power mode with clock running">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\4632 '<td class="yellow" title="{5}">{3} Resume Time: <b>{2} ms</b></td>'\4633 '</tr>\n</table>\n'4634 html_timetotal3 = '<table class="time1">\n<tr>'\4635 '<td class="green">Execution Time: <b>{0} ms</b></td>'\4636 '<td class="yellow">Command: <b>{1}</b></td>'\4637 '</tr>\n</table>\n'4638 html_fail = '<table class="testfail"><tr><td>{0}</td></tr></table>\n'4639 html_kdesc = '<td class="{3}" title="time spent in kernel execution">{0}Kernel {2}: {1} ms</td>'4640 html_fwdesc = '<td class="{3}" title="time spent in firmware">{0}Firmware {2}: {1} ms</td>'4641 html_wifdesc = '<td class="yellow" title="time for wifi to reconnect after resume complete ({2})">{0}Wifi Resume: {1}</td>'4642 4643 # html format variables4644 scaleH = 204645 if kerror:4646 scaleH = 404647 4648 # device timeline4649 devtl = Timeline(30, scaleH)4650 4651 # write the test title and general info header4652 devtl.createHeader(sysvals, testruns[0].stamp)4653 4654 # Generate the header for this timeline4655 for data in testruns:4656 tTotal = data.end - data.start4657 if(tTotal == 0):4658 doError('No timeline data')4659 if sysvals.suspendmode == 'command':4660 run_time = '%.0f' % (tTotal * 1000)4661 if sysvals.testcommand:4662 testdesc = sysvals.testcommand4663 else:4664 testdesc = 'unknown'4665 if(len(testruns) > 1):4666 testdesc = ordinal(data.testnumber+1)+' '+testdesc4667 thtml = html_timetotal3.format(run_time, testdesc)4668 devtl.html += thtml4669 continue4670 # typical full suspend/resume header4671 stot, rtot = sktime, rktime = data.getTimeValues()4672 ssrc, rsrc, testdesc, testdesc2 = ['kernel'], ['kernel'], 'Kernel', ''4673 if data.fwValid:4674 stot += (data.fwSuspend/1000000.0)4675 rtot += (data.fwResume/1000000.0)4676 ssrc.append('firmware')4677 rsrc.append('firmware')4678 testdesc = 'Total'4679 if 'time' in data.wifi and data.wifi['stat'] != 'timeout':4680 rtot += data.end - data.tKernRes + (data.wifi['time'] * 1000.0)4681 rsrc.append('wifi')4682 testdesc = 'Total'4683 suspend_time, resume_time = '%.3f' % stot, '%.3f' % rtot4684 stitle = 'time from kernel suspend start to %s mode [%s time]' % \4685 (sysvals.suspendmode, ' & '.join(ssrc))4686 rtitle = 'time from %s mode to kernel resume complete [%s time]' % \4687 (sysvals.suspendmode, ' & '.join(rsrc))4688 if(len(testruns) > 1):4689 testdesc = testdesc2 = ordinal(data.testnumber+1)4690 testdesc2 += ' '4691 if(len(data.tLow) == 0):4692 thtml = html_timetotal.format(suspend_time, \4693 resume_time, testdesc, stitle, rtitle)4694 else:4695 low_time = '+'.join(data.tLow)4696 thtml = html_timetotal2.format(suspend_time, low_time, \4697 resume_time, testdesc, stitle, rtitle)4698 devtl.html += thtml4699 if not data.fwValid and 'dev' not in data.wifi:4700 continue4701 # extra detail when the times come from multiple sources4702 thtml = '<table class="time2">\n<tr>'4703 thtml += html_kdesc.format(testdesc2, '%.3f'%sktime, 'Suspend', 'green')4704 if data.fwValid:4705 sftime = '%.3f'%(data.fwSuspend / 1000000.0)4706 rftime = '%.3f'%(data.fwResume / 1000000.0)4707 thtml += html_fwdesc.format(testdesc2, sftime, 'Suspend', 'green')4708 thtml += html_fwdesc.format(testdesc2, rftime, 'Resume', 'yellow')4709 thtml += html_kdesc.format(testdesc2, '%.3f'%rktime, 'Resume', 'yellow')4710 if 'time' in data.wifi:4711 if data.wifi['stat'] != 'timeout':4712 wtime = '%.0f ms'%(data.end - data.tKernRes + (data.wifi['time'] * 1000.0))4713 else:4714 wtime = 'TIMEOUT'4715 thtml += html_wifdesc.format(testdesc2, wtime, data.wifi['dev'])4716 thtml += '</tr>\n</table>\n'4717 devtl.html += thtml4718 if testfail:4719 devtl.html += html_fail.format(testfail)4720 4721 # time scale for potentially multiple datasets4722 t0 = testruns[0].start4723 tMax = testruns[-1].end4724 tTotal = tMax - t04725 4726 # determine the maximum number of rows we need to draw4727 fulllist = []4728 threadlist = []4729 pscnt = 04730 devcnt = 04731 for data in testruns:4732 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)4733 for group in data.devicegroups:4734 devlist = []4735 for phase in group:4736 for devname in sorted(data.tdevlist[phase]):4737 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])4738 devlist.append(d)4739 if d.isa('kth'):4740 threadlist.append(d)4741 else:4742 if d.isa('ps'):4743 pscnt += 14744 else:4745 devcnt += 14746 fulllist.append(d)4747 if sysvals.mixedphaseheight:4748 devtl.getPhaseRows(devlist)4749 if not sysvals.mixedphaseheight:4750 if len(threadlist) > 0 and len(fulllist) > 0:4751 if pscnt > 0 and devcnt > 0:4752 msg = 'user processes & device pm callbacks'4753 elif pscnt > 0:4754 msg = 'user processes'4755 else:4756 msg = 'device pm callbacks'4757 d = testruns[0].addHorizontalDivider(msg, testruns[-1].end)4758 fulllist.insert(0, d)4759 devtl.getPhaseRows(fulllist)4760 if len(threadlist) > 0:4761 d = testruns[0].addHorizontalDivider('asynchronous kernel threads', testruns[-1].end)4762 threadlist.insert(0, d)4763 devtl.getPhaseRows(threadlist, devtl.rows)4764 devtl.calcTotalRows()4765 4766 # draw the full timeline4767 devtl.createZoomBox(sysvals.suspendmode, len(testruns))4768 for data in testruns:4769 # draw each test run and block chronologically4770 phases = {'suspend':[],'resume':[]}4771 for phase in data.sortedPhases():4772 if data.dmesg[phase]['start'] >= data.tSuspended:4773 phases['resume'].append(phase)4774 else:4775 phases['suspend'].append(phase)4776 # now draw the actual timeline blocks4777 for dir in phases:4778 # draw suspend and resume blocks separately4779 bname = '%s%d' % (dir[0], data.testnumber)4780 if dir == 'suspend':4781 m0 = data.start4782 mMax = data.tSuspended4783 left = '%f' % (((m0-t0)*100.0)/tTotal)4784 else:4785 m0 = data.tSuspended4786 mMax = data.end4787 # in an x2 run, remove any gap between blocks4788 if len(testruns) > 1 and data.testnumber == 0:4789 mMax = testruns[1].start4790 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)4791 mTotal = mMax - m04792 # if a timeline block is 0 length, skip altogether4793 if mTotal == 0:4794 continue4795 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)4796 devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)4797 for b in phases[dir]:4798 # draw the phase color background4799 phase = data.dmesg[b]4800 length = phase['end']-phase['start']4801 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)4802 width = '%f' % ((length*100.0)/mTotal)4803 devtl.html += devtl.html_phase.format(left, width, \4804 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \4805 data.dmesg[b]['color'], '')4806 for e in data.errorinfo[dir]:4807 # draw red lines for any kernel errors found4808 type, t, idx1, idx2 = e4809 id = '%d_%d' % (idx1, idx2)4810 right = '%f' % (((mMax-t)*100.0)/mTotal)4811 devtl.html += html_error.format(right, id, type)4812 for b in phases[dir]:4813 # draw the devices for this phase4814 phaselist = data.dmesg[b]['list']4815 for d in sorted(data.tdevlist[b]):4816 dname = d if ('[' not in d or 'CPU' in d) else d.split('[')[0]4817 name, dev = dname, phaselist[d]4818 drv = xtraclass = xtrainfo = xtrastyle = ''4819 if 'htmlclass' in dev:4820 xtraclass = dev['htmlclass']4821 if 'color' in dev:4822 xtrastyle = 'background:%s;' % dev['color']4823 if(d in sysvals.devprops):4824 name = sysvals.devprops[d].altName(d)4825 xtraclass = sysvals.devprops[d].xtraClass()4826 xtrainfo = sysvals.devprops[d].xtraInfo()4827 elif xtraclass == ' kth':4828 xtrainfo = ' kernel_thread'4829 if('drv' in dev and dev['drv']):4830 drv = ' {%s}' % dev['drv']4831 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row'])4832 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row'])4833 top = '%.3f' % (rowtop + devtl.scaleH)4834 left = '%f' % (((dev['start']-m0)*100)/mTotal)4835 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)4836 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)4837 title = name+drv+xtrainfo+length4838 if sysvals.suspendmode == 'command':4839 title += sysvals.testcommand4840 elif xtraclass == ' ps':4841 if 'suspend' in b:4842 title += 'pre_suspend_process'4843 else:4844 title += 'post_resume_process'4845 else:4846 title += b4847 devtl.html += devtl.html_device.format(dev['id'], \4848 title, left, top, '%.3f'%rowheight, width, \4849 dname+drv, xtraclass, xtrastyle)4850 if('cpuexec' in dev):4851 for t in sorted(dev['cpuexec']):4852 start, end = t4853 height = '%.3f' % (rowheight/3)4854 top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3)4855 left = '%f' % (((start-m0)*100)/mTotal)4856 width = '%f' % ((end-start)*100/mTotal)4857 color = 'rgba(255, 0, 0, %f)' % dev['cpuexec'][t]4858 devtl.html += \4859 html_cpuexec.format(left, top, height, width, color)4860 if('src' not in dev):4861 continue4862 # draw any trace events for this device4863 for e in dev['src']:4864 if e.length == 0:4865 continue4866 height = '%.3f' % devtl.rowH4867 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))4868 left = '%f' % (((e.time-m0)*100)/mTotal)4869 width = '%f' % (e.length*100/mTotal)4870 xtrastyle = ''4871 if e.color:4872 xtrastyle = 'background:%s;' % e.color4873 devtl.html += \4874 html_traceevent.format(e.title(), \4875 left, top, height, width, e.text(), '', xtrastyle)4876 # draw the time scale, try to make the number of labels readable4877 devtl.createTimeScale(m0, mMax, tTotal, dir)4878 devtl.html += '</div>\n'4879 4880 # timeline is finished4881 devtl.html += '</div>\n</div>\n'4882 4883 # draw a legend which describes the phases by color4884 if sysvals.suspendmode != 'command':4885 phasedef = testruns[-1].phasedef4886 devtl.html += '<div class="legend">\n'4887 pdelta = 100.0/len(phasedef.keys())4888 pmargin = pdelta / 4.04889 for phase in sorted(phasedef, key=lambda k:phasedef[k]['order']):4890 id, p = '', phasedef[phase]4891 for word in phase.split('_'):4892 id += word[0]4893 order = '%.2f' % ((p['order'] * pdelta) + pmargin)4894 name = phase.replace('_', ' ')4895 devtl.html += devtl.html_legend.format(order, p['color'], name, id)4896 devtl.html += '</div>\n'4897 4898 hf = open(sysvals.htmlfile, 'w')4899 addCSS(hf, sysvals, len(testruns), kerror)4900 4901 # write the device timeline4902 hf.write(devtl.html)4903 hf.write('<div id="devicedetailtitle"></div>\n')4904 hf.write('<div id="devicedetail" style="display:none;">\n')4905 # draw the colored boxes for the device detail section4906 for data in testruns:4907 hf.write('<div id="devicedetail%d">\n' % data.testnumber)4908 pscolor = 'linear-gradient(to top left, #ccc, #eee)'4909 hf.write(devtl.html_phaselet.format('pre_suspend_process', \4910 '0', '0', pscolor))4911 for b in data.sortedPhases():4912 phase = data.dmesg[b]4913 length = phase['end']-phase['start']4914 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)4915 width = '%.3f' % ((length*100.0)/tTotal)4916 hf.write(devtl.html_phaselet.format(b, left, width, \4917 data.dmesg[b]['color']))4918 hf.write(devtl.html_phaselet.format('post_resume_process', \4919 '0', '0', pscolor))4920 if sysvals.suspendmode == 'command':4921 hf.write(devtl.html_phaselet.format('cmdexec', '0', '0', pscolor))4922 hf.write('</div>\n')4923 hf.write('</div>\n')4924 4925 # write the ftrace data (callgraph)4926 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:4927 data = testruns[sysvals.cgtest]4928 else:4929 data = testruns[-1]4930 if sysvals.usecallgraph:4931 addCallgraphs(sysvals, hf, data)4932 4933 # add the test log as a hidden div4934 if sysvals.testlog and sysvals.logmsg:4935 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')4936 # add the dmesg log as a hidden div4937 if sysvals.dmesglog and sysvals.dmesgfile:4938 hf.write('<div id="dmesglog" style="display:none;">\n')4939 lf = sysvals.openlog(sysvals.dmesgfile, 'r')4940 for line in lf:4941 line = line.replace('<', '<').replace('>', '>')4942 hf.write(line)4943 lf.close()4944 hf.write('</div>\n')4945 # add the ftrace log as a hidden div4946 if sysvals.ftracelog and sysvals.ftracefile:4947 hf.write('<div id="ftracelog" style="display:none;">\n')4948 lf = sysvals.openlog(sysvals.ftracefile, 'r')4949 for line in lf:4950 hf.write(line)4951 lf.close()4952 hf.write('</div>\n')4953 4954 # write the footer and close4955 addScriptCode(hf, testruns)4956 hf.write('</body>\n</html>\n')4957 hf.close()4958 return True4959 4960def addCSS(hf, sv, testcount=1, kerror=False, extra=''):4961 kernel = sv.stamp['kernel']4962 host = sv.hostname[0].upper()+sv.hostname[1:]4963 mode = sv.suspendmode4964 if sv.suspendmode in suspendmodename:4965 mode = suspendmodename[sv.suspendmode]4966 title = host+' '+mode+' '+kernel4967 4968 # various format changes by flags4969 cgchk = 'checked'4970 cgnchk = 'not(:checked)'4971 if sv.cgexp:4972 cgchk = 'not(:checked)'4973 cgnchk = 'checked'4974 4975 hoverZ = 'z-index:8;'4976 if sv.usedevsrc:4977 hoverZ = ''4978 4979 devlistpos = 'absolute'4980 if testcount > 1:4981 devlistpos = 'relative'4982 4983 scaleTH = 204984 if kerror:4985 scaleTH = 604986 4987 # write the html header first (html head, css code, up to body start)4988 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\4989 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\4990 <title>'+title+'</title>\n\4991 <style type=\'text/css\'>\n\4992 body {overflow-y:scroll;}\n\4993 .stamp {width:100%;text-align:center;background:gray;line-height:30px;color:white;font:25px Arial;}\n\4994 .stamp.sysinfo {font:10px Arial;}\n\4995 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\4996 .callgraph article * {padding-left:28px;}\n\4997 h1 {color:black;font:bold 30px Times;}\n\4998 t0 {color:black;font:bold 30px Times;}\n\4999 t1 {color:black;font:30px Times;}\n\5000 t2 {color:black;font:25px Times;}\n\5001 t3 {color:black;font:20px Times;white-space:nowrap;}\n\5002 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\5003 cS {font:bold 13px Times;}\n\5004 table {width:100%;}\n\5005 .gray {background:rgba(80,80,80,0.1);}\n\5006 .green {background:rgba(204,255,204,0.4);}\n\5007 .purple {background:rgba(128,0,128,0.2);}\n\5008 .yellow {background:rgba(255,255,204,0.4);}\n\5009 .blue {background:rgba(169,208,245,0.4);}\n\5010 .time1 {font:22px Arial;border:1px solid;}\n\5011 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\5012 .testfail {font:bold 22px Arial;color:red;border:1px dashed;}\n\5013 td {text-align:center;}\n\5014 r {color:#500000;font:15px Tahoma;}\n\5015 n {color:#505050;font:15px Tahoma;}\n\5016 .tdhl {color:red;}\n\5017 .hide {display:none;}\n\5018 .pf {display:none;}\n\5019 .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\5020 .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\5021 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\5022 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\5023 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\5024 .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\5025 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\5026 .thread:hover {background:white;border:1px solid red;'+hoverZ+'}\n\5027 .thread.sec,.thread.sec:hover {background:black;border:0;color:white;line-height:15px;font-size:10px;}\n\5028 .hover {background:white;border:1px solid red;'+hoverZ+'}\n\5029 .hover.sync {background:white;}\n\5030 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background:white;}\n\5031 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\5032 .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\5033 .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\5034 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\5035 .phaselet {float:left;overflow:hidden;border:0px;text-align:center;min-height:100px;font-size:24px;}\n\5036 .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\5037 .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\5038 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\5039 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\5040 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\5041 .btnfmt {position:relative;float:right;height:25px;width:auto;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\5042 .devlist {position:'+devlistpos+';width:190px;}\n\5043 a:link {color:white;text-decoration:none;}\n\5044 a:visited {color:white;}\n\5045 a:hover {color:white;}\n\5046 a:active {color:white;}\n\5047 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\5048 #devicedetail {min-height:100px;box-shadow:5px 5px 20px black;}\n\5049 .tblock {position:absolute;height:100%;background:#ddd;}\n\5050 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\5051 .bg {z-index:1;}\n\5052'+extra+'\5053 </style>\n</head>\n<body>\n'5054 hf.write(html_header)5055 5056# Function: addScriptCode5057# Description:5058# Adds the javascript code to the output html5059# Arguments:5060# hf: the open html file pointer5061# testruns: array of Data objects from parseKernelLog or parseTraceLog5062def addScriptCode(hf, testruns):5063 t0 = testruns[0].start * 10005064 tMax = testruns[-1].end * 10005065 hf.write('<script type="text/javascript">\n');5066 # create an array in javascript memory with the device details5067 detail = ' var devtable = [];\n'5068 for data in testruns:5069 topo = data.deviceTopology()5070 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)5071 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)5072 # add the code which will manipulate the data in the browser5073 hf.write(detail);5074 script_code = r""" var resolution = -1;5075 var dragval = [0, 0];5076 function redrawTimescale(t0, tMax, tS) {5077 var rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">';5078 var tTotal = tMax - t0;5079 var list = document.getElementsByClassName("tblock");5080 for (var i = 0; i < list.length; i++) {5081 var timescale = list[i].getElementsByClassName("timescale")[0];5082 var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);5083 var mTotal = tTotal*parseFloat(list[i].style.width)/100;5084 var mMax = m0 + mTotal;5085 var html = "";5086 var divTotal = Math.floor(mTotal/tS) + 1;5087 if(divTotal > 1000) continue;5088 var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;5089 var pos = 0.0, val = 0.0;5090 for (var j = 0; j < divTotal; j++) {5091 var htmlline = "";5092 var mode = list[i].id[5];5093 if(mode == "s") {5094 pos = 100 - (((j)*tS*100)/mTotal) - divEdge;5095 val = (j-divTotal+1)*tS;5096 if(j == divTotal - 1)5097 htmlline = '<div class="t" style="right:'+pos+'%"><cS>S→</cS></div>';5098 else5099 htmlline = '<div class="t" style="right:'+pos+'%">'+val+'ms</div>';5100 } else {5101 pos = 100 - (((j)*tS*100)/mTotal);5102 val = (j)*tS;5103 htmlline = '<div class="t" style="right:'+pos+'%">'+val+'ms</div>';5104 if(j == 0)5105 if(mode == "r")5106 htmlline = rline+"<cS>←R</cS></div>";5107 else5108 htmlline = rline+"<cS>0ms</div>";5109 }5110 html += htmlline;5111 }5112 timescale.innerHTML = html;5113 }5114 }5115 function zoomTimeline() {5116 var dmesg = document.getElementById("dmesg");5117 var zoombox = document.getElementById("dmesgzoombox");5118 var left = zoombox.scrollLeft;5119 var val = parseFloat(dmesg.style.width);5120 var newval = 100;5121 var sh = window.outerWidth / 2;5122 if(this.id == "zoomin") {5123 newval = val * 1.2;5124 if(newval > 910034) newval = 910034;5125 dmesg.style.width = newval+"%";5126 zoombox.scrollLeft = ((left + sh) * newval / val) - sh;5127 } else if (this.id == "zoomout") {5128 newval = val / 1.2;5129 if(newval < 100) newval = 100;5130 dmesg.style.width = newval+"%";5131 zoombox.scrollLeft = ((left + sh) * newval / val) - sh;5132 } else {5133 zoombox.scrollLeft = 0;5134 dmesg.style.width = "100%";5135 }5136 var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];5137 var t0 = bounds[0];5138 var tMax = bounds[1];5139 var tTotal = tMax - t0;5140 var wTotal = tTotal * 100.0 / newval;5141 var idx = 7*window.innerWidth/1100;5142 for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);5143 if(i >= tS.length) i = tS.length - 1;5144 if(tS[i] == resolution) return;5145 resolution = tS[i];5146 redrawTimescale(t0, tMax, tS[i]);5147 }5148 function deviceName(title) {5149 var name = title.slice(0, title.indexOf(" ("));5150 return name;5151 }5152 function deviceHover() {5153 var name = deviceName(this.title);5154 var dmesg = document.getElementById("dmesg");5155 var dev = dmesg.getElementsByClassName("thread");5156 var cpu = -1;5157 if(name.match("CPU_ON\[[0-9]*\]"))5158 cpu = parseInt(name.slice(7));5159 else if(name.match("CPU_OFF\[[0-9]*\]"))5160 cpu = parseInt(name.slice(8));5161 for (var i = 0; i < dev.length; i++) {5162 dname = deviceName(dev[i].title);5163 var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));5164 if((cpu >= 0 && dname.match("CPU_O[NF]*\\[*"+cpu+"\\]")) ||5165 (name == dname))5166 {5167 dev[i].className = "hover "+cname;5168 } else {5169 dev[i].className = cname;5170 }5171 }5172 }5173 function deviceUnhover() {5174 var dmesg = document.getElementById("dmesg");5175 var dev = dmesg.getElementsByClassName("thread");5176 for (var i = 0; i < dev.length; i++) {5177 dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));5178 }5179 }5180 function deviceTitle(title, total, cpu) {5181 var prefix = "Total";5182 if(total.length > 3) {5183 prefix = "Average";5184 total[1] = (total[1]+total[3])/2;5185 total[2] = (total[2]+total[4])/2;5186 }5187 var devtitle = document.getElementById("devicedetailtitle");5188 var name = deviceName(title);5189 if(cpu >= 0) name = "CPU"+cpu;5190 var driver = "";5191 var tS = "<t2>(</t2>";5192 var tR = "<t2>)</t2>";5193 if(total[1] > 0)5194 tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";5195 if(total[2] > 0)5196 tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";5197 var s = title.indexOf("{");5198 var e = title.indexOf("}");5199 if((s >= 0) && (e >= 0))5200 driver = title.slice(s+1, e) + " <t1>@</t1> ";5201 if(total[1] > 0 && total[2] > 0)5202 devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;5203 else5204 devtitle.innerHTML = "<t0>"+title+"</t0>";5205 return name;5206 }5207 function deviceDetail() {5208 var devinfo = document.getElementById("devicedetail");5209 devinfo.style.display = "block";5210 var name = deviceName(this.title);5211 var cpu = -1;5212 if(name.match("CPU_ON\[[0-9]*\]"))5213 cpu = parseInt(name.slice(7));5214 else if(name.match("CPU_OFF\[[0-9]*\]"))5215 cpu = parseInt(name.slice(8));5216 var dmesg = document.getElementById("dmesg");5217 var dev = dmesg.getElementsByClassName("thread");5218 var idlist = [];5219 var pdata = [[]];5220 if(document.getElementById("devicedetail1"))5221 pdata = [[], []];5222 var pd = pdata[0];5223 var total = [0.0, 0.0, 0.0];5224 for (var i = 0; i < dev.length; i++) {5225 dname = deviceName(dev[i].title);5226 if((cpu >= 0 && dname.match("CPU_O[NF]*\\[*"+cpu+"\\]")) ||5227 (name == dname))5228 {5229 idlist[idlist.length] = dev[i].id;5230 var tidx = 1;5231 if(dev[i].id[0] == "a") {5232 pd = pdata[0];5233 } else {5234 if(pdata.length == 1) pdata[1] = [];5235 if(total.length == 3) total[3]=total[4]=0.0;5236 pd = pdata[1];5237 tidx = 3;5238 }5239 var info = dev[i].title.split(" ");5240 var pname = info[info.length-1];5241 pd[pname] = parseFloat(info[info.length-3].slice(1));5242 total[0] += pd[pname];5243 if(pname.indexOf("suspend") >= 0)5244 total[tidx] += pd[pname];5245 else5246 total[tidx+1] += pd[pname];5247 }5248 }5249 var devname = deviceTitle(this.title, total, cpu);5250 var left = 0.0;5251 for (var t = 0; t < pdata.length; t++) {5252 pd = pdata[t];5253 devinfo = document.getElementById("devicedetail"+t);5254 var phases = devinfo.getElementsByClassName("phaselet");5255 for (var i = 0; i < phases.length; i++) {5256 if(phases[i].id in pd) {5257 var w = 100.0*pd[phases[i].id]/total[0];5258 var fs = 32;5259 if(w < 8) fs = 4*w | 0;5260 var fs2 = fs*3/4;5261 phases[i].style.width = w+"%";5262 phases[i].style.left = left+"%";5263 phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";5264 left += w;5265 var time = "<t4 style=\"font-size:"+fs+"px\">"+pd[phases[i].id]+" ms<br></t4>";5266 var pname = "<t3 style=\"font-size:"+fs2+"px\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";5267 phases[i].innerHTML = time+pname;5268 } else {5269 phases[i].style.width = "0%";5270 phases[i].style.left = left+"%";5271 }5272 }5273 }5274 if(typeof devstats !== 'undefined')5275 callDetail(this.id, this.title);5276 var cglist = document.getElementById("callgraphs");5277 if(!cglist) return;5278 var cg = cglist.getElementsByClassName("atop");5279 if(cg.length < 10) return;5280 for (var i = 0; i < cg.length; i++) {5281 cgid = cg[i].id.split("x")[0]5282 if(idlist.indexOf(cgid) >= 0) {5283 cg[i].style.display = "block";5284 } else {5285 cg[i].style.display = "none";5286 }5287 }5288 }5289 function callDetail(devid, devtitle) {5290 if(!(devid in devstats) || devstats[devid].length < 1)5291 return;5292 var list = devstats[devid];5293 var tmp = devtitle.split(" ");5294 var name = tmp[0], phase = tmp[tmp.length-1];5295 var dd = document.getElementById(phase);5296 var total = parseFloat(tmp[1].slice(1));5297 var mlist = [];5298 var maxlen = 0;5299 var info = []5300 for(var i in list) {5301 if(list[i][0] == "@") {5302 info = list[i].split("|");5303 continue;5304 }5305 var tmp = list[i].split("|");5306 var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]);5307 var p = (t*100.0/total).toFixed(2);5308 mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"];5309 if(f.length > maxlen)5310 maxlen = f.length;5311 }5312 var pad = 5;5313 if(mlist.length == 0) pad = 30;5314 var html = '<div style="padding-top:'+pad+'px"><t3> <b>'+name+':</b>';5315 if(info.length > 2)5316 html += " start=<b>"+info[1]+"</b>, end=<b>"+info[2]+"</b>";5317 if(info.length > 3)5318 html += ", length<i>(w/o overhead)</i>=<b>"+info[3]+" ms</b>";5319 if(info.length > 4)5320 html += ", return=<b>"+info[4]+"</b>";5321 html += "</t3></div>";5322 if(mlist.length > 0) {5323 html += '<table class=fstat style="padding-top:'+(maxlen*5)+'px;"><tr><th>Function</th>';5324 for(var i in mlist)5325 html += "<td class=vt>"+mlist[i][0]+"</td>";5326 html += "</tr><tr><th>Calls</th>";5327 for(var i in mlist)5328 html += "<td>"+mlist[i][1]+"</td>";5329 html += "</tr><tr><th>Time(ms)</th>";5330 for(var i in mlist)5331 html += "<td>"+mlist[i][2]+"</td>";5332 html += "</tr><tr><th>Percent</th>";5333 for(var i in mlist)5334 html += "<td>"+mlist[i][3]+"</td>";5335 html += "</tr></table>";5336 }5337 dd.innerHTML = html;5338 var height = (maxlen*5)+100;5339 dd.style.height = height+"px";5340 document.getElementById("devicedetail").style.height = height+"px";5341 }5342 function callSelect() {5343 var cglist = document.getElementById("callgraphs");5344 if(!cglist) return;5345 var cg = cglist.getElementsByClassName("atop");5346 for (var i = 0; i < cg.length; i++) {5347 if(this.id == cg[i].id) {5348 cg[i].style.display = "block";5349 } else {5350 cg[i].style.display = "none";5351 }5352 }5353 }5354 function devListWindow(e) {5355 var win = window.open();5356 var html = "<title>"+e.target.innerHTML+"</title>"+5357 "<style type=\"text/css\">"+5358 " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+5359 "</style>"5360 var dt = devtable[0];5361 if(e.target.id != "devlist1")5362 dt = devtable[1];5363 win.document.write(html+dt);5364 }5365 function errWindow() {5366 var range = this.id.split("_");5367 var idx1 = parseInt(range[0]);5368 var idx2 = parseInt(range[1]);5369 var win = window.open();5370 var log = document.getElementById("dmesglog");5371 var title = "<title>dmesg log</title>";5372 var text = log.innerHTML.split("\n");5373 var html = "";5374 for(var i = 0; i < text.length; i++) {5375 if(i == idx1) {5376 html += "<e id=target>"+text[i]+"</e>\n";5377 } else if(i > idx1 && i <= idx2) {5378 html += "<e>"+text[i]+"</e>\n";5379 } else {5380 html += text[i]+"\n";5381 }5382 }5383 win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>");5384 win.location.hash = "#target";5385 win.document.close();5386 }5387 function logWindow(e) {5388 var name = e.target.id.slice(4);5389 var win = window.open();5390 var log = document.getElementById(name+"log");5391 var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";5392 win.document.write(title+"<pre>"+log.innerHTML+"</pre>");5393 win.document.close();5394 }5395 function onMouseDown(e) {5396 dragval[0] = e.clientX;5397 dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;5398 document.onmousemove = onMouseMove;5399 }5400 function onMouseMove(e) {5401 var zoombox = document.getElementById("dmesgzoombox");5402 zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;5403 }5404 function onMouseUp(e) {5405 document.onmousemove = null;5406 }5407 function onKeyPress(e) {5408 var c = e.charCode;5409 if(c != 42 && c != 43 && c != 45) return;5410 var click = document.createEvent("Events");5411 click.initEvent("click", true, false);5412 if(c == 43)5413 document.getElementById("zoomin").dispatchEvent(click);5414 else if(c == 45)5415 document.getElementById("zoomout").dispatchEvent(click);5416 else if(c == 42)5417 document.getElementById("zoomdef").dispatchEvent(click);5418 }5419 window.addEventListener("resize", function () {zoomTimeline();});5420 window.addEventListener("load", function () {5421 var dmesg = document.getElementById("dmesg");5422 dmesg.style.width = "100%"5423 dmesg.onmousedown = onMouseDown;5424 document.onmouseup = onMouseUp;5425 document.onkeypress = onKeyPress;5426 document.getElementById("zoomin").onclick = zoomTimeline;5427 document.getElementById("zoomout").onclick = zoomTimeline;5428 document.getElementById("zoomdef").onclick = zoomTimeline;5429 var list = document.getElementsByClassName("err");5430 for (var i = 0; i < list.length; i++)5431 list[i].onclick = errWindow;5432 var list = document.getElementsByClassName("logbtn");5433 for (var i = 0; i < list.length; i++)5434 list[i].onclick = logWindow;5435 list = document.getElementsByClassName("devlist");5436 for (var i = 0; i < list.length; i++)5437 list[i].onclick = devListWindow;5438 var dev = dmesg.getElementsByClassName("thread");5439 for (var i = 0; i < dev.length; i++) {5440 dev[i].onclick = deviceDetail;5441 dev[i].onmouseover = deviceHover;5442 dev[i].onmouseout = deviceUnhover;5443 }5444 var dev = dmesg.getElementsByClassName("srccall");5445 for (var i = 0; i < dev.length; i++)5446 dev[i].onclick = callSelect;5447 zoomTimeline();5448 });5449</script> """5450 hf.write(script_code);5451 5452# Function: executeSuspend5453# Description:5454# Execute system suspend through the sysfs interface, then copy the output5455# dmesg and ftrace files to the test output directory.5456def executeSuspend(quiet=False):5457 sv, tp, pm = sysvals, sysvals.tpath, ProcessMonitor()5458 if sv.wifi:5459 wifi = sv.checkWifi()5460 sv.dlog('wifi check, connected device is "%s"' % wifi)5461 testdata = []5462 # run these commands to prepare the system for suspend5463 if sv.display:5464 if not quiet:5465 pprint('SET DISPLAY TO %s' % sv.display.upper())5466 ret = sv.displayControl(sv.display)5467 sv.dlog('xset display %s, ret = %d' % (sv.display, ret))5468 time.sleep(1)5469 if sv.sync:5470 if not quiet:5471 pprint('SYNCING FILESYSTEMS')5472 sv.dlog('syncing filesystems')5473 call('sync', shell=True)5474 sv.dlog('read dmesg')5475 sv.initdmesg()5476 sv.dlog('cmdinfo before')5477 sv.cmdinfo(True)5478 sv.start(pm)5479 # execute however many s/r runs requested5480 for count in range(1,sv.execcount+1):5481 # x2delay in between test runs5482 if(count > 1 and sv.x2delay > 0):5483 sv.fsetVal('WAIT %d' % sv.x2delay, 'trace_marker')5484 time.sleep(sv.x2delay/1000.0)5485 sv.fsetVal('WAIT END', 'trace_marker')5486 # start message5487 if sv.testcommand != '':5488 pprint('COMMAND START')5489 else:5490 if(sv.rtcwake):5491 pprint('SUSPEND START')5492 else:5493 pprint('SUSPEND START (press a key to resume)')5494 # set rtcwake5495 if(sv.rtcwake):5496 if not quiet:5497 pprint('will issue an rtcwake in %d seconds' % sv.rtcwaketime)5498 sv.dlog('enable RTC wake alarm')5499 sv.rtcWakeAlarmOn()5500 # start of suspend trace marker5501 sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker')5502 # predelay delay5503 if(count == 1 and sv.predelay > 0):5504 sv.fsetVal('WAIT %d' % sv.predelay, 'trace_marker')5505 time.sleep(sv.predelay/1000.0)5506 sv.fsetVal('WAIT END', 'trace_marker')5507 # initiate suspend or command5508 sv.dlog('system executing a suspend')5509 tdata = {'error': ''}5510 if sv.testcommand != '':5511 res = call(sv.testcommand+' 2>&1', shell=True);5512 if res != 0:5513 tdata['error'] = 'cmd returned %d' % res5514 else:5515 s0ixready = sv.s0ixSupport()5516 mode = sv.suspendmode5517 if sv.memmode and os.path.exists(sv.mempowerfile):5518 mode = 'mem'5519 sv.testVal(sv.mempowerfile, 'radio', sv.memmode)5520 if sv.diskmode and os.path.exists(sv.diskpowerfile):5521 mode = 'disk'5522 sv.testVal(sv.diskpowerfile, 'radio', sv.diskmode)5523 if sv.acpidebug:5524 sv.testVal(sv.acpipath, 'acpi', '0xe')5525 if ((mode == 'freeze') or (sv.memmode == 's2idle')) \5526 and sv.haveTurbostat():5527 # execution will pause here5528 retval, turbo = sv.turbostat(s0ixready)5529 if retval != 0:5530 tdata['error'] ='turbostat returned %d' % retval5531 if turbo:5532 tdata['turbo'] = turbo5533 else:5534 pf = open(sv.powerfile, 'w')5535 pf.write(mode)5536 # execution will pause here5537 try:5538 pf.flush()5539 pf.close()5540 except Exception as e:5541 tdata['error'] = str(e)5542 sv.fsetVal('CMD COMPLETE', 'trace_marker')5543 sv.dlog('system returned')5544 # reset everything5545 sv.testVal('restoreall')5546 if(sv.rtcwake):5547 sv.dlog('disable RTC wake alarm')5548 sv.rtcWakeAlarmOff()5549 # postdelay delay5550 if(count == sv.execcount and sv.postdelay > 0):5551 sv.fsetVal('WAIT %d' % sv.postdelay, 'trace_marker')5552 time.sleep(sv.postdelay/1000.0)5553 sv.fsetVal('WAIT END', 'trace_marker')5554 # return from suspend5555 pprint('RESUME COMPLETE')5556 if(count < sv.execcount):5557 sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker')5558 elif(not sv.wifitrace):5559 sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker')5560 sv.stop(pm)5561 if sv.wifi and wifi:5562 tdata['wifi'] = sv.pollWifi(wifi)5563 sv.dlog('wifi check, %s' % tdata['wifi'])5564 if(count == sv.execcount and sv.wifitrace):5565 sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker')5566 sv.stop(pm)5567 if sv.netfix:5568 tdata['netfix'] = sv.netfixon()5569 sv.dlog('netfix, %s' % tdata['netfix'])5570 if(sv.suspendmode == 'mem' or sv.suspendmode == 'command'):5571 sv.dlog('read the ACPI FPDT')5572 tdata['fw'] = getFPDT(False)5573 testdata.append(tdata)5574 sv.dlog('cmdinfo after')5575 cmdafter = sv.cmdinfo(False)5576 # grab a copy of the dmesg output5577 if not quiet:5578 pprint('CAPTURING DMESG')5579 sv.getdmesg(testdata)5580 # grab a copy of the ftrace output5581 if sv.useftrace:5582 if not quiet:5583 pprint('CAPTURING TRACE')5584 op = sv.writeDatafileHeader(sv.ftracefile, testdata)5585 fp = open(tp+'trace', 'rb')5586 op.write(ascii(fp.read()))5587 op.close()5588 sv.fsetVal('', 'trace')5589 sv.platforminfo(cmdafter)5590 5591def readFile(file):5592 if os.path.islink(file):5593 return os.readlink(file).split('/')[-1]5594 else:5595 return sysvals.getVal(file).strip()5596 5597# Function: ms2nice5598# Description:5599# Print out a very concise time string in minutes and seconds5600# Output:5601# The time string, e.g. "1901m16s"5602def ms2nice(val):5603 val = int(val)5604 h = val // 36000005605 m = (val // 60000) % 605606 s = (val // 1000) % 605607 if h > 0:5608 return '%d:%02d:%02d' % (h, m, s)5609 if m > 0:5610 return '%02d:%02d' % (m, s)5611 return '%ds' % s5612 5613def yesno(val):5614 list = {'enabled':'A', 'disabled':'S', 'auto':'E', 'on':'D',5615 'active':'A', 'suspended':'S', 'suspending':'S'}5616 if val not in list:5617 return ' '5618 return list[val]5619 5620# Function: deviceInfo5621# Description:5622# Detect all the USB hosts and devices currently connected and add5623# a list of USB device names to sysvals for better timeline readability5624def deviceInfo(output=''):5625 if not output:5626 pprint('LEGEND\n'\5627 '---------------------------------------------------------------------------------------------\n'\5628 ' A = async/sync PM queue (A/S) C = runtime active children\n'\5629 ' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)\n'\5630 ' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)\n'\5631 ' U = runtime usage count\n'\5632 '---------------------------------------------------------------------------------------------\n'\5633 'DEVICE NAME A R S U C rACTIVE rSUSPEND\n'\5634 '---------------------------------------------------------------------------------------------')5635 5636 res = []5637 tgtval = 'runtime_status'5638 lines = dict()5639 for dirname, dirnames, filenames in os.walk('/sys/devices'):5640 if(not re.match(r'.*/power', dirname) or5641 'control' not in filenames or5642 tgtval not in filenames):5643 continue5644 name = ''5645 dirname = dirname[:-6]5646 device = dirname.split('/')[-1]5647 power = dict()5648 power[tgtval] = readFile('%s/power/%s' % (dirname, tgtval))5649 # only list devices which support runtime suspend5650 if power[tgtval] not in ['active', 'suspended', 'suspending']:5651 continue5652 for i in ['product', 'driver', 'subsystem']:5653 file = '%s/%s' % (dirname, i)5654 if os.path.exists(file):5655 name = readFile(file)5656 break5657 for i in ['async', 'control', 'runtime_status', 'runtime_usage',5658 'runtime_active_kids', 'runtime_active_time',5659 'runtime_suspended_time']:5660 if i in filenames:5661 power[i] = readFile('%s/power/%s' % (dirname, i))5662 if output:5663 if power['control'] == output:5664 res.append('%s/power/control' % dirname)5665 continue5666 lines[dirname] = '%-26s %-26s %1s %1s %1s %1s %1s %10s %10s' % \5667 (device[:26], name[:26],5668 yesno(power['async']), \5669 yesno(power['control']), \5670 yesno(power['runtime_status']), \5671 power['runtime_usage'], \5672 power['runtime_active_kids'], \5673 ms2nice(power['runtime_active_time']), \5674 ms2nice(power['runtime_suspended_time']))5675 for i in sorted(lines):5676 print(lines[i])5677 return res5678 5679# Function: getModes5680# Description:5681# Determine the supported power modes on this system5682# Output:5683# A string list of the available modes5684def getModes():5685 modes = []5686 if(os.path.exists(sysvals.powerfile)):5687 fp = open(sysvals.powerfile, 'r')5688 modes = fp.read().split()5689 fp.close()5690 if(os.path.exists(sysvals.mempowerfile)):5691 deep = False5692 fp = open(sysvals.mempowerfile, 'r')5693 for m in fp.read().split():5694 memmode = m.strip('[]')5695 if memmode == 'deep':5696 deep = True5697 else:5698 modes.append('mem-%s' % memmode)5699 fp.close()5700 if 'mem' in modes and not deep:5701 modes.remove('mem')5702 if('disk' in modes and os.path.exists(sysvals.diskpowerfile)):5703 fp = open(sysvals.diskpowerfile, 'r')5704 for m in fp.read().split():5705 modes.append('disk-%s' % m.strip('[]'))5706 fp.close()5707 return modes5708 5709def dmidecode_backup(out, fatal=False):5710 cpath, spath, info = '/proc/cpuinfo', '/sys/class/dmi/id', {5711 'bios-vendor': 'bios_vendor',5712 'bios-version': 'bios_version',5713 'bios-release-date': 'bios_date',5714 'system-manufacturer': 'sys_vendor',5715 'system-product-name': 'product_name',5716 'system-version': 'product_version',5717 'system-serial-number': 'product_serial',5718 'baseboard-manufacturer': 'board_vendor',5719 'baseboard-product-name': 'board_name',5720 'baseboard-version': 'board_version',5721 'baseboard-serial-number': 'board_serial',5722 'chassis-manufacturer': 'chassis_vendor',5723 'chassis-version': 'chassis_version',5724 'chassis-serial-number': 'chassis_serial',5725 }5726 for key in info:5727 if key not in out:5728 val = sysvals.getVal(os.path.join(spath, info[key])).strip()5729 if val and val.lower() != 'to be filled by o.e.m.':5730 out[key] = val5731 if 'processor-version' not in out and os.path.exists(cpath):5732 with open(cpath, 'r') as fp:5733 for line in fp:5734 m = re.match(r'^model\s*name\s*\:\s*(?P<c>.*)', line)5735 if m:5736 out['processor-version'] = m.group('c').strip()5737 break5738 if fatal and len(out) < 1:5739 doError('dmidecode failed to get info from %s or %s' % \5740 (sysvals.mempath, spath))5741 return out5742 5743# Function: dmidecode5744# Description:5745# Read the bios tables and pull out system info5746# Arguments:5747# mempath: /dev/mem or custom mem path5748# fatal: True to exit on error, False to return empty dict5749# Output:5750# A dict object with all available key/values5751def dmidecode(mempath, fatal=False):5752 out = dict()5753 if(not (os.path.exists(mempath) and os.access(mempath, os.R_OK))):5754 return dmidecode_backup(out, fatal)5755 5756 # the list of values to retrieve, with hardcoded (type, idx)5757 info = {5758 'bios-vendor': (0, 4),5759 'bios-version': (0, 5),5760 'bios-release-date': (0, 8),5761 'system-manufacturer': (1, 4),5762 'system-product-name': (1, 5),5763 'system-version': (1, 6),5764 'system-serial-number': (1, 7),5765 'baseboard-manufacturer': (2, 4),5766 'baseboard-product-name': (2, 5),5767 'baseboard-version': (2, 6),5768 'baseboard-serial-number': (2, 7),5769 'chassis-manufacturer': (3, 4),5770 'chassis-version': (3, 6),5771 'chassis-serial-number': (3, 7),5772 'processor-manufacturer': (4, 7),5773 'processor-version': (4, 16),5774 }5775 5776 # by default use legacy scan, but try to use EFI first5777 memaddr, memsize = 0xf0000, 0x100005778 for ep in ['/sys/firmware/efi/systab', '/proc/efi/systab']:5779 if not os.path.exists(ep) or not os.access(ep, os.R_OK):5780 continue5781 fp = open(ep, 'r')5782 buf = fp.read()5783 fp.close()5784 i = buf.find('SMBIOS=')5785 if i >= 0:5786 try:5787 memaddr = int(buf[i+7:], 16)5788 memsize = 0x205789 except:5790 continue5791 5792 # read in the memory for scanning5793 try:5794 fp = open(mempath, 'rb')5795 fp.seek(memaddr)5796 buf = fp.read(memsize)5797 except:5798 return dmidecode_backup(out, fatal)5799 fp.close()5800 5801 # search for either an SM table or DMI table5802 i = base = length = num = 05803 while(i < memsize):5804 if buf[i:i+4] == b'_SM_' and i < memsize - 16:5805 length = struct.unpack('H', buf[i+22:i+24])[0]5806 base, num = struct.unpack('IH', buf[i+24:i+30])5807 break5808 elif buf[i:i+5] == b'_DMI_':5809 length = struct.unpack('H', buf[i+6:i+8])[0]5810 base, num = struct.unpack('IH', buf[i+8:i+14])5811 break5812 i += 165813 if base == 0 and length == 0 and num == 0:5814 return dmidecode_backup(out, fatal)5815 5816 # read in the SM or DMI table5817 try:5818 fp = open(mempath, 'rb')5819 fp.seek(base)5820 buf = fp.read(length)5821 except:5822 return dmidecode_backup(out, fatal)5823 fp.close()5824 5825 # scan the table for the values we want5826 count = i = 05827 while(count < num and i <= len(buf) - 4):5828 type, size, handle = struct.unpack('BBH', buf[i:i+4])5829 n = i + size5830 while n < len(buf) - 1:5831 if 0 == struct.unpack('H', buf[n:n+2])[0]:5832 break5833 n += 15834 data = buf[i+size:n+2].split(b'\0')5835 for name in info:5836 itype, idxadr = info[name]5837 if itype == type:5838 idx = struct.unpack('B', buf[i+idxadr:i+idxadr+1])[0]5839 if idx > 0 and idx < len(data) - 1:5840 s = data[idx-1].decode('utf-8')5841 if s.strip() and s.strip().lower() != 'to be filled by o.e.m.':5842 out[name] = s5843 i = n + 25844 count += 15845 return out5846 5847# Function: getFPDT5848# Description:5849# Read the acpi bios tables and pull out FPDT, the firmware data5850# Arguments:5851# output: True to output the info to stdout, False otherwise5852def getFPDT(output):5853 rectype = {}5854 rectype[0] = 'Firmware Basic Boot Performance Record'5855 rectype[1] = 'S3 Performance Table Record'5856 prectype = {}5857 prectype[0] = 'Basic S3 Resume Performance Record'5858 prectype[1] = 'Basic S3 Suspend Performance Record'5859 5860 sysvals.rootCheck(True)5861 if(not os.path.exists(sysvals.fpdtpath)):5862 if(output):5863 doError('file does not exist: %s' % sysvals.fpdtpath)5864 return False5865 if(not os.access(sysvals.fpdtpath, os.R_OK)):5866 if(output):5867 doError('file is not readable: %s' % sysvals.fpdtpath)5868 return False5869 if(not os.path.exists(sysvals.mempath)):5870 if(output):5871 doError('file does not exist: %s' % sysvals.mempath)5872 return False5873 if(not os.access(sysvals.mempath, os.R_OK)):5874 if(output):5875 doError('file is not readable: %s' % sysvals.mempath)5876 return False5877 5878 fp = open(sysvals.fpdtpath, 'rb')5879 buf = fp.read()5880 fp.close()5881 5882 if(len(buf) < 36):5883 if(output):5884 doError('Invalid FPDT table data, should '+\5885 'be at least 36 bytes')5886 return False5887 5888 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])5889 if(output):5890 pprint('\n'\5891 'Firmware Performance Data Table (%s)\n'\5892 ' Signature : %s\n'\5893 ' Table Length : %u\n'\5894 ' Revision : %u\n'\5895 ' Checksum : 0x%x\n'\5896 ' OEM ID : %s\n'\5897 ' OEM Table ID : %s\n'\5898 ' OEM Revision : %u\n'\5899 ' Creator ID : %s\n'\5900 ' Creator Revision : 0x%x\n'\5901 '' % (ascii(table[0]), ascii(table[0]), table[1], table[2],5902 table[3], ascii(table[4]), ascii(table[5]), table[6],5903 ascii(table[7]), table[8]))5904 5905 if(table[0] != b'FPDT'):5906 if(output):5907 doError('Invalid FPDT table')5908 return False5909 if(len(buf) <= 36):5910 return False5911 i = 05912 fwData = [0, 0]5913 records = buf[36:]5914 try:5915 fp = open(sysvals.mempath, 'rb')5916 except:5917 pprint('WARNING: /dev/mem is not readable, ignoring the FPDT data')5918 return False5919 while(i < len(records)):5920 header = struct.unpack('HBB', records[i:i+4])5921 if(header[0] not in rectype):5922 i += header[1]5923 continue5924 if(header[1] != 16):5925 i += header[1]5926 continue5927 addr = struct.unpack('Q', records[i+8:i+16])[0]5928 try:5929 fp.seek(addr)5930 first = fp.read(8)5931 except:5932 if(output):5933 pprint('Bad address 0x%x in %s' % (addr, sysvals.mempath))5934 return [0, 0]5935 rechead = struct.unpack('4sI', first)5936 recdata = fp.read(rechead[1]-8)5937 if(rechead[0] == b'FBPT'):5938 record = struct.unpack('HBBIQQQQQ', recdata[:48])5939 if(output):5940 pprint('%s (%s)\n'\5941 ' Reset END : %u ns\n'\5942 ' OS Loader LoadImage Start : %u ns\n'\5943 ' OS Loader StartImage Start : %u ns\n'\5944 ' ExitBootServices Entry : %u ns\n'\5945 ' ExitBootServices Exit : %u ns'\5946 '' % (rectype[header[0]], ascii(rechead[0]), record[4], record[5],5947 record[6], record[7], record[8]))5948 elif(rechead[0] == b'S3PT'):5949 if(output):5950 pprint('%s (%s)' % (rectype[header[0]], ascii(rechead[0])))5951 j = 05952 while(j < len(recdata)):5953 prechead = struct.unpack('HBB', recdata[j:j+4])5954 if(prechead[0] not in prectype):5955 continue5956 if(prechead[0] == 0):5957 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])5958 fwData[1] = record[2]5959 if(output):5960 pprint(' %s\n'\5961 ' Resume Count : %u\n'\5962 ' FullResume : %u ns\n'\5963 ' AverageResume : %u ns'\5964 '' % (prectype[prechead[0]], record[1],5965 record[2], record[3]))5966 elif(prechead[0] == 1):5967 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])5968 fwData[0] = record[1] - record[0]5969 if(output):5970 pprint(' %s\n'\5971 ' SuspendStart : %u ns\n'\5972 ' SuspendEnd : %u ns\n'\5973 ' SuspendTime : %u ns'\5974 '' % (prectype[prechead[0]], record[0],5975 record[1], fwData[0]))5976 5977 j += prechead[1]5978 if(output):5979 pprint('')5980 i += header[1]5981 fp.close()5982 return fwData5983 5984# Function: statusCheck5985# Description:5986# Verify that the requested command and options will work, and5987# print the results to the terminal5988# Output:5989# True if the test will work, False if not5990def statusCheck(probecheck=False):5991 status = ''5992 5993 pprint('Checking this system (%s)...' % platform.node())5994 5995 # check we have root access5996 res = sysvals.colorText('NO (No features of this tool will work!)')5997 if(sysvals.rootCheck(False)):5998 res = 'YES'5999 pprint(' have root access: %s' % res)6000 if(res != 'YES'):6001 pprint(' Try running this script with sudo')6002 return 'missing root access'6003 6004 # check sysfs is mounted6005 res = sysvals.colorText('NO (No features of this tool will work!)')6006 if(os.path.exists(sysvals.powerfile)):6007 res = 'YES'6008 pprint(' is sysfs mounted: %s' % res)6009 if(res != 'YES'):6010 return 'sysfs is missing'6011 6012 # check target mode is a valid mode6013 if sysvals.suspendmode != 'command':6014 res = sysvals.colorText('NO')6015 modes = getModes()6016 if(sysvals.suspendmode in modes):6017 res = 'YES'6018 else:6019 status = '%s mode is not supported' % sysvals.suspendmode6020 pprint(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))6021 if(res == 'NO'):6022 pprint(' valid power modes are: %s' % modes)6023 pprint(' please choose one with -m')6024 6025 # check if ftrace is available6026 if sysvals.useftrace:6027 res = sysvals.colorText('NO')6028 sysvals.useftrace = sysvals.verifyFtrace()6029 efmt = '"{0}" uses ftrace, and it is not properly supported'6030 if sysvals.useftrace:6031 res = 'YES'6032 elif sysvals.usecallgraph:6033 status = efmt.format('-f')6034 elif sysvals.usedevsrc:6035 status = efmt.format('-dev')6036 elif sysvals.useprocmon:6037 status = efmt.format('-proc')6038 pprint(' is ftrace supported: %s' % res)6039 6040 # check if kprobes are available6041 if sysvals.usekprobes:6042 res = sysvals.colorText('NO')6043 sysvals.usekprobes = sysvals.verifyKprobes()6044 if(sysvals.usekprobes):6045 res = 'YES'6046 else:6047 sysvals.usedevsrc = False6048 pprint(' are kprobes supported: %s' % res)6049 6050 # what data source are we using6051 res = 'DMESG (very limited, ftrace is preferred)'6052 if sysvals.useftrace:6053 sysvals.usetraceevents = True6054 for e in sysvals.traceevents:6055 if not os.path.exists(sysvals.epath+e):6056 sysvals.usetraceevents = False6057 if(sysvals.usetraceevents):6058 res = 'FTRACE (all trace events found)'6059 pprint(' timeline data source: %s' % res)6060 6061 # check if rtcwake6062 res = sysvals.colorText('NO')6063 if(sysvals.rtcpath != ''):6064 res = 'YES'6065 elif(sysvals.rtcwake):6066 status = 'rtcwake is not properly supported'6067 pprint(' is rtcwake supported: %s' % res)6068 6069 # check info commands6070 pprint(' optional commands this tool may use for info:')6071 no = sysvals.colorText('MISSING')6072 yes = sysvals.colorText('FOUND', 32)6073 for c in ['turbostat', 'mcelog', 'lspci', 'lsusb', 'netfix']:6074 if c == 'turbostat':6075 res = yes if sysvals.haveTurbostat() else no6076 else:6077 res = yes if sysvals.getExec(c) else no6078 pprint(' %s: %s' % (c, res))6079 6080 if not probecheck:6081 return status6082 6083 # verify kprobes6084 if sysvals.usekprobes:6085 for name in sysvals.tracefuncs:6086 sysvals.defaultKprobe(name, sysvals.tracefuncs[name])6087 if sysvals.usedevsrc:6088 for name in sysvals.dev_tracefuncs:6089 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])6090 sysvals.addKprobes(True)6091 6092 return status6093 6094# Function: doError6095# Description:6096# generic error function for catastrphic failures6097# Arguments:6098# msg: the error message to print6099# help: True if printHelp should be called after, False otherwise6100def doError(msg, help=False):6101 if(help == True):6102 printHelp()6103 pprint('ERROR: %s\n' % msg)6104 sysvals.outputResult({'error':msg})6105 sys.exit(1)6106 6107# Function: getArgInt6108# Description:6109# pull out an integer argument from the command line with checks6110def getArgInt(name, args, min, max, main=True):6111 if main:6112 try:6113 arg = next(args)6114 except:6115 doError(name+': no argument supplied', True)6116 else:6117 arg = args6118 try:6119 val = int(arg)6120 except:6121 doError(name+': non-integer value given', True)6122 if(val < min or val > max):6123 doError(name+': value should be between %d and %d' % (min, max), True)6124 return val6125 6126# Function: getArgFloat6127# Description:6128# pull out a float argument from the command line with checks6129def getArgFloat(name, args, min, max, main=True):6130 if main:6131 try:6132 arg = next(args)6133 except:6134 doError(name+': no argument supplied', True)6135 else:6136 arg = args6137 try:6138 val = float(arg)6139 except:6140 doError(name+': non-numerical value given', True)6141 if(val < min or val > max):6142 doError(name+': value should be between %f and %f' % (min, max), True)6143 return val6144 6145def processData(live=False, quiet=False):6146 if not quiet:6147 pprint('PROCESSING: %s' % sysvals.htmlfile)6148 sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \6149 (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes))6150 error = ''6151 if(sysvals.usetraceevents):6152 testruns, error = parseTraceLog(live)6153 if sysvals.dmesgfile:6154 for data in testruns:6155 data.extractErrorInfo()6156 else:6157 testruns = loadKernelLog()6158 for data in testruns:6159 parseKernelLog(data)6160 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):6161 appendIncompleteTraceLog(testruns)6162 if not sysvals.stamp:6163 pprint('ERROR: data does not include the expected stamp')6164 return (testruns, {'error': 'timeline generation failed'})6165 shown = ['os', 'bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr',6166 'memsz', 'mode', 'numcpu', 'plat', 'time', 'wifi']6167 sysvals.vprint('System Info:')6168 for key in sorted(sysvals.stamp):6169 if key in shown:6170 sysvals.vprint(' %-8s : %s' % (key.upper(), sysvals.stamp[key]))6171 sysvals.vprint('Command:\n %s' % sysvals.cmdline)6172 for data in testruns:6173 if data.turbostat:6174 idx, s = 0, 'Turbostat:\n '6175 for val in data.turbostat.split('|'):6176 idx += len(val) + 16177 if idx >= 80:6178 idx = 06179 s += '\n '6180 s += val + ' '6181 sysvals.vprint(s)6182 data.printDetails()6183 if len(sysvals.platinfo) > 0:6184 sysvals.vprint('\nPlatform Info:')6185 for info in sysvals.platinfo:6186 sysvals.vprint('[%s - %s]' % (info[0], info[1]))6187 sysvals.vprint(info[2])6188 sysvals.vprint('')6189 if sysvals.cgdump:6190 for data in testruns:6191 data.debugPrint()6192 sys.exit(0)6193 if len(testruns) < 1:6194 pprint('ERROR: Not enough test data to build a timeline')6195 return (testruns, {'error': 'timeline generation failed'})6196 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)6197 createHTML(testruns, error)6198 if not quiet:6199 pprint('DONE: %s' % sysvals.htmlfile)6200 data = testruns[0]6201 stamp = data.stamp6202 stamp['suspend'], stamp['resume'] = data.getTimeValues()6203 if data.fwValid:6204 stamp['fwsuspend'], stamp['fwresume'] = data.fwSuspend, data.fwResume6205 if error:6206 stamp['error'] = error6207 return (testruns, stamp)6208 6209# Function: rerunTest6210# Description:6211# generate an output from an existing set of ftrace/dmesg logs6212def rerunTest(htmlfile=''):6213 if sysvals.ftracefile:6214 doesTraceLogHaveTraceEvents()6215 if not sysvals.dmesgfile and not sysvals.usetraceevents:6216 doError('recreating this html output requires a dmesg file')6217 if htmlfile:6218 sysvals.htmlfile = htmlfile6219 else:6220 sysvals.setOutputFile()6221 if os.path.exists(sysvals.htmlfile):6222 if not os.path.isfile(sysvals.htmlfile):6223 doError('a directory already exists with this name: %s' % sysvals.htmlfile)6224 elif not os.access(sysvals.htmlfile, os.W_OK):6225 doError('missing permission to write to %s' % sysvals.htmlfile)6226 testruns, stamp = processData()6227 sysvals.resetlog()6228 return stamp6229 6230# Function: runTest6231# Description:6232# execute a suspend/resume, gather the logs, and generate the output6233def runTest(n=0, quiet=False):6234 # prepare for the test6235 sysvals.initTestOutput('suspend')6236 op = sysvals.writeDatafileHeader(sysvals.dmesgfile, [])6237 op.write('# EXECUTION TRACE START\n')6238 op.close()6239 if n <= 1:6240 if sysvals.rs != 0:6241 sysvals.dlog('%sabling runtime suspend' % ('en' if sysvals.rs > 0 else 'dis'))6242 sysvals.setRuntimeSuspend(True)6243 if sysvals.display:6244 ret = sysvals.displayControl('init')6245 sysvals.dlog('xset display init, ret = %d' % ret)6246 sysvals.testVal(sysvals.pmdpath, 'basic', '1')6247 sysvals.testVal(sysvals.s0ixpath, 'basic', 'Y')6248 sysvals.dlog('initialize ftrace')6249 sysvals.initFtrace(quiet)6250 6251 # execute the test6252 executeSuspend(quiet)6253 sysvals.cleanupFtrace()6254 if sysvals.skiphtml:6255 sysvals.outputResult({}, n)6256 sysvals.sudoUserchown(sysvals.testdir)6257 return6258 testruns, stamp = processData(True, quiet)6259 for data in testruns:6260 del data6261 sysvals.sudoUserchown(sysvals.testdir)6262 sysvals.outputResult(stamp, n)6263 if 'error' in stamp:6264 return 26265 return 06266 6267def find_in_html(html, start, end, firstonly=True):6268 cnt, out, list = len(html), [], []6269 if firstonly:6270 m = re.search(start, html)6271 if m:6272 list.append(m)6273 else:6274 list = re.finditer(start, html)6275 for match in list:6276 s = match.end()6277 e = cnt if (len(out) < 1 or s + 10000 > cnt) else s + 100006278 m = re.search(end, html[s:e])6279 if not m:6280 break6281 e = s + m.start()6282 str = html[s:e]6283 if end == 'ms':6284 num = re.search(r'[-+]?\d*\.\d+|\d+', str)6285 str = num.group() if num else 'NaN'6286 if firstonly:6287 return str6288 out.append(str)6289 if firstonly:6290 return ''6291 return out6292 6293def data_from_html(file, outpath, issues, fulldetail=False):6294 try:6295 html = open(file, 'r').read()6296 except:6297 html = ascii(open(file, 'rb').read())6298 sysvals.htmlfile = os.path.relpath(file, outpath)6299 # extract general info6300 suspend = find_in_html(html, 'Kernel Suspend', 'ms')6301 resume = find_in_html(html, 'Kernel Resume', 'ms')6302 sysinfo = find_in_html(html, '<div class="stamp sysinfo">', '</div>')6303 line = find_in_html(html, '<div class="stamp">', '</div>')6304 stmp = line.split()6305 if not suspend or not resume or len(stmp) != 8:6306 return False6307 try:6308 dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')6309 except:6310 return False6311 sysvals.hostname = stmp[0]6312 tstr = dt.strftime('%Y/%m/%d %H:%M:%S')6313 error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')6314 if error:6315 m = re.match(r'[a-z0-9]* failed in (?P<p>\S*).*', error)6316 if m:6317 result = 'fail in %s' % m.group('p')6318 else:6319 result = 'fail'6320 else:6321 result = 'pass'6322 # extract error info6323 tp, ilist = False, []6324 extra = dict()6325 log = find_in_html(html, '<div id="dmesglog" style="display:none;">',6326 '</div>').strip()6327 if log:6328 d = Data(0)6329 d.end = 9999999996330 d.dmesgtext = log.split('\n')6331 tp = d.extractErrorInfo()6332 if len(issues) < 100:6333 for msg in tp.msglist:6334 sysvals.errorSummary(issues, msg)6335 if stmp[2] == 'freeze':6336 extra = d.turbostatInfo()6337 elist = dict()6338 for dir in d.errorinfo:6339 for err in d.errorinfo[dir]:6340 if err[0] not in elist:6341 elist[err[0]] = 06342 elist[err[0]] += 16343 for i in elist:6344 ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i)6345 line = find_in_html(log, '# wifi ', '\n')6346 if line:6347 extra['wifi'] = line6348 line = find_in_html(log, '# netfix ', '\n')6349 if line:6350 extra['netfix'] = line6351 line = find_in_html(log, '# command ', '\n')6352 if line:6353 m = re.match(r'.* -m (?P<m>\S*).*', line)6354 if m:6355 extra['fullmode'] = m.group('m')6356 low = find_in_html(html, 'freeze time: <b>', ' ms</b>')6357 for lowstr in ['waking', '+']:6358 if not low:6359 break6360 if lowstr not in low:6361 continue6362 if lowstr == '+':6363 issue = 'S2LOOPx%d' % len(low.split('+'))6364 else:6365 m = re.match(r'.*waking *(?P<n>[0-9]*) *times.*', low)6366 issue = 'S2WAKEx%s' % m.group('n') if m else 'S2WAKExNaN'6367 match = [i for i in issues if i['match'] == issue]6368 if len(match) > 0:6369 match[0]['count'] += 16370 if sysvals.hostname not in match[0]['urls']:6371 match[0]['urls'][sysvals.hostname] = [sysvals.htmlfile]6372 elif sysvals.htmlfile not in match[0]['urls'][sysvals.hostname]:6373 match[0]['urls'][sysvals.hostname].append(sysvals.htmlfile)6374 else:6375 issues.append({6376 'match': issue, 'count': 1, 'line': issue,6377 'urls': {sysvals.hostname: [sysvals.htmlfile]},6378 })6379 ilist.append(issue)6380 # extract device info6381 devices = dict()6382 for line in html.split('\n'):6383 m = re.match(r' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line)6384 if not m or 'thread kth' in line or 'thread sec' in line:6385 continue6386 m = re.match(r'(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title'))6387 if not m:6388 continue6389 name, time, phase = m.group('n'), m.group('t'), m.group('p')6390 if name == 'async_synchronize_full':6391 continue6392 if ' async' in name or ' sync' in name:6393 name = ' '.join(name.split(' ')[:-1])6394 if phase.startswith('suspend'):6395 d = 'suspend'6396 elif phase.startswith('resume'):6397 d = 'resume'6398 else:6399 continue6400 if d not in devices:6401 devices[d] = dict()6402 if name not in devices[d]:6403 devices[d][name] = 0.06404 devices[d][name] += float(time)6405 # create worst device info6406 worst = dict()6407 for d in ['suspend', 'resume']:6408 worst[d] = {'name':'', 'time': 0.0}6409 dev = devices[d] if d in devices else 06410 if dev and len(dev.keys()) > 0:6411 n = sorted(dev, key=lambda k:(dev[k], k), reverse=True)[0]6412 worst[d]['name'], worst[d]['time'] = n, dev[n]6413 data = {6414 'mode': stmp[2],6415 'host': stmp[0],6416 'kernel': stmp[1],6417 'sysinfo': sysinfo,6418 'time': tstr,6419 'result': result,6420 'issues': ' '.join(ilist),6421 'suspend': suspend,6422 'resume': resume,6423 'devlist': devices,6424 'sus_worst': worst['suspend']['name'],6425 'sus_worsttime': worst['suspend']['time'],6426 'res_worst': worst['resume']['name'],6427 'res_worsttime': worst['resume']['time'],6428 'url': sysvals.htmlfile,6429 }6430 for key in extra:6431 data[key] = extra[key]6432 if fulldetail:6433 data['funclist'] = find_in_html(html, '<div title="', '" class="traceevent"', False)6434 if tp:6435 for arg in ['-multi ', '-info ']:6436 if arg in tp.cmdline:6437 data['target'] = tp.cmdline[tp.cmdline.find(arg):].split()[1]6438 break6439 return data6440 6441def genHtml(subdir, force=False):6442 for dirname, dirnames, filenames in os.walk(subdir):6443 sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''6444 for filename in filenames:6445 file = os.path.join(dirname, filename)6446 if sysvals.usable(file):6447 if(re.match(r'.*_dmesg.txt', filename)):6448 sysvals.dmesgfile = file6449 elif(re.match(r'.*_ftrace.txt', filename)):6450 sysvals.ftracefile = file6451 sysvals.setOutputFile()6452 if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \6453 (force or not sysvals.usable(sysvals.htmlfile, True)):6454 pprint('FTRACE: %s' % sysvals.ftracefile)6455 if sysvals.dmesgfile:6456 pprint('DMESG : %s' % sysvals.dmesgfile)6457 rerunTest()6458 6459# Function: runSummary6460# Description:6461# create a summary of tests in a sub-directory6462def runSummary(subdir, local=True, genhtml=False):6463 inpath = os.path.abspath(subdir)6464 outpath = os.path.abspath('.') if local else inpath6465 pprint('Generating a summary of folder:\n %s' % inpath)6466 if genhtml:6467 genHtml(subdir)6468 target, issues, testruns = '', [], []6469 desc = {'host':[],'mode':[],'kernel':[]}6470 for dirname, dirnames, filenames in os.walk(subdir):6471 for filename in filenames:6472 if(not re.match(r'.*.html', filename)):6473 continue6474 data = data_from_html(os.path.join(dirname, filename), outpath, issues)6475 if(not data):6476 continue6477 if 'target' in data:6478 target = data['target']6479 testruns.append(data)6480 for key in desc:6481 if data[key] not in desc[key]:6482 desc[key].append(data[key])6483 pprint('Summary files:')6484 if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1:6485 title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0])6486 if target:6487 title += ' %s' % target6488 else:6489 title = inpath6490 createHTMLSummarySimple(testruns, os.path.join(outpath, 'summary.html'), title)6491 pprint(' summary.html - tabular list of test data found')6492 createHTMLDeviceSummary(testruns, os.path.join(outpath, 'summary-devices.html'), title)6493 pprint(' summary-devices.html - kernel device list sorted by total execution time')6494 createHTMLIssuesSummary(testruns, issues, os.path.join(outpath, 'summary-issues.html'), title)6495 pprint(' summary-issues.html - kernel issues found sorted by frequency')6496 6497# Function: checkArgBool6498# Description:6499# check if a boolean string value is true or false6500def checkArgBool(name, value):6501 if value in switchvalues:6502 if value in switchoff:6503 return False6504 return True6505 doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True)6506 return False6507 6508# Function: configFromFile6509# Description:6510# Configure the script via the info in a config file6511def configFromFile(file):6512 Config = configparser.ConfigParser()6513 6514 Config.read(file)6515 sections = Config.sections()6516 overridekprobes = False6517 overridedevkprobes = False6518 if 'Settings' in sections:6519 for opt in Config.options('Settings'):6520 value = Config.get('Settings', opt).lower()6521 option = opt.lower()6522 if(option == 'verbose'):6523 sysvals.verbose = checkArgBool(option, value)6524 elif(option == 'addlogs'):6525 sysvals.dmesglog = sysvals.ftracelog = checkArgBool(option, value)6526 elif(option == 'dev'):6527 sysvals.usedevsrc = checkArgBool(option, value)6528 elif(option == 'proc'):6529 sysvals.useprocmon = checkArgBool(option, value)6530 elif(option == 'x2'):6531 if checkArgBool(option, value):6532 sysvals.execcount = 26533 elif(option == 'callgraph'):6534 sysvals.usecallgraph = checkArgBool(option, value)6535 elif(option == 'override-timeline-functions'):6536 overridekprobes = checkArgBool(option, value)6537 elif(option == 'override-dev-timeline-functions'):6538 overridedevkprobes = checkArgBool(option, value)6539 elif(option == 'skiphtml'):6540 sysvals.skiphtml = checkArgBool(option, value)6541 elif(option == 'sync'):6542 sysvals.sync = checkArgBool(option, value)6543 elif(option == 'rs' or option == 'runtimesuspend'):6544 if value in switchvalues:6545 if value in switchoff:6546 sysvals.rs = -16547 else:6548 sysvals.rs = 16549 else:6550 doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)6551 elif(option == 'display'):6552 disopt = ['on', 'off', 'standby', 'suspend']6553 if value not in disopt:6554 doError('invalid value --> (%s: %s), use %s' % (option, value, disopt), True)6555 sysvals.display = value6556 elif(option == 'gzip'):6557 sysvals.gzip = checkArgBool(option, value)6558 elif(option == 'cgfilter'):6559 sysvals.setCallgraphFilter(value)6560 elif(option == 'cgskip'):6561 if value in switchoff:6562 sysvals.cgskip = ''6563 else:6564 sysvals.cgskip = sysvals.configFile(val)6565 if(not sysvals.cgskip):6566 doError('%s does not exist' % sysvals.cgskip)6567 elif(option == 'cgtest'):6568 sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)6569 elif(option == 'cgphase'):6570 d = Data(0)6571 if value not in d.phasedef:6572 doError('invalid phase --> (%s: %s), valid phases are %s'\6573 % (option, value, d.phasedef.keys()), True)6574 sysvals.cgphase = value6575 elif(option == 'fadd'):6576 file = sysvals.configFile(value)6577 if(not file):6578 doError('%s does not exist' % value)6579 sysvals.addFtraceFilterFunctions(file)6580 elif(option == 'result'):6581 sysvals.result = value6582 elif(option == 'multi'):6583 nums = value.split()6584 if len(nums) != 2:6585 doError('multi requires 2 integers (exec_count and delay)', True)6586 sysvals.multiinit(nums[0], nums[1])6587 elif(option == 'devicefilter'):6588 sysvals.setDeviceFilter(value)6589 elif(option == 'expandcg'):6590 sysvals.cgexp = checkArgBool(option, value)6591 elif(option == 'srgap'):6592 if checkArgBool(option, value):6593 sysvals.srgap = 56594 elif(option == 'mode'):6595 sysvals.suspendmode = value6596 elif(option == 'command' or option == 'cmd'):6597 sysvals.testcommand = value6598 elif(option == 'x2delay'):6599 sysvals.x2delay = getArgInt('x2delay', value, 0, 60000, False)6600 elif(option == 'predelay'):6601 sysvals.predelay = getArgInt('predelay', value, 0, 60000, False)6602 elif(option == 'postdelay'):6603 sysvals.postdelay = getArgInt('postdelay', value, 0, 60000, False)6604 elif(option == 'maxdepth'):6605 sysvals.max_graph_depth = getArgInt('maxdepth', value, 0, 1000, False)6606 elif(option == 'rtcwake'):6607 if value in switchoff:6608 sysvals.rtcwake = False6609 else:6610 sysvals.rtcwake = True6611 sysvals.rtcwaketime = getArgInt('rtcwake', value, 0, 3600, False)6612 elif(option == 'timeprec'):6613 sysvals.setPrecision(getArgInt('timeprec', value, 0, 6, False))6614 elif(option == 'mindev'):6615 sysvals.mindevlen = getArgFloat('mindev', value, 0.0, 10000.0, False)6616 elif(option == 'callloop-maxgap'):6617 sysvals.callloopmaxgap = getArgFloat('callloop-maxgap', value, 0.0, 1.0, False)6618 elif(option == 'callloop-maxlen'):6619 sysvals.callloopmaxgap = getArgFloat('callloop-maxlen', value, 0.0, 1.0, False)6620 elif(option == 'mincg'):6621 sysvals.mincglen = getArgFloat('mincg', value, 0.0, 10000.0, False)6622 elif(option == 'bufsize'):6623 sysvals.bufsize = getArgInt('bufsize', value, 1, 1024*1024*8, False)6624 elif(option == 'output-dir'):6625 sysvals.outdir = sysvals.setOutputFolder(value)6626 6627 if sysvals.suspendmode == 'command' and not sysvals.testcommand:6628 doError('No command supplied for mode "command"')6629 6630 # compatibility errors6631 if sysvals.usedevsrc and sysvals.usecallgraph:6632 doError('-dev is not compatible with -f')6633 if sysvals.usecallgraph and sysvals.useprocmon:6634 doError('-proc is not compatible with -f')6635 6636 if overridekprobes:6637 sysvals.tracefuncs = dict()6638 if overridedevkprobes:6639 sysvals.dev_tracefuncs = dict()6640 6641 kprobes = dict()6642 kprobesec = 'dev_timeline_functions_'+platform.machine()6643 if kprobesec in sections:6644 for name in Config.options(kprobesec):6645 text = Config.get(kprobesec, name)6646 kprobes[name] = (text, True)6647 kprobesec = 'timeline_functions_'+platform.machine()6648 if kprobesec in sections:6649 for name in Config.options(kprobesec):6650 if name in kprobes:6651 doError('Duplicate timeline function found "%s"' % (name))6652 text = Config.get(kprobesec, name)6653 kprobes[name] = (text, False)6654 6655 for name in kprobes:6656 function = name6657 format = name6658 color = ''6659 args = dict()6660 text, dev = kprobes[name]6661 data = text.split()6662 i = 06663 for val in data:6664 # bracketted strings are special formatting, read them separately6665 if val[0] == '[' and val[-1] == ']':6666 for prop in val[1:-1].split(','):6667 p = prop.split('=')6668 if p[0] == 'color':6669 try:6670 color = int(p[1], 16)6671 color = '#'+p[1]6672 except:6673 color = p[1]6674 continue6675 # first real arg should be the format string6676 if i == 0:6677 format = val6678 # all other args are actual function args6679 else:6680 d = val.split('=')6681 args[d[0]] = d[1]6682 i += 16683 if not function or not format:6684 doError('Invalid kprobe: %s' % name)6685 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):6686 if arg not in args:6687 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))6688 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):6689 doError('Duplicate timeline function found "%s"' % (name))6690 6691 kp = {6692 'name': name,6693 'func': function,6694 'format': format,6695 sysvals.archargs: args6696 }6697 if color:6698 kp['color'] = color6699 if dev:6700 sysvals.dev_tracefuncs[name] = kp6701 else:6702 sysvals.tracefuncs[name] = kp6703 6704# Function: printHelp6705# Description:6706# print out the help text6707def printHelp():6708 pprint('\n%s v%s\n'\6709 'Usage: sudo sleepgraph <options> <commands>\n'\6710 '\n'\6711 'Description:\n'\6712 ' This tool is designed to assist kernel and OS developers in optimizing\n'\6713 ' their linux stack\'s suspend/resume time. Using a kernel image built\n'\6714 ' with a few extra options enabled, the tool will execute a suspend and\n'\6715 ' capture dmesg and ftrace data until resume is complete. This data is\n'\6716 ' transformed into a device timeline and an optional callgraph to give\n'\6717 ' a detailed view of which devices/subsystems are taking the most\n'\6718 ' time in suspend/resume.\n'\6719 '\n'\6720 ' If no specific command is given, the default behavior is to initiate\n'\6721 ' a suspend/resume and capture the dmesg/ftrace output as an html timeline.\n'\6722 '\n'\6723 ' Generates output files in subdirectory: suspend-yymmdd-HHMMSS\n'\6724 ' HTML output: <hostname>_<mode>.html\n'\6725 ' raw dmesg output: <hostname>_<mode>_dmesg.txt\n'\6726 ' raw ftrace output: <hostname>_<mode>_ftrace.txt\n'\6727 '\n'\6728 'Options:\n'\6729 ' -h Print this help text\n'\6730 ' -v Print the current tool version\n'\6731 ' -config fn Pull arguments and config options from file fn\n'\6732 ' -verbose Print extra information during execution and analysis\n'\6733 ' -m mode Mode to initiate for suspend (default: %s)\n'\6734 ' -o name Overrides the output subdirectory name when running a new test\n'\6735 ' default: suspend-{date}-{time}\n'\6736 ' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)\n'\6737 ' -addlogs Add the dmesg and ftrace logs to the html output\n'\6738 ' -noturbostat Dont use turbostat in freeze mode (default: disabled)\n'\6739 ' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\6740 ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\6741 ' -result fn Export a results table to a text file for parsing.\n'\6742 ' -wifi If a wifi connection is available, check that it reconnects after resume.\n'\6743 ' -wifitrace Trace kernel execution through wifi reconnect.\n'\6744 ' -netfix Use netfix to reset the network in the event it fails to resume.\n'\6745 ' [testprep]\n'\6746 ' -sync Sync the filesystems before starting the test\n'\6747 ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\6748 ' -display m Change the display mode to m for the test (on/off/standby/suspend)\n'\6749 ' [advanced]\n'\6750 ' -gzip Gzip the trace and dmesg logs to save space\n'\6751 ' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"\n'\6752 ' -proc Add usermode process info into the timeline (default: disabled)\n'\6753 ' -dev Add kernel function calls and threads to the timeline (default: disabled)\n'\6754 ' -x2 Run two suspend/resumes back to back (default: disabled)\n'\6755 ' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)\n'\6756 ' -predelay t Include t ms delay before 1st suspend (default: 0 ms)\n'\6757 ' -postdelay t Include t ms delay after last resume (default: 0 ms)\n'\6758 ' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)\n'\6759 ' -multi n d Execute <n> consecutive tests at <d> seconds intervals. If <n> is followed\n'\6760 ' by a "d", "h", or "m" execute for <n> days, hours, or mins instead.\n'\6761 ' The outputs will be created in a new subdirectory with a summary page.\n'\6762 ' -maxfail n Abort a -multi run after n consecutive fails (default is 0 = never abort)\n'\6763 ' [debug]\n'\6764 ' -f Use ftrace to create device callgraphs (default: disabled)\n'\6765 ' -ftop Use ftrace on the top level call: "%s" (default: disabled)\n'\6766 ' -maxdepth N limit the callgraph data to N call levels (default: 0=all)\n'\6767 ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\6768 ' -fadd file Add functions to be graphed in the timeline from a list in a text file\n'\6769 ' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names\n'\6770 ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\6771 ' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)\n'\6772 ' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)\n'\6773 ' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)\n'\6774 ' -cgfilter S Filter the callgraph output in the timeline\n'\6775 ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\6776 ' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)\n'\6777 ' -devdump Print out all the raw device data for each phase\n'\6778 ' -cgdump Print out all the raw callgraph data\n'\6779 '\n'\6780 'Other commands:\n'\6781 ' -modes List available suspend modes\n'\6782 ' -status Test to see if the system is enabled to run this tool\n'\6783 ' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\6784 ' -wificheck Print out wifi connection info\n'\6785 ' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\6786 ' -sysinfo Print out system info extracted from BIOS\n'\6787 ' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\6788 ' -cmdinfo Print out all the platform info collected before and after suspend/resume\n'\6789 ' -flist Print the list of functions currently being captured in ftrace\n'\6790 ' -flistall Print all functions capable of being captured in ftrace\n'\6791 ' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]\n'\6792 ' [redo]\n'\6793 ' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)\n'\6794 ' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)\n'\6795 '' % (sysvals.title, sysvals.version, sysvals.suspendmode, sysvals.ftopfunc))6796 return True6797 6798# ----------------- MAIN --------------------6799# exec start (skipped if script is loaded as library)6800if __name__ == '__main__':6801 genhtml = False6802 cmd = ''6803 simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall',6804 '-devinfo', '-status', '-xon', '-xoff', '-xstandby', '-xsuspend',6805 '-xinit', '-xreset', '-xstat', '-wificheck', '-cmdinfo']6806 if '-f' in sys.argv:6807 sysvals.cgskip = sysvals.configFile('cgskip.txt')6808 # loop through the command line arguments6809 args = iter(sys.argv[1:])6810 for arg in args:6811 if(arg == '-m'):6812 try:6813 val = next(args)6814 except:6815 doError('No mode supplied', True)6816 if val == 'command' and not sysvals.testcommand:6817 doError('No command supplied for mode "command"', True)6818 sysvals.suspendmode = val6819 elif(arg in simplecmds):6820 cmd = arg[1:]6821 elif(arg == '-h'):6822 printHelp()6823 sys.exit(0)6824 elif(arg == '-v'):6825 pprint("Version %s" % sysvals.version)6826 sys.exit(0)6827 elif(arg == '-debugtiming'):6828 debugtiming = True6829 elif(arg == '-x2'):6830 sysvals.execcount = 26831 elif(arg == '-x2delay'):6832 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)6833 elif(arg == '-predelay'):6834 sysvals.predelay = getArgInt('-predelay', args, 0, 60000)6835 elif(arg == '-postdelay'):6836 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)6837 elif(arg == '-f'):6838 sysvals.usecallgraph = True6839 elif(arg == '-ftop'):6840 sysvals.usecallgraph = True6841 sysvals.ftop = True6842 sysvals.usekprobes = False6843 elif(arg == '-skiphtml'):6844 sysvals.skiphtml = True6845 elif(arg == '-cgdump'):6846 sysvals.cgdump = True6847 elif(arg == '-devdump'):6848 sysvals.devdump = True6849 elif(arg == '-genhtml'):6850 genhtml = True6851 elif(arg == '-addlogs'):6852 sysvals.dmesglog = sysvals.ftracelog = True6853 elif(arg == '-nologs'):6854 sysvals.dmesglog = sysvals.ftracelog = False6855 elif(arg == '-addlogdmesg'):6856 sysvals.dmesglog = True6857 elif(arg == '-addlogftrace'):6858 sysvals.ftracelog = True6859 elif(arg == '-noturbostat'):6860 sysvals.tstat = False6861 elif(arg == '-verbose'):6862 sysvals.verbose = True6863 elif(arg == '-proc'):6864 sysvals.useprocmon = True6865 elif(arg == '-dev'):6866 sysvals.usedevsrc = True6867 elif(arg == '-sync'):6868 sysvals.sync = True6869 elif(arg == '-wifi'):6870 sysvals.wifi = True6871 elif(arg == '-wifitrace'):6872 sysvals.wifitrace = True6873 elif(arg == '-netfix'):6874 sysvals.netfix = True6875 elif(arg == '-gzip'):6876 sysvals.gzip = True6877 elif(arg == '-info'):6878 try:6879 val = next(args)6880 except:6881 doError('-info requires one string argument', True)6882 elif(arg == '-desc'):6883 try:6884 val = next(args)6885 except:6886 doError('-desc requires one string argument', True)6887 elif(arg == '-rs'):6888 try:6889 val = next(args)6890 except:6891 doError('-rs requires "enable" or "disable"', True)6892 if val.lower() in switchvalues:6893 if val.lower() in switchoff:6894 sysvals.rs = -16895 else:6896 sysvals.rs = 16897 else:6898 doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True)6899 elif(arg == '-display'):6900 try:6901 val = next(args)6902 except:6903 doError('-display requires an mode value', True)6904 disopt = ['on', 'off', 'standby', 'suspend']6905 if val.lower() not in disopt:6906 doError('valid display mode values are %s' % disopt, True)6907 sysvals.display = val.lower()6908 elif(arg == '-maxdepth'):6909 sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)6910 elif(arg == '-rtcwake'):6911 try:6912 val = next(args)6913 except:6914 doError('No rtcwake time supplied', True)6915 if val.lower() in switchoff:6916 sysvals.rtcwake = False6917 else:6918 sysvals.rtcwake = True6919 sysvals.rtcwaketime = getArgInt('-rtcwake', val, 0, 3600, False)6920 elif(arg == '-timeprec'):6921 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))6922 elif(arg == '-mindev'):6923 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)6924 elif(arg == '-mincg'):6925 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)6926 elif(arg == '-bufsize'):6927 sysvals.bufsize = getArgInt('-bufsize', args, 1, 1024*1024*8)6928 elif(arg == '-cgtest'):6929 sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)6930 elif(arg == '-cgphase'):6931 try:6932 val = next(args)6933 except:6934 doError('No phase name supplied', True)6935 d = Data(0)6936 if val not in d.phasedef:6937 doError('invalid phase --> (%s: %s), valid phases are %s'\6938 % (arg, val, d.phasedef.keys()), True)6939 sysvals.cgphase = val6940 elif(arg == '-cgfilter'):6941 try:6942 val = next(args)6943 except:6944 doError('No callgraph functions supplied', True)6945 sysvals.setCallgraphFilter(val)6946 elif(arg == '-skipkprobe'):6947 try:6948 val = next(args)6949 except:6950 doError('No kprobe functions supplied', True)6951 sysvals.skipKprobes(val)6952 elif(arg == '-cgskip'):6953 try:6954 val = next(args)6955 except:6956 doError('No file supplied', True)6957 if val.lower() in switchoff:6958 sysvals.cgskip = ''6959 else:6960 sysvals.cgskip = sysvals.configFile(val)6961 if(not sysvals.cgskip):6962 doError('%s does not exist' % sysvals.cgskip)6963 elif(arg == '-callloop-maxgap'):6964 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)6965 elif(arg == '-callloop-maxlen'):6966 sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)6967 elif(arg == '-cmd'):6968 try:6969 val = next(args)6970 except:6971 doError('No command string supplied', True)6972 sysvals.testcommand = val6973 sysvals.suspendmode = 'command'6974 elif(arg == '-expandcg'):6975 sysvals.cgexp = True6976 elif(arg == '-srgap'):6977 sysvals.srgap = 56978 elif(arg == '-maxfail'):6979 sysvals.maxfail = getArgInt('-maxfail', args, 0, 1000000)6980 elif(arg == '-multi'):6981 try:6982 c, d = next(args), next(args)6983 except:6984 doError('-multi requires two values', True)6985 sysvals.multiinit(c, d)6986 elif(arg == '-o'):6987 try:6988 val = next(args)6989 except:6990 doError('No subdirectory name supplied', True)6991 sysvals.outdir = sysvals.setOutputFolder(val)6992 elif(arg == '-config'):6993 try:6994 val = next(args)6995 except:6996 doError('No text file supplied', True)6997 file = sysvals.configFile(val)6998 if(not file):6999 doError('%s does not exist' % val)7000 configFromFile(file)7001 elif(arg == '-fadd'):7002 try:7003 val = next(args)7004 except:7005 doError('No text file supplied', True)7006 file = sysvals.configFile(val)7007 if(not file):7008 doError('%s does not exist' % val)7009 sysvals.addFtraceFilterFunctions(file)7010 elif(arg == '-dmesg'):7011 try:7012 val = next(args)7013 except:7014 doError('No dmesg file supplied', True)7015 sysvals.notestrun = True7016 sysvals.dmesgfile = val7017 if(os.path.exists(sysvals.dmesgfile) == False):7018 doError('%s does not exist' % sysvals.dmesgfile)7019 elif(arg == '-ftrace'):7020 try:7021 val = next(args)7022 except:7023 doError('No ftrace file supplied', True)7024 sysvals.notestrun = True7025 sysvals.ftracefile = val7026 if(os.path.exists(sysvals.ftracefile) == False):7027 doError('%s does not exist' % sysvals.ftracefile)7028 elif(arg == '-summary'):7029 try:7030 val = next(args)7031 except:7032 doError('No directory supplied', True)7033 cmd = 'summary'7034 sysvals.outdir = val7035 sysvals.notestrun = True7036 if(os.path.isdir(val) == False):7037 doError('%s is not accesible' % val)7038 elif(arg == '-filter'):7039 try:7040 val = next(args)7041 except:7042 doError('No devnames supplied', True)7043 sysvals.setDeviceFilter(val)7044 elif(arg == '-result'):7045 try:7046 val = next(args)7047 except:7048 doError('No result file supplied', True)7049 sysvals.result = val7050 sysvals.signalHandlerInit()7051 else:7052 doError('Invalid argument: '+arg, True)7053 7054 # compatibility errors7055 if(sysvals.usecallgraph and sysvals.usedevsrc):7056 doError('-dev is not compatible with -f')7057 if(sysvals.usecallgraph and sysvals.useprocmon):7058 doError('-proc is not compatible with -f')7059 7060 if sysvals.usecallgraph and sysvals.cgskip:7061 sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip)7062 sysvals.setCallgraphBlacklist(sysvals.cgskip)7063 7064 # callgraph size cannot exceed device size7065 if sysvals.mincglen < sysvals.mindevlen:7066 sysvals.mincglen = sysvals.mindevlen7067 7068 # remove existing buffers before calculating memory7069 if(sysvals.usecallgraph or sysvals.usedevsrc):7070 sysvals.fsetVal('16', 'buffer_size_kb')7071 sysvals.cpuInfo()7072 7073 # just run a utility command and exit7074 if(cmd != ''):7075 ret = 07076 if(cmd == 'status'):7077 if not statusCheck(True):7078 ret = 17079 elif(cmd == 'fpdt'):7080 if not getFPDT(True):7081 ret = 17082 elif(cmd == 'sysinfo'):7083 sysvals.printSystemInfo(True)7084 elif(cmd == 'devinfo'):7085 deviceInfo()7086 elif(cmd == 'modes'):7087 pprint(getModes())7088 elif(cmd == 'flist'):7089 sysvals.getFtraceFilterFunctions(True)7090 elif(cmd == 'flistall'):7091 sysvals.getFtraceFilterFunctions(False)7092 elif(cmd == 'summary'):7093 runSummary(sysvals.outdir, True, genhtml)7094 elif(cmd in ['xon', 'xoff', 'xstandby', 'xsuspend', 'xinit', 'xreset']):7095 sysvals.verbose = True7096 ret = sysvals.displayControl(cmd[1:])7097 elif(cmd == 'xstat'):7098 pprint('Display Status: %s' % sysvals.displayControl('stat').upper())7099 elif(cmd == 'wificheck'):7100 dev = sysvals.checkWifi()7101 if dev:7102 print('%s is connected' % sysvals.wifiDetails(dev))7103 else:7104 print('No wifi connection found')7105 elif(cmd == 'cmdinfo'):7106 for out in sysvals.cmdinfo(False, True):7107 print('[%s - %s]\n%s\n' % out)7108 sys.exit(ret)7109 7110 # if instructed, re-analyze existing data files7111 if(sysvals.notestrun):7112 stamp = rerunTest(sysvals.outdir)7113 sysvals.outputResult(stamp)7114 sys.exit(0)7115 7116 # verify that we can run a test7117 error = statusCheck()7118 if(error):7119 doError(error)7120 7121 # extract mem/disk extra modes and convert7122 mode = sysvals.suspendmode7123 if mode.startswith('mem'):7124 memmode = mode.split('-', 1)[-1] if '-' in mode else 'deep'7125 if memmode == 'shallow':7126 mode = 'standby'7127 elif memmode == 's2idle':7128 mode = 'freeze'7129 else:7130 mode = 'mem'7131 sysvals.memmode = memmode7132 sysvals.suspendmode = mode7133 if mode.startswith('disk-'):7134 sysvals.diskmode = mode.split('-', 1)[-1]7135 sysvals.suspendmode = 'disk'7136 sysvals.systemInfo(dmidecode(sysvals.mempath))7137 7138 failcnt, ret = 0, 07139 if sysvals.multitest['run']:7140 # run multiple tests in a separate subdirectory7141 if not sysvals.outdir:7142 if 'time' in sysvals.multitest:7143 s = '-%dm' % sysvals.multitest['time']7144 else:7145 s = '-x%d' % sysvals.multitest['count']7146 sysvals.outdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S'+s)7147 if not os.path.isdir(sysvals.outdir):7148 os.makedirs(sysvals.outdir)7149 sysvals.sudoUserchown(sysvals.outdir)7150 finish = datetime.now()7151 if 'time' in sysvals.multitest:7152 finish += timedelta(minutes=sysvals.multitest['time'])7153 for i in range(sysvals.multitest['count']):7154 sysvals.multistat(True, i, finish)7155 if i != 0 and sysvals.multitest['delay'] > 0:7156 pprint('Waiting %d seconds...' % (sysvals.multitest['delay']))7157 time.sleep(sysvals.multitest['delay'])7158 fmt = 'suspend-%y%m%d-%H%M%S'7159 sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))7160 ret = runTest(i+1, not sysvals.verbose)7161 failcnt = 0 if not ret else failcnt + 17162 if sysvals.maxfail > 0 and failcnt >= sysvals.maxfail:7163 pprint('Maximum fail count of %d reached, aborting multitest' % (sysvals.maxfail))7164 break7165 sysvals.resetlog()7166 sysvals.multistat(False, i, finish)7167 if 'time' in sysvals.multitest and datetime.now() >= finish:7168 break7169 if not sysvals.skiphtml:7170 runSummary(sysvals.outdir, False, False)7171 sysvals.sudoUserchown(sysvals.outdir)7172 else:7173 if sysvals.outdir:7174 sysvals.testdir = sysvals.outdir7175 # run the test in the current directory7176 ret = runTest()7177 7178 # reset to default values after testing7179 if sysvals.display:7180 sysvals.displayControl('reset')7181 if sysvals.rs != 0:7182 sysvals.setRuntimeSuspend(False)7183 sys.exit(ret)7184