diff options
Diffstat (limited to 'tools/power/pm-graph/sleepgraph.py')
| -rwxr-xr-x | tools/power/pm-graph/sleepgraph.py | 2380 |
1 files changed, 1367 insertions, 1013 deletions
diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index 602e64b68ba7..1555b51a7d55 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -18,7 +18,7 @@ # # Links: # Home Page -# https://01.org/pm-graph +# https://www.intel.com/content/www/us/en/developer/topic-technology/open/pm-graph/overview.html # Source repo # git@github.com:intel/pm-graph # @@ -65,9 +65,15 @@ import gzip from threading import Thread from subprocess import call, Popen, PIPE import base64 +import traceback +debugtiming = False +mystarttime = time.time() def pprint(msg): - print(msg) + if debugtiming: + print('[%09.3f] %s' % (time.time()-mystarttime, msg)) + else: + print(msg) sys.stdout.flush() def ascii(text): @@ -81,19 +87,22 @@ def ascii(text): # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.6' + version = '5.13' ansi = False rs = 0 display = '' gzip = False sync = False wifi = False + netfix = False verbose = False testlog = True dmesglog = True ftracelog = False + acpidebug = True tstat = True - mindevlen = 0.0 + wifitrace = False + mindevlen = 0.0001 mincglen = 0.0 cgphase = '' cgtest = -1 @@ -107,14 +116,18 @@ class SystemValues: cpucount = 0 memtotal = 204800 memfree = 204800 + osversion = '' srgap = 0 cgexp = False testdir = '' outdir = '' - tpath = '/sys/kernel/debug/tracing/' + tpath = '/sys/kernel/tracing/' fpdtpath = '/sys/firmware/acpi/tables/FPDT' - epath = '/sys/kernel/debug/tracing/events/power/' + epath = '/sys/kernel/tracing/events/power/' pmdpath = '/sys/power/pm_debug_messages' + s0ixpath = '/sys/module/intel_pmc_core/parameters/warn_on_s0ix_failures' + s0ixres = '/sys/devices/system/cpu/cpuidle/low_power_idle_system_residency_us' + acpipath='/sys/module/acpi/parameters/debug_level' traceevents = [ 'suspend_resume', 'wakeup_source_activate', @@ -154,6 +167,7 @@ class SystemValues: ftop = False usetraceevents = False usetracemarkers = True + useftrace = True usekprobes = True usedevsrc = False useprocmon = False @@ -162,13 +176,14 @@ class SystemValues: devdump = False mixedphaseheight = True devprops = dict() + cfgdef = dict() platinfo = [] predelay = 0 postdelay = 0 - pmdebug = '' tmstart = 'SUSPEND START %Y%m%d-%H:%M:%S.%f' tmend = 'RESUME COMPLETE %Y%m%d-%H:%M:%S.%f' tracefuncs = { + 'async_synchronize_full': {}, 'sys_sync': {}, 'ksys_sync': {}, '__pm_notifier_call_chain': {}, @@ -195,13 +210,13 @@ class SystemValues: 'hibernate_preallocate_memory': {}, 'create_basic_memory_bitmaps': {}, 'swsusp_write': {}, - 'suspend_console': {}, + 'console_suspend_all': {}, 'acpi_pm_prepare': {}, 'syscore_suspend': {}, - 'arch_thaw_secondary_cpus_end': {}, + 'arch_enable_nonboot_cpus_end': {}, 'syscore_resume': {}, 'acpi_pm_finish': {}, - 'resume_console': {}, + 'console_resume_all': {}, 'acpi_pm_end': {}, 'pm_restore_gfp_mask': {}, 'thaw_processes': {}, @@ -222,7 +237,11 @@ class SystemValues: 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 }, 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 }, - 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, + 'usleep_range': { + 'func':'usleep_range_state', + 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, + 'ub': 1 + }, 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, 'acpi_os_stall': {'ub': 1}, 'rt_mutex_slowlock': {'ub': 1}, @@ -277,16 +296,24 @@ class SystemValues: 'intel_fbdev_set_suspend': {}, } infocmds = [ + [0, 'sysinfo', 'uname', '-a'], + [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'], [0, 'kparams', 'cat', '/proc/cmdline'], [0, 'mcelog', 'mcelog'], [0, 'pcidevices', 'lspci', '-tv'], - [0, 'usbdevices', 'lsusb', '-t'], + [0, 'usbdevices', 'lsusb', '-tv'], + [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'], + [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'], + [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'], + [0, 'ethtool', 'ethtool', '{ethdev}'], + [1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'], [1, 'interrupts', 'cat', '/proc/interrupts'], [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'], [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'], [2, 'suspendstats', 'sh', '-c', 'grep -v invalid /sys/power/suspend_stats/*'], [2, 'cpuidle', 'sh', '-c', 'grep -v invalid /sys/devices/system/cpu/cpu*/cpuidle/state*/s2idle/*'], [2, 'battery', 'sh', '-c', 'grep -v invalid /sys/class/power_supply/*/*'], + [2, 'thermal', 'sh', '-c', 'grep . /sys/class/thermal/thermal_zone*/temp'], ] cgblacklist = [] kprobes = dict() @@ -320,15 +347,21 @@ class SystemValues: if self.verbose or msg.startswith('WARNING:'): pprint(msg) def signalHandler(self, signum, frame): - if not self.result: - return signame = self.signames[signum] if signum in self.signames else 'UNKNOWN' - msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno) + if signame in ['SIGUSR1', 'SIGUSR2', 'SIGSEGV']: + traceback.print_stack() + stack = traceback.format_list(traceback.extract_stack()) + self.outputResult({'stack':stack}) + if signame == 'SIGUSR1': + return + msg = '%s caused a tool exit, line %d' % (signame, frame.f_lineno) + pprint(msg) self.outputResult({'error':msg}) + os.kill(os.getpid(), signal.SIGKILL) sys.exit(3) def signalHandlerInit(self): capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT', - 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM'] + 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM', 'USR1', 'USR2'] self.signames = dict() for i in capture: s = 'SIG'+i @@ -356,8 +389,19 @@ class SystemValues: self.outputResult({'error':msg}) sys.exit(1) return False - def usable(self, file): - return (os.path.exists(file) and os.path.getsize(file) > 0) + def usable(self, file, ishtml=False): + if not os.path.exists(file) or os.path.getsize(file) < 1: + return False + if ishtml: + try: + fp = open(file, 'r') + res = fp.read(1000) + fp.close() + except: + return False + if '<html>' not in res: + return False + return True def getExec(self, cmd): try: fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout @@ -387,11 +431,11 @@ class SystemValues: return value.format(**args) def setOutputFile(self): if self.dmesgfile != '': - m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile) + m = re.match(r'(?P<name>.*)_dmesg\.txt.*', self.dmesgfile) if(m): self.htmlfile = m.group('name')+'.html' if self.ftracefile != '': - m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile) + m = re.match(r'(?P<name>.*)_ftrace\.txt.*', self.ftracefile) if(m): self.htmlfile = m.group('name')+'.html' def systemInfo(self, info): @@ -411,12 +455,16 @@ class SystemValues: r = info['bios-release-date'] if 'bios-release-date' in info else '' self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \ (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree) + if self.osversion: + self.sysstamp += ' | os:%s' % self.osversion def printSystemInfo(self, fatal=False): self.rootCheck(True) out = dmidecode(self.mempath, fatal) if len(out) < 1: return fmt = '%-24s: %s' + if self.osversion: + print(fmt % ('os-version', self.osversion)) for name in sorted(out): print(fmt % (name, out[name])) print(fmt % ('cpucount', ('%d' % self.cpucount))) @@ -424,20 +472,25 @@ class SystemValues: print(fmt % ('memfree', ('%d kB' % self.memfree))) def cpuInfo(self): self.cpucount = 0 - fp = open('/proc/cpuinfo', 'r') - for line in fp: - if re.match('^processor[ \t]*:[ \t]*[0-9]*', line): - self.cpucount += 1 - fp.close() - fp = open('/proc/meminfo', 'r') - for line in fp: - m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line) - if m: - self.memtotal = int(m.group('sz')) - m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line) - if m: - self.memfree = int(m.group('sz')) - fp.close() + if os.path.exists('/proc/cpuinfo'): + with open('/proc/cpuinfo', 'r') as fp: + for line in fp: + if re.match(r'^processor[ \t]*:[ \t]*[0-9]*', line): + self.cpucount += 1 + if os.path.exists('/proc/meminfo'): + with open('/proc/meminfo', 'r') as fp: + for line in fp: + m = re.match(r'^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line) + if m: + self.memtotal = int(m.group('sz')) + m = re.match(r'^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line) + if m: + self.memfree = int(m.group('sz')) + if os.path.exists('/etc/os-release'): + with open('/etc/os-release', 'r') as fp: + for line in fp: + if line.startswith('PRETTY_NAME='): + self.osversion = line[12:].strip().replace('"', '') def initTestOutput(self, name): self.prefix = self.hostname v = open('/proc/version', 'r').read().strip() @@ -490,17 +543,17 @@ class SystemValues: call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True) def initdmesg(self): # get the latest time stamp from the dmesg log - fp = Popen('dmesg', stdout=PIPE).stdout + lines = Popen('dmesg', stdout=PIPE).stdout.readlines() ktime = '0' - for line in fp: + for line in reversed(lines): line = ascii(line).replace('\r\n', '') idx = line.find('[') if idx > 1: line = line[idx:] - m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if(m): ktime = m.group('ktime') - fp.close() + break self.dmesgstart = float(ktime) def getdmesg(self, testdata): op = self.writeDatafileHeader(self.dmesgfile, testdata) @@ -511,7 +564,7 @@ class SystemValues: idx = line.find('[') if idx > 1: line = line[idx:] - m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if(not m): continue ktime = float(m.group('ktime')) @@ -594,11 +647,11 @@ class SystemValues: # now process the args for arg in sorted(args): arglist[arg] = '' - m = re.match('.* '+arg+'=(?P<arg>.*) ', data); + m = re.match(r'.* '+arg+'=(?P<arg>.*) ', data); if m: arglist[arg] = m.group('arg') else: - m = re.match('.* '+arg+'=(?P<arg>.*)', data); + m = re.match(r'.* '+arg+'=(?P<arg>.*)', data); if m: arglist[arg] = m.group('arg') out = fmt.format(**arglist) @@ -696,6 +749,8 @@ class SystemValues: return False return True def fsetVal(self, val, path): + if not self.useftrace: + return False return self.setVal(val, self.tpath+path) def getVal(self, file): res = '' @@ -709,14 +764,14 @@ class SystemValues: pass return res def fgetVal(self, path): + if not self.useftrace: + return '' return self.getVal(self.tpath+path) def cleanupFtrace(self): - if(self.usecallgraph or self.usetraceevents or self.usedevsrc): + if self.useftrace: self.fsetVal('0', 'events/kprobes/enable') self.fsetVal('', 'kprobe_events') self.fsetVal('1024', 'buffer_size_kb') - if self.pmdebug: - self.setVal(self.pmdebug, self.pmdpath) def setupAllKprobes(self): for name in self.tracefuncs: self.defaultKprobe(name, self.tracefuncs[name]) @@ -734,17 +789,14 @@ class SystemValues: return True return False def initFtrace(self, quiet=False): + if not self.useftrace: + return if not quiet: sysvals.printSystemInfo(False) - pprint('INITIALIZING FTRACE...') + pprint('INITIALIZING FTRACE') # turn trace off self.fsetVal('0', 'tracing_on') self.cleanupFtrace() - # pm debug messages - pv = self.getVal(self.pmdpath) - if pv != '1': - self.setVal('1', self.pmdpath) - self.pmdebug = pv # set the trace clock to global self.fsetVal('global', 'trace_clock') self.fsetVal('nop', 'current_tracer') @@ -770,6 +822,10 @@ class SystemValues: # set trace type self.fsetVal('function_graph', 'current_tracer') self.fsetVal('', 'set_ftrace_filter') + # temporary hack to fix https://bugzilla.kernel.org/show_bug.cgi?id=212761 + fp = open(self.tpath+'set_ftrace_notrace', 'w') + fp.write('native_queued_spin_lock_slowpath\ndev_driver_string') + fp.close() # set trace format options self.fsetVal('print-parent', 'trace_options') self.fsetVal('funcgraph-abstime', 'trace_options') @@ -801,7 +857,7 @@ class SystemValues: for name in self.dev_tracefuncs: self.defaultKprobe(name, self.dev_tracefuncs[name]) if not quiet: - pprint('INITIALIZING KPROBES...') + pprint('INITIALIZING KPROBES') self.addKprobes(self.verbose) if(self.usetraceevents): # turn trace events on @@ -814,6 +870,11 @@ class SystemValues: # files needed for any trace data files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock', 'trace_marker', 'trace_options', 'tracing_on'] + # legacy check for old systems + if not os.path.exists(self.tpath+'trace'): + self.tpath = '/sys/kernel/debug/tracing/' + if not os.path.exists(self.epath): + self.epath = '/sys/kernel/debug/tracing/events/power/' # files needed for callgraph trace data tp = self.tpath if(self.usecallgraph): @@ -850,6 +911,8 @@ class SystemValues: fp.write('# turbostat %s\n' % test['turbo']) if 'wifi' in test: fp.write('# wifi %s\n' % test['wifi']) + if 'netfix' in test: + fp.write('# netfix %s\n' % test['netfix']) if test['error'] or len(testdata) > 1: fp.write('# enter_sleep_error %s\n' % test['error']) return fp @@ -864,11 +927,20 @@ class SystemValues: if num > 0: n = '%d' % num fp = open(self.result, 'a') + if 'stack' in testdata: + fp.write('Printing stack trace:\n') + for line in testdata['stack']: + fp.write(line) + fp.close() + self.sudoUserchown(self.result) + return if 'error' in testdata: fp.write('result%s: fail\n' % n) fp.write('error%s: %s\n' % (n, testdata['error'])) else: fp.write('result%s: pass\n' % n) + if 'mode' in testdata: + fp.write('mode%s: %s\n' % (n, testdata['mode'])) for v in ['suspend', 'resume', 'boot', 'lastinit']: if v in testdata: fp.write('%s%s: %.3f\n' % (v, n, testdata[v])) @@ -900,6 +972,16 @@ class SystemValues: if isgz: return gzip.open(filename, mode+'t') return open(filename, mode) + def putlog(self, filename, text): + with self.openlog(filename, 'a') as fp: + fp.write(text) + fp.close() + def dlog(self, text): + if not self.dmesgfile: + return + self.putlog(self.dmesgfile, '# %s\n' % text) + def flog(self, text): + self.putlog(self.ftracefile, text) def b64unzip(self, data): try: out = codecs.decode(base64.b64decode(data), 'zlib').decode() @@ -924,16 +1006,13 @@ class SystemValues: tp = TestProps() tf = self.openlog(self.ftracefile, 'r') for line in tf: - # determine the trace data type (required for further parsing) - m = re.match(tp.tracertypefmt, line) - if(m): - tp.setTracerType(m.group('t')) + if tp.stampInfo(line, self): continue # parse only valid lines, if this is not one move on m = re.match(tp.ftrace_line_fmt, line) if(not m or 'device_pm_callback_start' not in line): continue - m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg')); + m = re.match(r'.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg')); if(not m): continue dev = m.group('d') @@ -943,7 +1022,7 @@ class SystemValues: # now get the syspath for each target device for dirname, dirnames, filenames in os.walk('/sys/devices'): - if(re.match('.*/power', dirname) and 'async' in filenames): + if(re.match(r'.*/power', dirname) and 'async' in filenames): dev = dirname.split('/')[-2] if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)): props[dev].syspath = dirname[:-6] @@ -953,34 +1032,31 @@ class SystemValues: dirname = props[dev].syspath if not dirname or not os.path.exists(dirname): continue - with open(dirname+'/power/async') as fp: - text = fp.read() - props[dev].isasync = False - if 'enabled' in text: + props[dev].isasync = False + if os.path.exists(dirname+'/power/async'): + fp = open(dirname+'/power/async') + if 'enabled' in fp.read(): props[dev].isasync = True + fp.close() fields = os.listdir(dirname) - if 'product' in fields: - with open(dirname+'/product', 'rb') as fp: - props[dev].altname = ascii(fp.read()) - elif 'name' in fields: - with open(dirname+'/name', 'rb') as fp: - props[dev].altname = ascii(fp.read()) - elif 'model' in fields: - with open(dirname+'/model', 'rb') as fp: - props[dev].altname = ascii(fp.read()) - elif 'description' in fields: - with open(dirname+'/description', 'rb') as fp: - props[dev].altname = ascii(fp.read()) - elif 'id' in fields: - with open(dirname+'/id', 'rb') as fp: - props[dev].altname = ascii(fp.read()) - elif 'idVendor' in fields and 'idProduct' in fields: - idv, idp = '', '' - with open(dirname+'/idVendor', 'rb') as fp: - idv = ascii(fp.read()).strip() - with open(dirname+'/idProduct', 'rb') as fp: - idp = ascii(fp.read()).strip() - props[dev].altname = '%s:%s' % (idv, idp) + for file in ['product', 'name', 'model', 'description', 'id', 'idVendor']: + if file not in fields: + continue + try: + with open(os.path.join(dirname, file), 'rb') as fp: + props[dev].altname = ascii(fp.read()) + except: + continue + if file == 'idVendor': + idv, idp = props[dev].altname.strip(), '' + try: + with open(os.path.join(dirname, 'idProduct'), 'rb') as fp: + idp = ascii(fp.read()).strip() + except: + props[dev].altname = '' + break + props[dev].altname = '%s:%s' % (idv, idp) + break if props[dev].altname: out = props[dev].altname.strip().replace('\n', ' ')\ .replace(',', ' ').replace(';', ' ') @@ -995,9 +1071,7 @@ class SystemValues: # add a line for each of these commands with their outputs for name, cmdline, info in cmdafter: footer += '# platform-%s: %s | %s\n' % (name, cmdline, self.b64zip(info)) - - with self.openlog(self.ftracefile, 'a') as fp: - fp.write(footer) + self.flog(footer) return True def commonPrefix(self, list): if len(list) < 2: @@ -1028,17 +1102,35 @@ class SystemValues: else: out[data[0].strip()] = data[1] return out + def cmdinfovar(self, arg): + if arg == 'ethdev': + try: + cmd = [self.getExec('ip'), '-4', '-o', '-br', 'addr'] + fp = Popen(cmd, stdout=PIPE, stderr=PIPE).stdout + info = ascii(fp.read()).strip() + fp.close() + except: + return 'iptoolcrash' + for line in info.split('\n'): + if line[0] == 'e' and 'UP' in line: + return line.split()[0] + return 'nodevicefound' + return 'unknown' def cmdinfo(self, begin, debug=False): out = [] if begin: self.cmd1 = dict() for cargs in self.infocmds: - delta, name = cargs[0], cargs[1] - cmdline, cmdpath = ' '.join(cargs[2:]), self.getExec(cargs[2]) + delta, name, args = cargs[0], cargs[1], cargs[2:] + for i in range(len(args)): + if args[i][0] == '{' and args[i][-1] == '}': + args[i] = self.cmdinfovar(args[i][1:-1]) + cmdline, cmdpath = ' '.join(args[0:]), self.getExec(args[0]) if not cmdpath or (begin and not delta): continue + self.dlog('[%s]' % cmdline) try: - fp = Popen([cmdpath]+cargs[3:], stdout=PIPE, stderr=PIPE).stdout + fp = Popen([cmdpath]+args[1:], stdout=PIPE, stderr=PIPE).stdout info = ascii(fp.read()).strip() fp.close() except: @@ -1047,7 +1139,7 @@ class SystemValues: self.cmd1[name] = self.dictify(info, delta) elif not debug and delta and name in self.cmd1: before, after = self.cmd1[name], self.dictify(info, delta) - dinfo = ('\t%s\n' % before['@']) if '@' in before else '' + dinfo = ('\t%s\n' % before['@']) if '@' in before and len(before) > 1 else '' prefix = self.commonPrefix(list(before.keys())) for key in sorted(before): if key in after and before[key] != after[key]: @@ -1063,6 +1155,38 @@ class SystemValues: else: out.append((name, cmdline, '\tnothing' if not info else info)) return out + def testVal(self, file, fmt='basic', value=''): + if file == 'restoreall': + for f in self.cfgdef: + if os.path.exists(f): + fp = open(f, 'w') + fp.write(self.cfgdef[f]) + fp.close() + self.cfgdef = dict() + elif value and os.path.exists(file): + fp = open(file, 'r+') + if fmt == 'radio': + m = re.match(r'.*\[(?P<v>.*)\].*', fp.read()) + if m: + self.cfgdef[file] = m.group('v') + elif fmt == 'acpi': + line = fp.read().strip().split('\n')[-1] + m = re.match(r'.* (?P<v>[0-9A-Fx]*) .*', line) + if m: + self.cfgdef[file] = m.group('v') + else: + self.cfgdef[file] = fp.read().strip() + fp.write(value) + fp.close() + def s0ixSupport(self): + if not os.path.exists(self.s0ixres) or not os.path.exists(self.mempowerfile): + return False + fp = open(sysvals.mempowerfile, 'r') + data = fp.read().strip() + fp.close() + if '[s2idle]' in data: + return True + return False def haveTurbostat(self): if not self.tstat: return False @@ -1072,39 +1196,49 @@ class SystemValues: fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr out = ascii(fp.read()).strip() fp.close() - if re.match('turbostat version .*', out): + if re.match(r'turbostat version .*', out): self.vprint(out) return True return False - def turbostat(self): + def turbostat(self, s0ixready): cmd = self.getExec('turbostat') rawout = keyline = valline = '' fullcmd = '%s -q -S echo freeze > %s' % (cmd, self.powerfile) - fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE).stderr - for line in fp: + fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE) + for line in fp.stderr: line = ascii(line) rawout += line if keyline and valline: continue - if re.match('(?i)Avg_MHz.*', line): + if re.match(r'(?i)Avg_MHz.*', line): keyline = line.strip().split() elif keyline: valline = line.strip().split() - fp.close() + fp.wait() if not keyline or not valline or len(keyline) != len(valline): errmsg = 'unrecognized turbostat output:\n'+rawout.strip() self.vprint(errmsg) if not self.verbose: pprint(errmsg) - return '' + return (fp.returncode, '') if self.verbose: pprint(rawout.strip()) out = [] for key in keyline: idx = keyline.index(key) val = valline[idx] + if key == 'SYS%LPI' and not s0ixready and re.match(r'^[0\.]*$', val): + continue out.append('%s=%s' % (key, val)) - return '|'.join(out) + return (fp.returncode, '|'.join(out)) + def netfixon(self, net='both'): + cmd = self.getExec('netfix') + if not cmd: + return '' + fp = Popen([cmd, '-s', net, 'on'], stdout=PIPE, stderr=PIPE).stdout + out = ascii(fp.read()).strip() + fp.close() + return out def wifiDetails(self, dev): try: info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip() @@ -1121,12 +1255,12 @@ class SystemValues: except: return '' for line in reversed(w.split('\n')): - m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', w.split('\n')[-1]) + m = re.match(r' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', line) if not m or (dev and dev != m.group('dev')): continue return m.group('dev') return '' - def pollWifi(self, dev, timeout=60): + def pollWifi(self, dev, timeout=10): start = time.time() while (time.time() - start) < timeout: w = self.checkWifi(dev) @@ -1150,14 +1284,14 @@ class SystemValues: return arr = msg.split() for j in range(len(arr)): - if re.match('^[0-9,\-\.]*$', arr[j]): - arr[j] = '[0-9,\-\.]*' + if re.match(r'^[0-9,\-\.]*$', arr[j]): + arr[j] = r'[0-9,\-\.]*' else: arr[j] = arr[j]\ - .replace('\\', '\\\\').replace(']', '\]').replace('[', '\[')\ - .replace('.', '\.').replace('+', '\+').replace('*', '\*')\ - .replace('(', '\(').replace(')', '\)').replace('}', '\}')\ - .replace('{', '\{') + .replace('\\', r'\\\\').replace(']', r'\]').replace('[', r'\[')\ + .replace('.', r'\.').replace('+', r'\+').replace('*', r'\*')\ + .replace('(', r'\(').replace(')', r'\)').replace('}', r'\}')\ + .replace('{', r'\{') mstr = ' *'.join(arr) entry = { 'line': msg, @@ -1204,15 +1338,80 @@ class SystemValues: self.multitest[sz] *= 1440 elif unit == 'h': self.multitest[sz] *= 60 + def displayControl(self, cmd): + xset, ret = 'timeout 10 xset -d :0.0 {0}', 0 + if self.sudouser: + xset = 'sudo -u %s %s' % (self.sudouser, xset) + if cmd == 'init': + ret = call(xset.format('dpms 0 0 0'), shell=True) + if not ret: + ret = call(xset.format('s off'), shell=True) + elif cmd == 'reset': + ret = call(xset.format('s reset'), shell=True) + elif cmd in ['on', 'off', 'standby', 'suspend']: + b4 = self.displayControl('stat') + ret = call(xset.format('dpms force %s' % cmd), shell=True) + if not ret: + curr = self.displayControl('stat') + self.vprint('Display Switched: %s -> %s' % (b4, curr)) + if curr != cmd: + self.vprint('WARNING: Display failed to change to %s' % cmd) + if ret: + self.vprint('WARNING: Display failed to change to %s with xset' % cmd) + return ret + elif cmd == 'stat': + fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout + ret = 'unknown' + for line in fp: + m = re.match(r'[\s]*Monitor is (?P<m>.*)', ascii(line)) + if(m and len(m.group('m')) >= 2): + out = m.group('m').lower() + ret = out[3:] if out[0:2] == 'in' else out + break + fp.close() + return ret + def setRuntimeSuspend(self, before=True): + if before: + # runtime suspend disable or enable + if self.rs > 0: + self.rstgt, self.rsval, self.rsdir = 'on', 'auto', 'enabled' + else: + self.rstgt, self.rsval, self.rsdir = 'auto', 'on', 'disabled' + pprint('CONFIGURING RUNTIME SUSPEND...') + self.rslist = deviceInfo(self.rstgt) + for i in self.rslist: + self.setVal(self.rsval, i) + pprint('runtime suspend %s on all devices (%d changed)' % (self.rsdir, len(self.rslist))) + pprint('waiting 5 seconds...') + time.sleep(5) + else: + # runtime suspend re-enable or re-disable + for i in self.rslist: + self.setVal(self.rstgt, i) + pprint('runtime suspend settings restored on %d devices' % len(self.rslist)) + def start(self, pm): + if self.useftrace: + self.dlog('start ftrace tracing') + self.fsetVal('1', 'tracing_on') + if self.useprocmon: + self.dlog('start the process monitor') + pm.start() + def stop(self, pm): + if self.useftrace: + if self.useprocmon: + self.dlog('stop the process monitor') + pm.stop() + self.dlog('stop ftrace tracing') + self.fsetVal('0', 'tracing_on') sysvals = SystemValues() switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0'] switchoff = ['disable', 'off', 'false', '0'] suspendmodename = { - 'freeze': 'Freeze (S0)', - 'standby': 'Standby (S1)', - 'mem': 'Suspend (S3)', - 'disk': 'Hibernate (S4)' + 'standby': 'standby (S1)', + 'freeze': 'freeze (S2idle)', + 'mem': 'suspend (S3)', + 'disk': 'hibernate (S4)' } # Class: DevProps @@ -1244,8 +1443,8 @@ class DevProps: if self.xtraclass: return ' '+self.xtraclass if self.isasync: - return ' async_device' - return ' sync_device' + return ' (async)' + return ' (sync)' # Class: DeviceNode # Description: @@ -1294,6 +1493,7 @@ class Data: errlist = { 'HWERROR' : r'.*\[ *Hardware Error *\].*', 'FWBUG' : r'.*\[ *Firmware Bug *\].*', + 'TASKFAIL': r'.*Freezing .*after *.*', 'BUG' : r'(?i).*\bBUG\b.*', 'ERROR' : r'(?i).*\bERROR\b.*', 'WARNING' : r'(?i).*\bWARNING\b.*', @@ -1301,8 +1501,9 @@ class Data: 'FAIL' : r'(?i).*\bFAILED\b.*', 'INVALID' : r'(?i).*\bINVALID\b.*', 'CRASH' : r'(?i).*\bCRASHED\b.*', + 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*', + 'ABORT' : r'(?i).*\bABORT\b.*', 'IRQ' : r'.*\bgenirq: .*', - 'TASKFAIL': r'.*Freezing of tasks *.*', 'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*', 'DISKFULL': r'.*\bNo space left on device.*', 'USBERR' : r'.*usb .*device .*, error [0-9-]*', @@ -1358,11 +1559,11 @@ class Data: if self.dmesg[p]['order'] == order: return p return '' - def lastPhase(self): + def lastPhase(self, depth=1): plist = self.sortedPhases() - if len(plist) < 1: + if len(plist) < depth: return '' - return plist[-1] + return plist[-1*depth] def turbostatInfo(self): tp = TestProps() out = {'syslpi':'N/A','pkgpc10':'N/A'} @@ -1382,10 +1583,13 @@ class Data: if len(self.dmesgtext) < 1 and sysvals.dmesgfile: lf = sysvals.openlog(sysvals.dmesgfile, 'r') i = 0 + tp = TestProps() list = [] for line in lf: i += 1 - m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + if tp.stampInfo(line, sysvals): + continue + m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if not m: continue t = float(m.group('ktime')) @@ -1393,22 +1597,22 @@ class Data: continue dir = 'suspend' if t < self.tSuspended else 'resume' msg = m.group('msg') - if re.match('capability: warning: .*', msg): + if re.match(r'capability: warning: .*', msg): continue for err in self.errlist: if re.match(self.errlist[err], msg): list.append((msg, err, dir, t, i, i)) self.kerror = True break - msglist = [] + tp.msglist = [] for msg, type, dir, t, idx1, idx2 in list: - msglist.append(msg) + tp.msglist.append(msg) self.errorinfo[dir].append((type, t, idx1, idx2)) if self.kerror: sysvals.dmesglog = True if len(self.dmesgtext) < 1 and sysvals.dmesgfile: lf.close() - return msglist + return tp def setStart(self, time, msg=''): self.start = time if msg: @@ -1439,7 +1643,7 @@ class Data: pend = self.dmesg[phase]['end'] if start <= pend: return phase - return 'resume_complete' + return 'resume_complete' if 'resume_complete' in self.dmesg else '' def sourceDevice(self, phaselist, start, end, pid, type): tgtdev = '' for phase in phaselist: @@ -1482,6 +1686,8 @@ class Data: else: threadname = '%s-%d' % (proc, pid) tgtphase = self.sourcePhase(start) + if not tgtphase: + return False self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '') return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) # this should not happen @@ -1496,19 +1702,20 @@ class Data: ubiquitous = False if kprobename in dtf and 'ub' in dtf[kprobename]: ubiquitous = True - title = cdata+' '+rdata - mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)' - m = re.match(mstr, title) - if m: - c = m.group('caller') - a = m.group('args').strip() - r = m.group('ret') + mc = re.match(r'\(.*\) *(?P<args>.*)', cdata) + mr = re.match(r'\((?P<caller>\S*).* arg1=(?P<ret>.*)', rdata) + if mc and mr: + c = mr.group('caller').split('+')[0] + a = mc.group('args').strip() + r = mr.group('ret') if len(r) > 6: r = '' else: r = 'ret=%s ' % r if ubiquitous and c in dtf and 'ub' in dtf[c]: return False + else: + return False color = sysvals.kprobeColor(kprobename) e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color) tgtdev['src'].append(e) @@ -1623,6 +1830,16 @@ class Data: if('src' in d): for e in d['src']: e.time = self.trimTimeVal(e.time, t0, dT, left) + e.end = self.trimTimeVal(e.end, t0, dT, left) + e.length = e.end - e.time + if('cpuexec' in d): + cpuexec = dict() + for e in d['cpuexec']: + c0, cN = e + c0 = self.trimTimeVal(c0, t0, dT, left) + cN = self.trimTimeVal(cN, t0, dT, left) + cpuexec[(c0, cN)] = d['cpuexec'][e] + d['cpuexec'] = cpuexec for dir in ['suspend', 'resume']: list = [] for e in self.errorinfo[dir]: @@ -1637,10 +1854,20 @@ class Data: if 'resume_machine' in phase and 'suspend_machine' in lp: tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start'] tL = tR - tS - if tL > 0: - left = True if tR > tZero else False - self.trimTime(tS, tL, left) - self.tLow.append('%.0f'%(tL*1000)) + if tL <= 0: + continue + left = True if tR > tZero else False + self.trimTime(tS, tL, left) + if 'waking' in self.dmesg[lp]: + tCnt = self.dmesg[lp]['waking'][0] + if self.dmesg[lp]['waking'][1] >= 0.001: + tTry = '%.0f' % (round(self.dmesg[lp]['waking'][1] * 1000)) + else: + tTry = '%.3f' % (self.dmesg[lp]['waking'][1] * 1000) + text = '%.0f (%s ms waking %d times)' % (tL * 1000, tTry, tCnt) + else: + text = '%.0f' % (tL * 1000) + self.tLow.append(text) lp = phase def getMemTime(self): if not self.hwstart or not self.hwend: @@ -1651,9 +1878,9 @@ class Data: hwr = self.hwend - timedelta(microseconds=rtime) self.tLow.append('%.0f'%((hwr - hws).total_seconds() * 1000)) def getTimeValues(self): - sktime = (self.tSuspended - self.tKernSus) * 1000 - rktime = (self.tKernRes - self.tResumed) * 1000 - return (sktime, rktime) + s = (self.tSuspended - self.tKernSus) * 1000 + r = (self.tKernRes - self.tResumed) * 1000 + return (max(s, 0), max(r, 0)) def setPhase(self, phase, ktime, isbegin, order=-1): if(isbegin): # phase start over current phase @@ -1776,7 +2003,7 @@ class Data: length = -1.0 if(start >= 0 and end >= 0): length = end - start - if pid == -2: + if pid >= -2: i = 2 origname = name while(name in list): @@ -1789,6 +2016,15 @@ class Data: if color: list[name]['color'] = color return name + def findDevice(self, phase, name): + list = self.dmesg[phase]['list'] + mydev = '' + for devname in sorted(list): + if name == devname or re.match(r'^%s\[(?P<num>[0-9]*)\]$' % name, devname): + mydev = devname + if mydev: + return list[mydev] + return False def deviceChildren(self, devname, phase): devlist = [] list = self.dmesg[phase]['list'] @@ -1886,7 +2122,7 @@ class Data: for dev in sorted(list): pdev = list[dev]['par'] pid = list[dev]['pid'] - if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): + if(pid < 0 or re.match(r'[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): continue if pdev and pdev not in real and pdev not in rootlist: rootlist.append(pdev) @@ -1904,7 +2140,7 @@ class Data: for dev in list: length = (list[dev]['end'] - list[dev]['start']) * 1000 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal) - if width != '0.000000' and length >= mindevlen: + if length >= mindevlen: devlist.append(dev) self.tdevlist[phase] = devlist def addHorizontalDivider(self, devname, devend): @@ -1918,75 +2154,43 @@ class Data: return d def addProcessUsageEvent(self, name, times): # get the start and end times for this process - maxC = 0 - tlast = 0 - start = -1 - end = -1 + cpuexec = dict() + tlast = start = end = -1 for t in sorted(times): - if tlast == 0: + if tlast < 0: tlast = t continue - if name in self.pstl[t]: - if start == -1 or tlast < start: + if name in self.pstl[t] and self.pstl[t][name] > 0: + if start < 0: start = tlast - if end == -1 or t > end: - end = t + end, key = t, (tlast, t) + maxj = (t - tlast) * 1024.0 + cpuexec[key] = min(1.0, float(self.pstl[t][name]) / maxj) tlast = t - if start == -1 or end == -1: - return 0 + if start < 0 or end < 0: + return # add a new action for this process and get the object out = self.newActionGlobal(name, start, end, -3) - if not out: - return 0 - phase, devname = out - dev = self.dmesg[phase]['list'][devname] - # get the cpu exec data - tlast = 0 - clast = 0 - cpuexec = dict() - for t in sorted(times): - if tlast == 0 or t <= start or t > end: - tlast = t - continue - list = self.pstl[t] - c = 0 - if name in list: - c = list[name] - if c > maxC: - maxC = c - if c != clast: - key = (tlast, t) - cpuexec[key] = c - tlast = t - clast = c - dev['cpuexec'] = cpuexec - return maxC + if out: + phase, devname = out + dev = self.dmesg[phase]['list'][devname] + dev['cpuexec'] = cpuexec def createProcessUsageEvents(self): - # get an array of process names - proclist = [] + # get an array of process names and times + proclist = {'sus': dict(), 'res': dict()} + tdata = {'sus': [], 'res': []} for t in sorted(self.pstl): - pslist = self.pstl[t] - for ps in sorted(pslist): - if ps not in proclist: - proclist.append(ps) - # get a list of data points for suspend and resume - tsus = [] - tres = [] - for t in sorted(self.pstl): - if t < self.tSuspended: - tsus.append(t) - else: - tres.append(t) + dir = 'sus' if t < self.tSuspended else 'res' + for ps in sorted(self.pstl[t]): + if ps not in proclist[dir]: + proclist[dir][ps] = 0 + tdata[dir].append(t) # process the events for suspend and resume - if len(proclist) > 0: + if len(proclist['sus']) > 0 or len(proclist['res']) > 0: sysvals.vprint('Process Execution:') - for ps in proclist: - c = self.addProcessUsageEvent(ps, tsus) - if c > 0: - sysvals.vprint('%25s (sus): %d' % (ps, c)) - c = self.addProcessUsageEvent(ps, tres) - if c > 0: - sysvals.vprint('%25s (res): %d' % (ps, c)) + for dir in ['sus', 'res']: + for ps in sorted(proclist[dir]): + self.addProcessUsageEvent(ps, tdata[dir]) def handleEndMarker(self, time, msg=''): dm = self.dmesg self.setEnd(time, msg) @@ -2008,6 +2212,30 @@ class Data: # set resume complete to end at end marker if 'resume_complete' in dm: dm['resume_complete']['end'] = time + def initcall_debug_call(self, line, quick=False): + m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + r'PM: *calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) + if not m: + m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + r'calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) + if not m: + m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ + r'(?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)', line) + if m: + return True if quick else m.group('t', 'f', 'n', 'p') + return False if quick else ('', '', '', '') + def initcall_debug_return(self, line, quick=False): + m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: PM: '+\ + r'.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) + if not m: + m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + r'.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) + if not m: + m = re.match(r'.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ + r'(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', line) + if m: + return True if quick else m.group('t', 'f', 'dt') + return False if quick else ('', '', '') def debugPrint(self): for p in self.sortedPhases(): list = self.dmesg[p]['list'] @@ -2089,28 +2317,28 @@ class FTraceLine: if not m and not d: return # is this a trace event - if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)): + if(d == 'traceevent' or re.match(r'^ *\/\* *(?P<msg>.*) \*\/ *$', m)): if(d == 'traceevent'): # nop format trace event msg = m else: # function_graph format trace event - em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m) + em = re.match(r'^ *\/\* *(?P<msg>.*) \*\/ *$', m) msg = em.group('msg') - emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg) + emm = re.match(r'^(?P<call>.*?): (?P<msg>.*)', msg) if(emm): self.name = emm.group('msg') self.type = emm.group('call') else: self.name = msg - km = re.match('^(?P<n>.*)_cal$', self.type) + km = re.match(r'^(?P<n>.*)_cal$', self.type) if km: self.fcall = True self.fkprobe = True self.type = km.group('n') return - km = re.match('^(?P<n>.*)_ret$', self.type) + km = re.match(r'^(?P<n>.*)_ret$', self.type) if km: self.freturn = True self.fkprobe = True @@ -2122,7 +2350,7 @@ class FTraceLine: if(d): self.length = float(d)/1000000 # the indentation determines the depth - match = re.match('^(?P<d> *)(?P<o>.*)$', m) + match = re.match(r'^(?P<d> *)(?P<o>.*)$', m) if(not match): return self.depth = self.getDepth(match.group('d')) @@ -2132,7 +2360,7 @@ class FTraceLine: self.freturn = True if(len(m) > 1): # includes comment with function name - match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m) + match = re.match(r'^} *\/\* *(?P<n>.*) *\*\/$', m) if(match): self.name = match.group('n').strip() # function call @@ -2140,13 +2368,13 @@ class FTraceLine: self.fcall = True # function call with children if(m[-1] == '{'): - match = re.match('^(?P<n>.*) *\(.*', m) + match = re.match(r'^(?P<n>.*) *\(.*', m) if(match): self.name = match.group('n').strip() # function call with no children (leaf) elif(m[-1] == ';'): self.freturn = True - match = re.match('^(?P<n>.*) *\(.*', m) + match = re.match(r'^(?P<n>.*) *\(.*', m) if(match): self.name = match.group('n').strip() # something else (possibly a trace marker) @@ -2180,7 +2408,7 @@ class FTraceLine: return False else: if(self.type == 'suspend_resume' and - re.match('suspend_enter\[.*\] begin', self.name)): + re.match(r'suspend_enter\[.*\] begin', self.name)): return True return False def endMarker(self): @@ -2193,7 +2421,7 @@ class FTraceLine: return False else: if(self.type == 'suspend_resume' and - re.match('thaw_processes\[.*\] end', self.name)): + re.match(r'thaw_processes\[.*\] end', self.name)): return True return False @@ -2548,7 +2776,8 @@ class Timeline: def createHeader(self, sv, stamp): if(not stamp['time']): return - self.html += '<div class="version"><a href="https://01.org/pm-graph">%s v%s</a></div>' \ + self.html += '<div class="version"><a href="https://www.intel.com/content/www/'+\ + 'us/en/developer/topic-technology/open/pm-graph/overview.html">%s v%s</a></div>' \ % (sv.title, sv.version) if sv.logmsg and sv.testlog: self.html += '<button id="showtest" class="logbtn btnfmt">log</button>' @@ -2771,27 +3000,33 @@ class Timeline: # Description: # A list of values describing the properties of these test runs class TestProps: - stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ - '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ - ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' - wififmt = '^# wifi *(?P<d>\S*) *(?P<s>\S*) *(?P<t>[0-9\.]+).*' - tstatfmt = '^# turbostat (?P<t>\S*)' - testerrfmt = '^# enter_sleep_error (?P<e>.*)' - sysinfofmt = '^# sysinfo .*' - cmdlinefmt = '^# command \| (?P<cmd>.*)' - devpropfmt = '# Device Properties: .*' - pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9]*): (?P<info>.*)' - tracertypefmt = '# tracer: (?P<t>.*)' - firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' - procexecfmt = 'ps - (?P<ps>.*)$' + stampfmt = r'# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ + r'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ + r' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' + wififmt = r'^# wifi *(?P<d>\S*) *(?P<s>\S*) *(?P<t>[0-9\.]+).*' + tstatfmt = r'^# turbostat (?P<t>\S*)' + testerrfmt = r'^# enter_sleep_error (?P<e>.*)' + sysinfofmt = r'^# sysinfo .*' + cmdlinefmt = r'^# command \| (?P<cmd>.*)' + kparamsfmt = r'^# kparams \| (?P<kp>.*)' + devpropfmt = r'# Device Properties: .*' + pinfofmt = r'# platform-(?P<val>[a-z,A-Z,0-9,_]*): (?P<info>.*)' + tracertypefmt = r'# tracer: (?P<t>.*)' + firmwarefmt = r'# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' + procexecfmt = r'ps - (?P<ps>.*)$' + procmultifmt = r'@(?P<n>[0-9]*)\|(?P<ps>.*)$' ftrace_line_fmt_fg = \ - '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ - ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ - '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' + r'^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ + r' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ + r'[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' ftrace_line_fmt_nop = \ - ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ - '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ - '(?P<msg>.*)' + r' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ + r'(?P<flags>\S*) *(?P<time>[0-9\.]*): *'+\ + r'(?P<msg>.*)' + machinesuspend = r'machine_suspend\[.*' + multiproclist = dict() + multiproctime = 0.0 + multiproccnt = 0 def __init__(self): self.stamp = '' self.sysinfo = '' @@ -2812,16 +3047,13 @@ class TestProps: self.ftrace_line_fmt = self.ftrace_line_fmt_nop else: doError('Invalid tracer format: [%s]' % tracer) - def stampInfo(self, line): + def stampInfo(self, line, sv): if re.match(self.stampfmt, line): self.stamp = line return True elif re.match(self.sysinfofmt, line): self.sysinfo = line return True - elif re.match(self.cmdlinefmt, line): - self.cmdline = line - return True elif re.match(self.tstatfmt, line): self.turbostat.append(line) return True @@ -2834,6 +3066,20 @@ class TestProps: elif re.match(self.firmwarefmt, line): self.fwdata.append(line) return True + elif(re.match(self.devpropfmt, line)): + self.parseDevprops(line, sv) + return True + elif(re.match(self.pinfofmt, line)): + self.parsePlatformInfo(line, sv) + return True + m = re.match(self.cmdlinefmt, line) + if m: + self.cmdline = m.group('cmd') + return True + m = re.match(self.tracertypefmt, line) + if(m): + self.setTracerType(m.group('t')) + return True return False def parseStamp(self, data, sv): # global test data @@ -2858,19 +3104,21 @@ class TestProps: data.stamp[key] = val sv.hostname = data.stamp['host'] sv.suspendmode = data.stamp['mode'] + if sv.suspendmode == 'freeze': + self.machinesuspend = r'timekeeping_freeze\[.*' + else: + self.machinesuspend = r'machine_suspend\[.*' if sv.suspendmode == 'command' and sv.ftracefile != '': modes = ['on', 'freeze', 'standby', 'mem', 'disk'] - fp = sysvals.openlog(sv.ftracefile, 'r') + fp = sv.openlog(sv.ftracefile, 'r') for line in fp: - m = re.match('.* machine_suspend\[(?P<mode>.*)\]', line) + m = re.match(r'.* machine_suspend\[(?P<mode>.*)\]', line) if m and m.group('mode') in ['1', '2', '3', '4']: sv.suspendmode = modes[int(m.group('mode'))] data.stamp['mode'] = sv.suspendmode break fp.close() - m = re.match(self.cmdlinefmt, self.cmdline) - if m: - sv.cmdline = m.group('cmd') + sv.cmdline = self.cmdline if not sv.stamp: sv.stamp = data.stamp # firmware data @@ -2949,6 +3197,7 @@ class TestRun: self.ttemp = dict() class ProcessMonitor: + maxchars = 512 def __init__(self): self.proclist = dict() self.running = False @@ -2974,19 +3223,23 @@ class ProcessMonitor: if ujiff > 0 or kjiff > 0: running[pid] = ujiff + kjiff process.wait() - out = '' + out = [''] for pid in running: jiffies = running[pid] val = self.proclist[pid] - if out: - out += ',' - out += '%s-%s %d' % (val['name'], pid, jiffies) - return 'ps - '+out + if len(out[-1]) > self.maxchars: + out.append('') + elif len(out[-1]) > 0: + out[-1] += ',' + out[-1] += '%s-%s %d' % (val['name'], pid, jiffies) + if len(out) > 1: + for line in out: + sysvals.fsetVal('ps - @%d|%s' % (len(out), line), 'trace_marker') + else: + sysvals.fsetVal('ps - %s' % out[0], 'trace_marker') def processMonitor(self, tid): while self.running: - out = self.procstat() - if out: - sysvals.fsetVal(out, 'trace_marker') + self.procstat() def start(self): self.thread = Thread(target=self.processMonitor, args=(0,)) self.running = True @@ -3002,7 +3255,7 @@ class ProcessMonitor: # markers, and/or kprobes required for primary parsing. def doesTraceLogHaveTraceEvents(): kpcheck = ['_cal: (', '_ret: ('] - techeck = ['suspend_resume', 'device_pm_callback'] + techeck = ['suspend_resume', 'device_pm_callback', 'tracing_mark_write'] tmcheck = ['SUSPEND START', 'RESUME COMPLETE'] sysvals.usekprobes = False fp = sysvals.openlog(sysvals.ftracefile, 'r') @@ -3025,12 +3278,11 @@ def doesTraceLogHaveTraceEvents(): check.remove(i) tmcheck = check fp.close() - sysvals.usetraceevents = True if len(techeck) < 2 else False + sysvals.usetraceevents = True if len(techeck) < 3 else False sysvals.usetracemarkers = True if len(tmcheck) == 0 else False # Function: appendIncompleteTraceLog # Description: -# [deprecated for kernel 3.15 or newer] # Adds callgraph data which lacks trace event data. This is only # for timelines generated from 3.15 or older # Arguments: @@ -3052,20 +3304,7 @@ def appendIncompleteTraceLog(testruns): for line in tf: # remove any latent carriage returns line = line.replace('\r\n', '') - if tp.stampInfo(line): - continue - # determine the trace data type (required for further parsing) - m = re.match(tp.tracertypefmt, line) - if(m): - tp.setTracerType(m.group('t')) - continue - # device properties line - if(re.match(tp.devpropfmt, line)): - tp.parseDevprops(line, sysvals) - continue - # platform info line - if(re.match(tp.pinfofmt, line)): - tp.parsePlatformInfo(line, sysvals) + if tp.stampInfo(line, sysvals): continue # parse only valid lines, if this is not one move on m = re.match(tp.ftrace_line_fmt, line) @@ -3145,6 +3384,61 @@ def appendIncompleteTraceLog(testruns): dev['ftrace'] = cg break +# Function: loadTraceLog +# Description: +# load the ftrace file into memory and fix up any ordering issues +# Output: +# TestProps instance and an array of lines in proper order +def loadTraceLog(): + tp, data, lines, trace = TestProps(), dict(), [], [] + tf = sysvals.openlog(sysvals.ftracefile, 'r') + for line in tf: + # remove any latent carriage returns + line = line.replace('\r\n', '') + if tp.stampInfo(line, sysvals): + continue + # ignore all other commented lines + if line[0] == '#': + continue + # ftrace line: parse only valid lines + m = re.match(tp.ftrace_line_fmt, line) + if(not m): + continue + dur = m.group('dur') if tp.cgformat else 'traceevent' + info = (m.group('time'), m.group('proc'), m.group('pid'), + m.group('msg'), dur) + # group the data by timestamp + t = float(info[0]) + if t in data: + data[t].append(info) + else: + data[t] = [info] + # we only care about trace event ordering + if (info[3].startswith('suspend_resume:') or \ + info[3].startswith('tracing_mark_write:')) and t not in trace: + trace.append(t) + tf.close() + for t in sorted(data): + first, last, blk = [], [], data[t] + if len(blk) > 1 and t in trace: + # move certain lines to the start or end of a timestamp block + for i in range(len(blk)): + if 'SUSPEND START' in blk[i][3]: + first.append(i) + elif re.match(r'.* timekeeping_freeze.*begin', blk[i][3]): + last.append(i) + elif re.match(r'.* timekeeping_freeze.*end', blk[i][3]): + first.append(i) + elif 'RESUME COMPLETE' in blk[i][3]: + last.append(i) + if len(first) == 1 and len(last) == 0: + blk.insert(0, blk.pop(first[0])) + elif len(last) == 1 and len(first) == 0: + blk.append(blk.pop(last[0])) + for info in blk: + lines.append(info) + return (tp, lines) + # Function: parseTraceLog # Description: # Analyze an ftrace log output file generated from this app during @@ -3165,51 +3459,17 @@ def parseTraceLog(live=False): tracewatch = ['irq_wakeup'] if sysvals.usekprobes: tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', - 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', - 'CPU_OFF', 'timekeeping_freeze', 'acpi_suspend'] + 'syscore_resume', 'console_resume_all', 'thaw_processes', 'CPU_ON', + 'CPU_OFF', 'acpi_suspend'] # extract the callgraph and traceevent data - tp = TestProps() - testruns = [] - testdata = [] - testrun = 0 - data, limbo = 0, True - tf = sysvals.openlog(sysvals.ftracefile, 'r') + s2idle_enter = hwsus = False + testruns, testdata = [], [] + testrun, data, limbo = 0, 0, True phase = 'suspend_prepare' - for line in tf: - # remove any latent carriage returns - line = line.replace('\r\n', '') - if tp.stampInfo(line): - continue - # tracer type line: determine the trace data type - m = re.match(tp.tracertypefmt, line) - if(m): - tp.setTracerType(m.group('t')) - continue - # device properties line - if(re.match(tp.devpropfmt, line)): - tp.parseDevprops(line, sysvals) - continue - # platform info line - if(re.match(tp.pinfofmt, line)): - tp.parsePlatformInfo(line, sysvals) - continue - # ignore all other commented lines - if line[0] == '#': - continue - # ftrace line: parse only valid lines - m = re.match(tp.ftrace_line_fmt, line) - if(not m): - continue + tp, tf = loadTraceLog() + for m_time, m_proc, m_pid, m_msg, m_param3 in tf: # gather the basic message data from the line - m_time = m.group('time') - m_proc = m.group('proc') - m_pid = m.group('pid') - m_msg = m.group('msg') - if(tp.cgformat): - m_param3 = m.group('dur') - else: - m_param3 = 'traceevent' if(m_time and m_pid and m_msg): t = FTraceLine(m_time, m_msg, m_param3) pid = int(m_pid) @@ -3233,16 +3493,33 @@ def parseTraceLog(live=False): continue # process cpu exec line if t.type == 'tracing_mark_write': + if t.name == 'CMD COMPLETE' and data.tKernRes == 0: + data.tKernRes = t.time m = re.match(tp.procexecfmt, t.name) if(m): - proclist = dict() - for ps in m.group('ps').split(','): + parts, msg = 1, m.group('ps') + m = re.match(tp.procmultifmt, msg) + if(m): + parts, msg = int(m.group('n')), m.group('ps') + if tp.multiproccnt == 0: + tp.multiproctime = t.time + tp.multiproclist = dict() + proclist = tp.multiproclist + tp.multiproccnt += 1 + else: + proclist = dict() + tp.multiproccnt = 0 + for ps in msg.split(','): val = ps.split() - if not val: + if not val or len(val) != 2: continue name = val[0].replace('--', '-') proclist[name] = int(val[1]) - data.pstl[t.time] = proclist + if parts == 1: + data.pstl[t.time] = proclist + elif parts == tp.multiproccnt: + data.pstl[tp.multiproctime] = proclist + tp.multiproccnt = 0 continue # find the end of resume if(t.endMarker()): @@ -3261,28 +3538,28 @@ def parseTraceLog(live=False): if(t.fevent): if(t.type == 'suspend_resume'): # suspend_resume trace events have two types, begin and end - if(re.match('(?P<name>.*) begin$', t.name)): + if(re.match(r'(?P<name>.*) begin$', t.name)): isbegin = True - elif(re.match('(?P<name>.*) end$', t.name)): + elif(re.match(r'(?P<name>.*) end$', t.name)): isbegin = False else: continue if '[' in t.name: - m = re.match('(?P<name>.*)\[.*', t.name) + m = re.match(r'(?P<name>.*)\[.*', t.name) else: - m = re.match('(?P<name>.*) .*', t.name) + m = re.match(r'(?P<name>.*) .*', t.name) name = m.group('name') # ignore these events if(name.split('[')[0] in tracewatch): continue # -- phase changes -- # start of kernel suspend - if(re.match('suspend_enter\[.*', t.name)): + if(re.match(r'suspend_enter\[.*', t.name)): if(isbegin and data.tKernSus == 0): data.tKernSus = t.time continue # suspend_prepare start - elif(re.match('dpm_prepare\[.*', t.name)): + elif(re.match(r'dpm_prepare\[.*', t.name)): if isbegin and data.first_suspend_prepare: data.first_suspend_prepare = False if data.tKernSus == 0: @@ -3291,28 +3568,42 @@ def parseTraceLog(live=False): phase = data.setPhase('suspend_prepare', t.time, isbegin) continue # suspend start - elif(re.match('dpm_suspend\[.*', t.name)): + elif(re.match(r'dpm_suspend\[.*', t.name)): phase = data.setPhase('suspend', t.time, isbegin) continue # suspend_late start - elif(re.match('dpm_suspend_late\[.*', t.name)): + elif(re.match(r'dpm_suspend_late\[.*', t.name)): phase = data.setPhase('suspend_late', t.time, isbegin) continue # suspend_noirq start - elif(re.match('dpm_suspend_noirq\[.*', t.name)): + elif(re.match(r'dpm_suspend_noirq\[.*', t.name)): phase = data.setPhase('suspend_noirq', t.time, isbegin) continue # suspend_machine/resume_machine - elif(re.match('machine_suspend\[.*', t.name)): + elif(re.match(tp.machinesuspend, t.name)): + lp = data.lastPhase() if(isbegin): - lp = data.lastPhase() + hwsus = True if lp.startswith('resume_machine'): - data.dmesg[lp]['end'] = t.time + # trim out s2idle loops, track time trying to freeze + llp = data.lastPhase(2) + if llp.startswith('suspend_machine'): + if 'waking' not in data.dmesg[llp]: + data.dmesg[llp]['waking'] = [0, 0.0] + data.dmesg[llp]['waking'][0] += 1 + data.dmesg[llp]['waking'][1] += \ + t.time - data.dmesg[lp]['start'] + data.currphase = '' + del data.dmesg[lp] + continue phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True) data.setPhase(phase, t.time, False) if data.tSuspended == 0: data.tSuspended = t.time else: + if lp.startswith('resume_machine'): + data.dmesg[lp]['end'] = t.time + continue phase = data.setPhase('resume_machine', t.time, True) if(sysvals.suspendmode in ['mem', 'disk']): susp = phase.replace('resume', 'suspend') @@ -3322,19 +3613,19 @@ def parseTraceLog(live=False): data.tResumed = t.time continue # resume_noirq start - elif(re.match('dpm_resume_noirq\[.*', t.name)): + elif(re.match(r'dpm_resume_noirq\[.*', t.name)): phase = data.setPhase('resume_noirq', t.time, isbegin) continue # resume_early start - elif(re.match('dpm_resume_early\[.*', t.name)): + elif(re.match(r'dpm_resume_early\[.*', t.name)): phase = data.setPhase('resume_early', t.time, isbegin) continue # resume start - elif(re.match('dpm_resume\[.*', t.name)): + elif(re.match(r'dpm_resume\[.*', t.name)): phase = data.setPhase('resume', t.time, isbegin) continue # resume complete start - elif(re.match('dpm_complete\[.*', t.name)): + elif(re.match(r'dpm_complete\[.*', t.name)): phase = data.setPhase('resume_complete', t.time, isbegin) continue # skip trace events inside devices calls @@ -3343,6 +3634,19 @@ def parseTraceLog(live=False): # global events (outside device calls) are graphed if(name not in testrun.ttemp): testrun.ttemp[name] = [] + # special handling for s2idle_enter + if name == 'machine_suspend': + if hwsus: + s2idle_enter = hwsus = False + elif s2idle_enter and not isbegin: + if(len(testrun.ttemp[name]) > 0): + testrun.ttemp[name][-1]['end'] = t.time + testrun.ttemp[name][-1]['loop'] += 1 + elif not s2idle_enter and isbegin: + s2idle_enter = True + testrun.ttemp[name].append({'begin': t.time, + 'end': t.time, 'pid': pid, 'loop': 0}) + continue if(isbegin): # create a new list entry testrun.ttemp[name].append(\ @@ -3355,7 +3659,7 @@ def parseTraceLog(live=False): elif(t.type == 'device_pm_callback_start'): if phase not in data.dmesg: continue - m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ + m = re.match(r'(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ t.name); if(not m): continue @@ -3370,13 +3674,12 @@ def parseTraceLog(live=False): elif(t.type == 'device_pm_callback_end'): if phase not in data.dmesg: continue - m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name); + m = re.match(r'(?P<drv>.*) (?P<d>.*), err.*', t.name); if(not m): continue n = m.group('d') - list = data.dmesg[phase]['list'] - if(n in list): - dev = list[n] + dev = data.findDevice(phase, n) + if dev: dev['length'] = t.time - dev['start'] dev['end'] = t.time # kprobe event processing @@ -3410,6 +3713,9 @@ def parseTraceLog(live=False): e = next((x for x in reversed(tp.ktemp[key]) if x['end'] < 0), 0) if not e: continue + if (t.time - e['begin']) * 1000 < sysvals.mindevlen: + tp.ktemp[key].pop() + continue e['end'] = t.time e['rdata'] = kprobedata # end of kernel resume @@ -3432,7 +3738,6 @@ def parseTraceLog(live=False): testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals)) if(res == -1): testrun.ftemp[key][-1].addLine(t) - tf.close() if len(testdata) < 1: sysvals.vprint('WARNING: ftrace start marker is missing') if data and not data.devicegroups: @@ -3479,7 +3784,12 @@ def parseTraceLog(live=False): # add actual trace funcs for name in sorted(test.ttemp): for event in test.ttemp[name]: - data.newActionGlobal(name, event['begin'], event['end'], event['pid']) + if event['end'] - event['begin'] <= 0: + continue + title = name + if name == 'machine_suspend' and 'loop' in event: + title = 's2idle_enter_%dx' % event['loop'] + data.newActionGlobal(title, event['begin'], event['end'], event['pid']) # add the kprobe based virtual tracefuncs as actual devices for key in sorted(tp.ktemp): name, pid = key @@ -3548,8 +3858,15 @@ def parseTraceLog(live=False): for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): if p not in data.dmesg: if not terr: - pprint('TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)) - terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp) + ph = p if 'machine' in p else lp + if p == 'suspend_machine': + sm = sysvals.suspendmode + if sm in suspendmodename: + sm = suspendmodename[sm] + terr = 'test%s did not enter %s power mode' % (tn, sm) + else: + terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph) + pprint('TEST%s FAILED: %s' % (tn, terr)) error.append(terr) if data.tSuspended == 0: data.tSuspended = data.dmesg[lp]['end'] @@ -3589,9 +3906,7 @@ def parseTraceLog(live=False): # Function: loadKernelLog # Description: -# [deprecated for kernel 3.15.0 or newer] # load the dmesg file into memory and fix up any ordering issues -# The dmesg filename is taken from sysvals # Output: # An array of empty Data objects with only their dmesgtext attributes set def loadKernelLog(): @@ -3611,28 +3926,35 @@ def loadKernelLog(): idx = line.find('[') if idx > 1: line = line[idx:] - if tp.stampInfo(line): + if tp.stampInfo(line, sysvals): continue - m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if(not m): continue msg = m.group("msg") - if(re.match('PM: Syncing filesystems.*', msg)): + if re.match(r'PM: Syncing filesystems.*', msg) or \ + re.match(r'PM: suspend entry.*', msg): if(data): testruns.append(data) data = Data(len(testruns)) tp.parseStamp(data, sysvals) if(not data): continue - m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) + m = re.match(r'.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) if(m): sysvals.stamp['kernel'] = m.group('k') - m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg) - if(m): + m = re.match(r'PM: Preparing system for (?P<m>.*) sleep', msg) + if not m: + m = re.match(r'PM: Preparing system for sleep \((?P<m>.*)\)', msg) + if m: sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m') data.dmesgtext.append(line) lf.close() + if sysvals.suspendmode == 's2idle': + sysvals.suspendmode = 'freeze' + elif sysvals.suspendmode == 'deep': + sysvals.suspendmode = 'mem' if data: testruns.append(data) if len(testruns) < 1: @@ -3643,12 +3965,9 @@ def loadKernelLog(): for data in testruns: last = '' for line in data.dmesgtext: - mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ - '(?P<f>.*)\+ @ .*, parent: .*', line) - mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ - '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last) - if(mc and mr and (mc.group('t') == mr.group('t')) and - (mc.group('f') == mr.group('f'))): + ct, cf, n, p = data.initcall_debug_call(line) + rt, rf, l = data.initcall_debug_return(last) + if ct and rt and ct == rt and cf == rf: i = data.dmesgtext.index(last) j = data.dmesgtext.index(line) data.dmesgtext[i] = line @@ -3658,7 +3977,6 @@ def loadKernelLog(): # Function: parseKernelLog # Description: -# [deprecated for kernel 3.15.0 or newer] # Analyse a dmesg log output file generated from this app during # the execution phase. Create a set of device structures in memory # for subsequent formatting in the html output file @@ -3677,42 +3995,43 @@ def parseKernelLog(data): # dmesg phase match table dm = { - 'suspend_prepare': ['PM: Syncing filesystems.*'], - 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*'], - 'suspend_late': ['PM: suspend of devices complete after.*'], - 'suspend_noirq': ['PM: late suspend of devices complete after.*'], - 'suspend_machine': ['PM: noirq suspend of devices complete after.*'], - 'resume_machine': ['ACPI: Low-level resume complete.*'], - 'resume_noirq': ['ACPI: Waking up from system sleep state.*'], - 'resume_early': ['PM: noirq resume of devices complete after.*'], - 'resume': ['PM: early resume of devices complete after.*'], - 'resume_complete': ['PM: resume of devices complete after.*'], - 'post_resume': ['.*Restarting tasks \.\.\..*'], + 'suspend_prepare': ['PM: Syncing filesystems.*', 'PM: suspend entry.*'], + 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*', + 'PM: Suspending system .*'], + 'suspend_late': ['PM: suspend of devices complete after.*', + 'PM: freeze of devices complete after.*'], + 'suspend_noirq': ['PM: late suspend of devices complete after.*', + 'PM: late freeze of devices complete after.*'], + 'suspend_machine': ['PM: suspend-to-idle', + 'PM: noirq suspend of devices complete after.*', + 'PM: noirq freeze of devices complete after.*'], + 'resume_machine': ['[PM: ]*Timekeeping suspended for.*', + 'ACPI: Low-level resume complete.*', + 'ACPI: resume from mwait', + r'Suspended for [0-9\.]* seconds'], + 'resume_noirq': ['PM: resume from suspend-to-idle', + 'ACPI: Waking up from system sleep state.*'], + 'resume_early': ['PM: noirq resume of devices complete after.*', + 'PM: noirq restore of devices complete after.*'], + 'resume': ['PM: early resume of devices complete after.*', + 'PM: early restore of devices complete after.*'], + 'resume_complete': ['PM: resume of devices complete after.*', + 'PM: restore of devices complete after.*'], + 'post_resume': [r'.*Restarting tasks \.\.\..*', + 'Done restarting tasks.*'], } - if(sysvals.suspendmode == 'standby'): - dm['resume_machine'] = ['PM: Restoring platform NVS memory'] - elif(sysvals.suspendmode == 'disk'): - dm['suspend_late'] = ['PM: freeze of devices complete after.*'] - dm['suspend_noirq'] = ['PM: late freeze of devices complete after.*'] - dm['suspend_machine'] = ['PM: noirq freeze of devices complete after.*'] - dm['resume_machine'] = ['PM: Restoring platform NVS memory'] - dm['resume_early'] = ['PM: noirq restore of devices complete after.*'] - dm['resume'] = ['PM: early restore of devices complete after.*'] - dm['resume_complete'] = ['PM: restore of devices complete after.*'] - elif(sysvals.suspendmode == 'freeze'): - dm['resume_machine'] = ['ACPI: resume from mwait'] # action table (expected events that occur and show up in dmesg) at = { 'sync_filesystems': { - 'smsg': 'PM: Syncing filesystems.*', - 'emsg': 'PM: Preparing system for mem sleep.*' }, + 'smsg': '.*[Ff]+ilesystems.*', + 'emsg': 'PM: Preparing system for[a-z]* sleep.*' }, 'freeze_user_processes': { - 'smsg': 'Freezing user space processes .*', + 'smsg': 'Freezing user space processes.*', 'emsg': 'Freezing remaining freezable tasks.*' }, 'freeze_tasks': { 'smsg': 'Freezing remaining freezable tasks.*', - 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' }, + 'emsg': 'PM: Suspending system.*' }, 'ACPI prepare': { 'smsg': 'ACPI: Preparing to enter system sleep state.*', 'emsg': 'PM: Saving platform NVS memory.*' }, @@ -3727,7 +4046,7 @@ def parseKernelLog(data): actions = dict() for line in data.dmesgtext: # parse each dmesg line into the time and message - m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + m = re.match(r'[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if(m): val = m.group('ktime') try: @@ -3748,12 +4067,13 @@ def parseKernelLog(data): for s in dm[p]: if(re.match(s, msg)): phasechange, phase = True, p + dm[p] = [s] break # hack for determining resume_machine end for freeze if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ and phase == 'resume_machine' and \ - re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): + data.initcall_debug_call(line, True)): data.setPhase(phase, ktime, False) phase = 'resume_noirq' data.setPhase(phase, ktime, True) @@ -3826,26 +4146,18 @@ def parseKernelLog(data): # -- device callbacks -- if(phase in data.sortedPhases()): # device init call - if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): - sm = re.match('calling (?P<f>.*)\+ @ '+\ - '(?P<n>.*), parent: (?P<p>.*)', msg); - f = sm.group('f') - n = sm.group('n') - p = sm.group('p') - if(f and n and p): - data.newAction(phase, f, int(n), p, ktime, -1, '') - # device init return - elif(re.match('call (?P<f>.*)\+ returned .* after '+\ - '(?P<t>.*) usecs', msg)): - sm = re.match('call (?P<f>.*)\+ returned .* after '+\ - '(?P<t>.*) usecs(?P<a>.*)', msg); - f = sm.group('f') - t = sm.group('t') - list = data.dmesg[phase]['list'] - if(f in list): - dev = list[f] - dev['length'] = int(t) - dev['end'] = ktime + t, f, n, p = data.initcall_debug_call(line) + if t and f and n and p: + data.newAction(phase, f, int(n), p, ktime, -1, '') + else: + # device init return + t, f, l = data.initcall_debug_return(line) + if t and f and l: + list = data.dmesg[phase]['list'] + if(f in list): + dev = list[f] + dev['length'] = int(l) + dev['end'] = ktime # if trace events are not available, these are better than nothing if(not sysvals.usetraceevents): @@ -3853,29 +4165,31 @@ def parseKernelLog(data): for a in sorted(at): if(re.match(at[a]['smsg'], msg)): if(a not in actions): - actions[a] = [] - actions[a].append({'begin': ktime, 'end': ktime}) + actions[a] = [{'begin': ktime, 'end': ktime}] if(re.match(at[a]['emsg'], msg)): - if(a in actions): + if(a in actions and actions[a][-1]['begin'] == actions[a][-1]['end']): actions[a][-1]['end'] = ktime # now look for CPU on/off events - if(re.match('Disabling non-boot CPUs .*', msg)): + if(re.match(r'Disabling non-boot CPUs .*', msg)): # start of first cpu suspend cpu_start = ktime - elif(re.match('Enabling non-boot CPUs .*', msg)): + elif(re.match(r'Enabling non-boot CPUs .*', msg)): # start of first cpu resume cpu_start = ktime - elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)): + elif(re.match(r'smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) \ + or re.match(r'psci: CPU(?P<cpu>[0-9]*) killed.*', msg)): # end of a cpu suspend, start of the next - m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) + m = re.match(r'smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) + if(not m): + m = re.match(r'psci: CPU(?P<cpu>[0-9]*) killed.*', msg) cpu = 'CPU'+m.group('cpu') if(cpu not in actions): actions[cpu] = [] actions[cpu].append({'begin': cpu_start, 'end': ktime}) cpu_start = ktime - elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)): + elif(re.match(r'CPU(?P<cpu>[0-9]*) is up', msg)): # end of a cpu resume, start of the next - m = re.match('CPU(?P<cpu>[0-9]*) is up', msg) + m = re.match(r'CPU(?P<cpu>[0-9]*) is up', msg) cpu = 'CPU'+m.group('cpu') if(cpu not in actions): actions[cpu] = [] @@ -3887,6 +4201,8 @@ def parseKernelLog(data): # fill in any missing phases phasedef = data.phasedef terr, lp = '', 'suspend_prepare' + if lp not in data.dmesg: + doError('dmesg log format has changed, could not find start of suspend') for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): if p not in data.dmesg: if not terr: @@ -3942,6 +4258,8 @@ def callgraphHTML(sv, hf, num, cg, title, color, devid): fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>' flen = fmt % (line.length*1000, line.time) if line.isLeaf(): + if line.length * 1000 < sv.mincglen: + continue hf.write(html_func_leaf.format(line.name, flen)) elif line.freturn: hf.write(html_func_end) @@ -3959,18 +4277,20 @@ def addCallgraphs(sv, hf, data): if sv.cgphase and p != sv.cgphase: continue list = data.dmesg[p]['list'] - for devname in data.sortedDevices(p): - if len(sv.cgfilter) > 0 and devname not in sv.cgfilter: + for d in data.sortedDevices(p): + if len(sv.cgfilter) > 0 and d not in sv.cgfilter: continue - dev = list[devname] + dev = list[d] color = 'white' if 'color' in data.dmesg[p]: color = data.dmesg[p]['color'] if 'color' in dev: color = dev['color'] - name = devname - if(devname in sv.devprops): - name = sv.devprops[devname].altName(devname) + name = d if '[' not in d else d.split('[')[0] + if(d in sv.devprops): + name = sv.devprops[d].altName(d) + if 'drv' in dev and dev['drv']: + name += ' {%s}' % dev['drv'] if sv.suspendmode in suspendmodename: name += ' '+p if('ftrace' in dev): @@ -4048,7 +4368,8 @@ def createHTMLSummarySimple(testruns, htmlfile, title): list[mode]['data'].append([data['host'], data['kernel'], data['time'], tVal[0], tVal[1], data['url'], res, data['issues'], data['sus_worst'], data['sus_worsttime'], - data['res_worst'], data['res_worsttime'], pkgpc10, syslpi, wifi]) + data['res_worst'], data['res_worsttime'], pkgpc10, syslpi, wifi, + (data['fullmode'] if 'fullmode' in data else mode)]) idx = len(list[mode]['data']) - 1 if res.startswith('fail in'): res = 'fail' @@ -4154,7 +4475,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title): elif idx == iMed[i]: tHigh[i] = ' id="%smed" class=medval title="Median"' % tag html += td.format("%d" % (list[mode]['data'].index(d) + 1)) # row - html += td.format(mode) # mode + html += td.format(d[15]) # mode html += td.format(d[0]) # host html += td.format(d[1]) # kernel html += td.format(d[2]) # time @@ -4517,12 +4838,9 @@ def createHTML(testruns, testfail): # draw the devices for this phase phaselist = data.dmesg[b]['list'] for d in sorted(data.tdevlist[b]): - name = d - drv = '' - dev = phaselist[d] - xtraclass = '' - xtrainfo = '' - xtrastyle = '' + dname = d if ('[' not in d or 'CPU' in d) else d.split('[')[0] + name, dev = dname, phaselist[d] + drv = xtraclass = xtrainfo = xtrastyle = '' if 'htmlclass' in dev: xtraclass = dev['htmlclass'] if 'color' in dev: @@ -4553,24 +4871,23 @@ def createHTML(testruns, testfail): title += b devtl.html += devtl.html_device.format(dev['id'], \ title, left, top, '%.3f'%rowheight, width, \ - d+drv, xtraclass, xtrastyle) + dname+drv, xtraclass, xtrastyle) if('cpuexec' in dev): for t in sorted(dev['cpuexec']): start, end = t - j = float(dev['cpuexec'][t]) / 5 - if j > 1.0: - j = 1.0 height = '%.3f' % (rowheight/3) top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3) left = '%f' % (((start-m0)*100)/mTotal) width = '%f' % ((end-start)*100/mTotal) - color = 'rgba(255, 0, 0, %f)' % j + color = 'rgba(255, 0, 0, %f)' % dev['cpuexec'][t] devtl.html += \ html_cpuexec.format(left, top, height, width, color) if('src' not in dev): continue # draw any trace events for this device for e in dev['src']: + if e.length == 0: + continue height = '%.3f' % devtl.rowH top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH)) left = '%f' % (((e.time-m0)*100)/mTotal) @@ -4770,6 +5087,7 @@ def addCSS(hf, sv, testcount=1, kerror=False, extra=''): def addScriptCode(hf, testruns): t0 = testruns[0].start * 1000 tMax = testruns[-1].end * 1000 + hf.write('<script type="text/javascript">\n'); # create an array in javascript memory with the device details detail = ' var devtable = [];\n' for data in testruns: @@ -4777,536 +5095,527 @@ def addScriptCode(hf, testruns): detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo) detail += ' var bounds = [%f,%f];\n' % (t0, tMax) # add the code which will manipulate the data in the browser - script_code = \ - '<script type="text/javascript">\n'+detail+\ - ' var resolution = -1;\n'\ - ' var dragval = [0, 0];\n'\ - ' function redrawTimescale(t0, tMax, tS) {\n'\ - ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;">\';\n'\ - ' var tTotal = tMax - t0;\n'\ - ' var list = document.getElementsByClassName("tblock");\n'\ - ' for (var i = 0; i < list.length; i++) {\n'\ - ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\ - ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\ - ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\ - ' var mMax = m0 + mTotal;\n'\ - ' var html = "";\n'\ - ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\ - ' if(divTotal > 1000) continue;\n'\ - ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\ - ' var pos = 0.0, val = 0.0;\n'\ - ' for (var j = 0; j < divTotal; j++) {\n'\ - ' var htmlline = "";\n'\ - ' var mode = list[i].id[5];\n'\ - ' if(mode == "s") {\n'\ - ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\ - ' val = (j-divTotal+1)*tS;\n'\ - ' if(j == divTotal - 1)\n'\ - ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S→</cS></div>\';\n'\ - ' else\n'\ - ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\ - ' } else {\n'\ - ' pos = 100 - (((j)*tS*100)/mTotal);\n'\ - ' val = (j)*tS;\n'\ - ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\ - ' if(j == 0)\n'\ - ' if(mode == "r")\n'\ - ' htmlline = rline+"<cS>←R</cS></div>";\n'\ - ' else\n'\ - ' htmlline = rline+"<cS>0ms</div>";\n'\ - ' }\n'\ - ' html += htmlline;\n'\ - ' }\n'\ - ' timescale.innerHTML = html;\n'\ - ' }\n'\ - ' }\n'\ - ' function zoomTimeline() {\n'\ - ' var dmesg = document.getElementById("dmesg");\n'\ - ' var zoombox = document.getElementById("dmesgzoombox");\n'\ - ' var left = zoombox.scrollLeft;\n'\ - ' var val = parseFloat(dmesg.style.width);\n'\ - ' var newval = 100;\n'\ - ' var sh = window.outerWidth / 2;\n'\ - ' if(this.id == "zoomin") {\n'\ - ' newval = val * 1.2;\n'\ - ' if(newval > 910034) newval = 910034;\n'\ - ' dmesg.style.width = newval+"%";\n'\ - ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\ - ' } else if (this.id == "zoomout") {\n'\ - ' newval = val / 1.2;\n'\ - ' if(newval < 100) newval = 100;\n'\ - ' dmesg.style.width = newval+"%";\n'\ - ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\ - ' } else {\n'\ - ' zoombox.scrollLeft = 0;\n'\ - ' dmesg.style.width = "100%";\n'\ - ' }\n'\ - ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\ - ' var t0 = bounds[0];\n'\ - ' var tMax = bounds[1];\n'\ - ' var tTotal = tMax - t0;\n'\ - ' var wTotal = tTotal * 100.0 / newval;\n'\ - ' var idx = 7*window.innerWidth/1100;\n'\ - ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\ - ' if(i >= tS.length) i = tS.length - 1;\n'\ - ' if(tS[i] == resolution) return;\n'\ - ' resolution = tS[i];\n'\ - ' redrawTimescale(t0, tMax, tS[i]);\n'\ - ' }\n'\ - ' function deviceName(title) {\n'\ - ' var name = title.slice(0, title.indexOf(" ("));\n'\ - ' return name;\n'\ - ' }\n'\ - ' function deviceHover() {\n'\ - ' var name = deviceName(this.title);\n'\ - ' var dmesg = document.getElementById("dmesg");\n'\ - ' var dev = dmesg.getElementsByClassName("thread");\n'\ - ' var cpu = -1;\n'\ - ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ - ' cpu = parseInt(name.slice(7));\n'\ - ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ - ' cpu = parseInt(name.slice(8));\n'\ - ' for (var i = 0; i < dev.length; i++) {\n'\ - ' dname = deviceName(dev[i].title);\n'\ - ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\ - ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ - ' (name == dname))\n'\ - ' {\n'\ - ' dev[i].className = "hover "+cname;\n'\ - ' } else {\n'\ - ' dev[i].className = cname;\n'\ - ' }\n'\ - ' }\n'\ - ' }\n'\ - ' function deviceUnhover() {\n'\ - ' var dmesg = document.getElementById("dmesg");\n'\ - ' var dev = dmesg.getElementsByClassName("thread");\n'\ - ' for (var i = 0; i < dev.length; i++) {\n'\ - ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\ - ' }\n'\ - ' }\n'\ - ' function deviceTitle(title, total, cpu) {\n'\ - ' var prefix = "Total";\n'\ - ' if(total.length > 3) {\n'\ - ' prefix = "Average";\n'\ - ' total[1] = (total[1]+total[3])/2;\n'\ - ' total[2] = (total[2]+total[4])/2;\n'\ - ' }\n'\ - ' var devtitle = document.getElementById("devicedetailtitle");\n'\ - ' var name = deviceName(title);\n'\ - ' if(cpu >= 0) name = "CPU"+cpu;\n'\ - ' var driver = "";\n'\ - ' var tS = "<t2>(</t2>";\n'\ - ' var tR = "<t2>)</t2>";\n'\ - ' if(total[1] > 0)\n'\ - ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\ - ' if(total[2] > 0)\n'\ - ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\ - ' var s = title.indexOf("{");\n'\ - ' var e = title.indexOf("}");\n'\ - ' if((s >= 0) && (e >= 0))\n'\ - ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\ - ' if(total[1] > 0 && total[2] > 0)\n'\ - ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\ - ' else\n'\ - ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\ - ' return name;\n'\ - ' }\n'\ - ' function deviceDetail() {\n'\ - ' var devinfo = document.getElementById("devicedetail");\n'\ - ' devinfo.style.display = "block";\n'\ - ' var name = deviceName(this.title);\n'\ - ' var cpu = -1;\n'\ - ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ - ' cpu = parseInt(name.slice(7));\n'\ - ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ - ' cpu = parseInt(name.slice(8));\n'\ - ' var dmesg = document.getElementById("dmesg");\n'\ - ' var dev = dmesg.getElementsByClassName("thread");\n'\ - ' var idlist = [];\n'\ - ' var pdata = [[]];\n'\ - ' if(document.getElementById("devicedetail1"))\n'\ - ' pdata = [[], []];\n'\ - ' var pd = pdata[0];\n'\ - ' var total = [0.0, 0.0, 0.0];\n'\ - ' for (var i = 0; i < dev.length; i++) {\n'\ - ' dname = deviceName(dev[i].title);\n'\ - ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ - ' (name == dname))\n'\ - ' {\n'\ - ' idlist[idlist.length] = dev[i].id;\n'\ - ' var tidx = 1;\n'\ - ' if(dev[i].id[0] == "a") {\n'\ - ' pd = pdata[0];\n'\ - ' } else {\n'\ - ' if(pdata.length == 1) pdata[1] = [];\n'\ - ' if(total.length == 3) total[3]=total[4]=0.0;\n'\ - ' pd = pdata[1];\n'\ - ' tidx = 3;\n'\ - ' }\n'\ - ' var info = dev[i].title.split(" ");\n'\ - ' var pname = info[info.length-1];\n'\ - ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\ - ' total[0] += pd[pname];\n'\ - ' if(pname.indexOf("suspend") >= 0)\n'\ - ' total[tidx] += pd[pname];\n'\ - ' else\n'\ - ' total[tidx+1] += pd[pname];\n'\ - ' }\n'\ - ' }\n'\ - ' var devname = deviceTitle(this.title, total, cpu);\n'\ - ' var left = 0.0;\n'\ - ' for (var t = 0; t < pdata.length; t++) {\n'\ - ' pd = pdata[t];\n'\ - ' devinfo = document.getElementById("devicedetail"+t);\n'\ - ' var phases = devinfo.getElementsByClassName("phaselet");\n'\ - ' for (var i = 0; i < phases.length; i++) {\n'\ - ' if(phases[i].id in pd) {\n'\ - ' var w = 100.0*pd[phases[i].id]/total[0];\n'\ - ' var fs = 32;\n'\ - ' if(w < 8) fs = 4*w | 0;\n'\ - ' var fs2 = fs*3/4;\n'\ - ' phases[i].style.width = w+"%";\n'\ - ' phases[i].style.left = left+"%";\n'\ - ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\ - ' left += w;\n'\ - ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\ - ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\ - ' phases[i].innerHTML = time+pname;\n'\ - ' } else {\n'\ - ' phases[i].style.width = "0%";\n'\ - ' phases[i].style.left = left+"%";\n'\ - ' }\n'\ - ' }\n'\ - ' }\n'\ - ' if(typeof devstats !== \'undefined\')\n'\ - ' callDetail(this.id, this.title);\n'\ - ' var cglist = document.getElementById("callgraphs");\n'\ - ' if(!cglist) return;\n'\ - ' var cg = cglist.getElementsByClassName("atop");\n'\ - ' if(cg.length < 10) return;\n'\ - ' for (var i = 0; i < cg.length; i++) {\n'\ - ' cgid = cg[i].id.split("x")[0]\n'\ - ' if(idlist.indexOf(cgid) >= 0) {\n'\ - ' cg[i].style.display = "block";\n'\ - ' } else {\n'\ - ' cg[i].style.display = "none";\n'\ - ' }\n'\ - ' }\n'\ - ' }\n'\ - ' function callDetail(devid, devtitle) {\n'\ - ' if(!(devid in devstats) || devstats[devid].length < 1)\n'\ - ' return;\n'\ - ' var list = devstats[devid];\n'\ - ' var tmp = devtitle.split(" ");\n'\ - ' var name = tmp[0], phase = tmp[tmp.length-1];\n'\ - ' var dd = document.getElementById(phase);\n'\ - ' var total = parseFloat(tmp[1].slice(1));\n'\ - ' var mlist = [];\n'\ - ' var maxlen = 0;\n'\ - ' var info = []\n'\ - ' for(var i in list) {\n'\ - ' if(list[i][0] == "@") {\n'\ - ' info = list[i].split("|");\n'\ - ' continue;\n'\ - ' }\n'\ - ' var tmp = list[i].split("|");\n'\ - ' var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]);\n'\ - ' var p = (t*100.0/total).toFixed(2);\n'\ - ' mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"];\n'\ - ' if(f.length > maxlen)\n'\ - ' maxlen = f.length;\n'\ - ' }\n'\ - ' var pad = 5;\n'\ - ' if(mlist.length == 0) pad = 30;\n'\ - ' var html = \'<div style="padding-top:\'+pad+\'px"><t3> <b>\'+name+\':</b>\';\n'\ - ' if(info.length > 2)\n'\ - ' html += " start=<b>"+info[1]+"</b>, end=<b>"+info[2]+"</b>";\n'\ - ' if(info.length > 3)\n'\ - ' html += ", length<i>(w/o overhead)</i>=<b>"+info[3]+" ms</b>";\n'\ - ' if(info.length > 4)\n'\ - ' html += ", return=<b>"+info[4]+"</b>";\n'\ - ' html += "</t3></div>";\n'\ - ' if(mlist.length > 0) {\n'\ - ' html += \'<table class=fstat style="padding-top:\'+(maxlen*5)+\'px;"><tr><th>Function</th>\';\n'\ - ' for(var i in mlist)\n'\ - ' html += "<td class=vt>"+mlist[i][0]+"</td>";\n'\ - ' html += "</tr><tr><th>Calls</th>";\n'\ - ' for(var i in mlist)\n'\ - ' html += "<td>"+mlist[i][1]+"</td>";\n'\ - ' html += "</tr><tr><th>Time(ms)</th>";\n'\ - ' for(var i in mlist)\n'\ - ' html += "<td>"+mlist[i][2]+"</td>";\n'\ - ' html += "</tr><tr><th>Percent</th>";\n'\ - ' for(var i in mlist)\n'\ - ' html += "<td>"+mlist[i][3]+"</td>";\n'\ - ' html += "</tr></table>";\n'\ - ' }\n'\ - ' dd.innerHTML = html;\n'\ - ' var height = (maxlen*5)+100;\n'\ - ' dd.style.height = height+"px";\n'\ - ' document.getElementById("devicedetail").style.height = height+"px";\n'\ - ' }\n'\ - ' function callSelect() {\n'\ - ' var cglist = document.getElementById("callgraphs");\n'\ - ' if(!cglist) return;\n'\ - ' var cg = cglist.getElementsByClassName("atop");\n'\ - ' for (var i = 0; i < cg.length; i++) {\n'\ - ' if(this.id == cg[i].id) {\n'\ - ' cg[i].style.display = "block";\n'\ - ' } else {\n'\ - ' cg[i].style.display = "none";\n'\ - ' }\n'\ - ' }\n'\ - ' }\n'\ - ' function devListWindow(e) {\n'\ - ' var win = window.open();\n'\ - ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\ - ' "<style type=\\"text/css\\">"+\n'\ - ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\ - ' "</style>"\n'\ - ' var dt = devtable[0];\n'\ - ' if(e.target.id != "devlist1")\n'\ - ' dt = devtable[1];\n'\ - ' win.document.write(html+dt);\n'\ - ' }\n'\ - ' function errWindow() {\n'\ - ' var range = this.id.split("_");\n'\ - ' var idx1 = parseInt(range[0]);\n'\ - ' var idx2 = parseInt(range[1]);\n'\ - ' var win = window.open();\n'\ - ' var log = document.getElementById("dmesglog");\n'\ - ' var title = "<title>dmesg log</title>";\n'\ - ' var text = log.innerHTML.split("\\n");\n'\ - ' var html = "";\n'\ - ' for(var i = 0; i < text.length; i++) {\n'\ - ' if(i == idx1) {\n'\ - ' html += "<e id=target>"+text[i]+"</e>\\n";\n'\ - ' } else if(i > idx1 && i <= idx2) {\n'\ - ' html += "<e>"+text[i]+"</e>\\n";\n'\ - ' } else {\n'\ - ' html += text[i]+"\\n";\n'\ - ' }\n'\ - ' }\n'\ - ' win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>");\n'\ - ' win.location.hash = "#target";\n'\ - ' win.document.close();\n'\ - ' }\n'\ - ' function logWindow(e) {\n'\ - ' var name = e.target.id.slice(4);\n'\ - ' var win = window.open();\n'\ - ' var log = document.getElementById(name+"log");\n'\ - ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\ - ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\ - ' win.document.close();\n'\ - ' }\n'\ - ' function onMouseDown(e) {\n'\ - ' dragval[0] = e.clientX;\n'\ - ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\ - ' document.onmousemove = onMouseMove;\n'\ - ' }\n'\ - ' function onMouseMove(e) {\n'\ - ' var zoombox = document.getElementById("dmesgzoombox");\n'\ - ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\ - ' }\n'\ - ' function onMouseUp(e) {\n'\ - ' document.onmousemove = null;\n'\ - ' }\n'\ - ' function onKeyPress(e) {\n'\ - ' var c = e.charCode;\n'\ - ' if(c != 42 && c != 43 && c != 45) return;\n'\ - ' var click = document.createEvent("Events");\n'\ - ' click.initEvent("click", true, false);\n'\ - ' if(c == 43) \n'\ - ' document.getElementById("zoomin").dispatchEvent(click);\n'\ - ' else if(c == 45)\n'\ - ' document.getElementById("zoomout").dispatchEvent(click);\n'\ - ' else if(c == 42)\n'\ - ' document.getElementById("zoomdef").dispatchEvent(click);\n'\ - ' }\n'\ - ' window.addEventListener("resize", function () {zoomTimeline();});\n'\ - ' window.addEventListener("load", function () {\n'\ - ' var dmesg = document.getElementById("dmesg");\n'\ - ' dmesg.style.width = "100%"\n'\ - ' dmesg.onmousedown = onMouseDown;\n'\ - ' document.onmouseup = onMouseUp;\n'\ - ' document.onkeypress = onKeyPress;\n'\ - ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ - ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ - ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ - ' var list = document.getElementsByClassName("err");\n'\ - ' for (var i = 0; i < list.length; i++)\n'\ - ' list[i].onclick = errWindow;\n'\ - ' var list = document.getElementsByClassName("logbtn");\n'\ - ' for (var i = 0; i < list.length; i++)\n'\ - ' list[i].onclick = logWindow;\n'\ - ' list = document.getElementsByClassName("devlist");\n'\ - ' for (var i = 0; i < list.length; i++)\n'\ - ' list[i].onclick = devListWindow;\n'\ - ' var dev = dmesg.getElementsByClassName("thread");\n'\ - ' for (var i = 0; i < dev.length; i++) {\n'\ - ' dev[i].onclick = deviceDetail;\n'\ - ' dev[i].onmouseover = deviceHover;\n'\ - ' dev[i].onmouseout = deviceUnhover;\n'\ - ' }\n'\ - ' var dev = dmesg.getElementsByClassName("srccall");\n'\ - ' for (var i = 0; i < dev.length; i++)\n'\ - ' dev[i].onclick = callSelect;\n'\ - ' zoomTimeline();\n'\ - ' });\n'\ - '</script>\n' + hf.write(detail); + script_code = r""" var resolution = -1; + var dragval = [0, 0]; + function redrawTimescale(t0, tMax, tS) { + var rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">'; + var tTotal = tMax - t0; + var list = document.getElementsByClassName("tblock"); + for (var i = 0; i < list.length; i++) { + var timescale = list[i].getElementsByClassName("timescale")[0]; + var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100); + var mTotal = tTotal*parseFloat(list[i].style.width)/100; + var mMax = m0 + mTotal; + var html = ""; + var divTotal = Math.floor(mTotal/tS) + 1; + if(divTotal > 1000) continue; + var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal; + var pos = 0.0, val = 0.0; + for (var j = 0; j < divTotal; j++) { + var htmlline = ""; + var mode = list[i].id[5]; + if(mode == "s") { + pos = 100 - (((j)*tS*100)/mTotal) - divEdge; + val = (j-divTotal+1)*tS; + if(j == divTotal - 1) + htmlline = '<div class="t" style="right:'+pos+'%"><cS>S→</cS></div>'; + else + htmlline = '<div class="t" style="right:'+pos+'%">'+val+'ms</div>'; + } else { + pos = 100 - (((j)*tS*100)/mTotal); + val = (j)*tS; + htmlline = '<div class="t" style="right:'+pos+'%">'+val+'ms</div>'; + if(j == 0) + if(mode == "r") + htmlline = rline+"<cS>←R</cS></div>"; + else + htmlline = rline+"<cS>0ms</div>"; + } + html += htmlline; + } + timescale.innerHTML = html; + } + } + function zoomTimeline() { + var dmesg = document.getElementById("dmesg"); + var zoombox = document.getElementById("dmesgzoombox"); + var left = zoombox.scrollLeft; + var val = parseFloat(dmesg.style.width); + var newval = 100; + var sh = window.outerWidth / 2; + if(this.id == "zoomin") { + newval = val * 1.2; + if(newval > 910034) newval = 910034; + dmesg.style.width = newval+"%"; + zoombox.scrollLeft = ((left + sh) * newval / val) - sh; + } else if (this.id == "zoomout") { + newval = val / 1.2; + if(newval < 100) newval = 100; + dmesg.style.width = newval+"%"; + zoombox.scrollLeft = ((left + sh) * newval / val) - sh; + } else { + zoombox.scrollLeft = 0; + dmesg.style.width = "100%"; + } + var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1]; + var t0 = bounds[0]; + var tMax = bounds[1]; + var tTotal = tMax - t0; + var wTotal = tTotal * 100.0 / newval; + var idx = 7*window.innerWidth/1100; + for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++); + if(i >= tS.length) i = tS.length - 1; + if(tS[i] == resolution) return; + resolution = tS[i]; + redrawTimescale(t0, tMax, tS[i]); + } + function deviceName(title) { + var name = title.slice(0, title.indexOf(" (")); + return name; + } + function deviceHover() { + var name = deviceName(this.title); + var dmesg = document.getElementById("dmesg"); + var dev = dmesg.getElementsByClassName("thread"); + var cpu = -1; + if(name.match("CPU_ON\[[0-9]*\]")) + cpu = parseInt(name.slice(7)); + else if(name.match("CPU_OFF\[[0-9]*\]")) + cpu = parseInt(name.slice(8)); + for (var i = 0; i < dev.length; i++) { + dname = deviceName(dev[i].title); + var cname = dev[i].className.slice(dev[i].className.indexOf("thread")); + if((cpu >= 0 && dname.match("CPU_O[NF]*\\[*"+cpu+"\\]")) || + (name == dname)) + { + dev[i].className = "hover "+cname; + } else { + dev[i].className = cname; + } + } + } + function deviceUnhover() { + var dmesg = document.getElementById("dmesg"); + var dev = dmesg.getElementsByClassName("thread"); + for (var i = 0; i < dev.length; i++) { + dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread")); + } + } + function deviceTitle(title, total, cpu) { + var prefix = "Total"; + if(total.length > 3) { + prefix = "Average"; + total[1] = (total[1]+total[3])/2; + total[2] = (total[2]+total[4])/2; + } + var devtitle = document.getElementById("devicedetailtitle"); + var name = deviceName(title); + if(cpu >= 0) name = "CPU"+cpu; + var driver = ""; + var tS = "<t2>(</t2>"; + var tR = "<t2>)</t2>"; + if(total[1] > 0) + tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> "; + if(total[2] > 0) + tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>"; + var s = title.indexOf("{"); + var e = title.indexOf("}"); + if((s >= 0) && (e >= 0)) + driver = title.slice(s+1, e) + " <t1>@</t1> "; + if(total[1] > 0 && total[2] > 0) + devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR; + else + devtitle.innerHTML = "<t0>"+title+"</t0>"; + return name; + } + function deviceDetail() { + var devinfo = document.getElementById("devicedetail"); + devinfo.style.display = "block"; + var name = deviceName(this.title); + var cpu = -1; + if(name.match("CPU_ON\[[0-9]*\]")) + cpu = parseInt(name.slice(7)); + else if(name.match("CPU_OFF\[[0-9]*\]")) + cpu = parseInt(name.slice(8)); + var dmesg = document.getElementById("dmesg"); + var dev = dmesg.getElementsByClassName("thread"); + var idlist = []; + var pdata = [[]]; + if(document.getElementById("devicedetail1")) + pdata = [[], []]; + var pd = pdata[0]; + var total = [0.0, 0.0, 0.0]; + for (var i = 0; i < dev.length; i++) { + dname = deviceName(dev[i].title); + if((cpu >= 0 && dname.match("CPU_O[NF]*\\[*"+cpu+"\\]")) || + (name == dname)) + { + idlist[idlist.length] = dev[i].id; + var tidx = 1; + if(dev[i].id[0] == "a") { + pd = pdata[0]; + } else { + if(pdata.length == 1) pdata[1] = []; + if(total.length == 3) total[3]=total[4]=0.0; + pd = pdata[1]; + tidx = 3; + } + var info = dev[i].title.split(" "); + var pname = info[info.length-1]; + var length = parseFloat(info[info.length-3].slice(1)); + if (pname in pd) + pd[pname] += length; + else + pd[pname] = length; + total[0] += length; + if(pname.indexOf("suspend") >= 0) + total[tidx] += length; + else + total[tidx+1] += length; + } + } + var devname = deviceTitle(this.title, total, cpu); + var left = 0.0; + for (var t = 0; t < pdata.length; t++) { + pd = pdata[t]; + devinfo = document.getElementById("devicedetail"+t); + var phases = devinfo.getElementsByClassName("phaselet"); + for (var i = 0; i < phases.length; i++) { + if(phases[i].id in pd) { + var w = 100.0*pd[phases[i].id]/total[0]; + var fs = 32; + if(w < 8) fs = 4*w | 0; + var fs2 = fs*3/4; + phases[i].style.width = w+"%"; + phases[i].style.left = left+"%"; + phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms"; + left += w; + var time = "<t4 style=\"font-size:"+fs+"px\">"+pd[phases[i].id].toFixed(3)+" ms<br></t4>"; + var pname = "<t3 style=\"font-size:"+fs2+"px\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>"; + phases[i].innerHTML = time+pname; + } else { + phases[i].style.width = "0%"; + phases[i].style.left = left+"%"; + } + } + } + if(typeof devstats !== 'undefined') + callDetail(this.id, this.title); + var cglist = document.getElementById("callgraphs"); + if(!cglist) return; + var cg = cglist.getElementsByClassName("atop"); + if(cg.length < 10) return; + for (var i = 0; i < cg.length; i++) { + cgid = cg[i].id.split("x")[0] + if(idlist.indexOf(cgid) >= 0) { + cg[i].style.display = "block"; + } else { + cg[i].style.display = "none"; + } + } + } + function callDetail(devid, devtitle) { + if(!(devid in devstats) || devstats[devid].length < 1) + return; + var list = devstats[devid]; + var tmp = devtitle.split(" "); + var name = tmp[0], phase = tmp[tmp.length-1]; + var dd = document.getElementById(phase); + var total = parseFloat(tmp[1].slice(1)); + var mlist = []; + var maxlen = 0; + var info = [] + for(var i in list) { + if(list[i][0] == "@") { + info = list[i].split("|"); + continue; + } + var tmp = list[i].split("|"); + var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]); + var p = (t*100.0/total).toFixed(2); + mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"]; + if(f.length > maxlen) + maxlen = f.length; + } + var pad = 5; + if(mlist.length == 0) pad = 30; + var html = '<div style="padding-top:'+pad+'px"><t3> <b>'+name+':</b>'; + if(info.length > 2) + html += " start=<b>"+info[1]+"</b>, end=<b>"+info[2]+"</b>"; + if(info.length > 3) + html += ", length<i>(w/o overhead)</i>=<b>"+info[3]+" ms</b>"; + if(info.length > 4) + html += ", return=<b>"+info[4]+"</b>"; + html += "</t3></div>"; + if(mlist.length > 0) { + html += '<table class=fstat style="padding-top:'+(maxlen*5)+'px;"><tr><th>Function</th>'; + for(var i in mlist) + html += "<td class=vt>"+mlist[i][0]+"</td>"; + html += "</tr><tr><th>Calls</th>"; + for(var i in mlist) + html += "<td>"+mlist[i][1]+"</td>"; + html += "</tr><tr><th>Time(ms)</th>"; + for(var i in mlist) + html += "<td>"+mlist[i][2]+"</td>"; + html += "</tr><tr><th>Percent</th>"; + for(var i in mlist) + html += "<td>"+mlist[i][3]+"</td>"; + html += "</tr></table>"; + } + dd.innerHTML = html; + var height = (maxlen*5)+100; + dd.style.height = height+"px"; + document.getElementById("devicedetail").style.height = height+"px"; + } + function callSelect() { + var cglist = document.getElementById("callgraphs"); + if(!cglist) return; + var cg = cglist.getElementsByClassName("atop"); + for (var i = 0; i < cg.length; i++) { + if(this.id == cg[i].id) { + cg[i].style.display = "block"; + } else { + cg[i].style.display = "none"; + } + } + } + function devListWindow(e) { + var win = window.open(); + var html = "<title>"+e.target.innerHTML+"</title>"+ + "<style type=\"text/css\">"+ + " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+ + "</style>" + var dt = devtable[0]; + if(e.target.id != "devlist1") + dt = devtable[1]; + win.document.write(html+dt); + } + function errWindow() { + var range = this.id.split("_"); + var idx1 = parseInt(range[0]); + var idx2 = parseInt(range[1]); + var win = window.open(); + var log = document.getElementById("dmesglog"); + var title = "<title>dmesg log</title>"; + var text = log.innerHTML.split("\n"); + var html = ""; + for(var i = 0; i < text.length; i++) { + if(i == idx1) { + html += "<e id=target>"+text[i]+"</e>\n"; + } else if(i > idx1 && i <= idx2) { + html += "<e>"+text[i]+"</e>\n"; + } else { + html += text[i]+"\n"; + } + } + win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>"); + win.location.hash = "#target"; + win.document.close(); + } + function logWindow(e) { + var name = e.target.id.slice(4); + var win = window.open(); + var log = document.getElementById(name+"log"); + var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>"; + win.document.write(title+"<pre>"+log.innerHTML+"</pre>"); + win.document.close(); + } + function onMouseDown(e) { + dragval[0] = e.clientX; + dragval[1] = document.getElementById("dmesgzoombox").scrollLeft; + document.onmousemove = onMouseMove; + } + function onMouseMove(e) { + var zoombox = document.getElementById("dmesgzoombox"); + zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX; + } + function onMouseUp(e) { + document.onmousemove = null; + } + function onKeyPress(e) { + var c = e.charCode; + if(c != 42 && c != 43 && c != 45) return; + var click = document.createEvent("Events"); + click.initEvent("click", true, false); + if(c == 43) + document.getElementById("zoomin").dispatchEvent(click); + else if(c == 45) + document.getElementById("zoomout").dispatchEvent(click); + else if(c == 42) + document.getElementById("zoomdef").dispatchEvent(click); + } + window.addEventListener("resize", function () {zoomTimeline();}); + window.addEventListener("load", function () { + var dmesg = document.getElementById("dmesg"); + dmesg.style.width = "100%" + dmesg.onmousedown = onMouseDown; + document.onmouseup = onMouseUp; + document.onkeypress = onKeyPress; + document.getElementById("zoomin").onclick = zoomTimeline; + document.getElementById("zoomout").onclick = zoomTimeline; + document.getElementById("zoomdef").onclick = zoomTimeline; + var list = document.getElementsByClassName("err"); + for (var i = 0; i < list.length; i++) + list[i].onclick = errWindow; + var list = document.getElementsByClassName("logbtn"); + for (var i = 0; i < list.length; i++) + list[i].onclick = logWindow; + list = document.getElementsByClassName("devlist"); + for (var i = 0; i < list.length; i++) + list[i].onclick = devListWindow; + var dev = dmesg.getElementsByClassName("thread"); + for (var i = 0; i < dev.length; i++) { + dev[i].onclick = deviceDetail; + dev[i].onmouseover = deviceHover; + dev[i].onmouseout = deviceUnhover; + } + var dev = dmesg.getElementsByClassName("srccall"); + for (var i = 0; i < dev.length; i++) + dev[i].onclick = callSelect; + zoomTimeline(); + }); +</script> """ hf.write(script_code); -def setRuntimeSuspend(before=True): - global sysvals - sv = sysvals - if sv.rs == 0: - return - if before: - # runtime suspend disable or enable - if sv.rs > 0: - sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled' - else: - sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled' - pprint('CONFIGURING RUNTIME SUSPEND...') - sv.rslist = deviceInfo(sv.rstgt) - for i in sv.rslist: - sv.setVal(sv.rsval, i) - pprint('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist))) - pprint('waiting 5 seconds...') - time.sleep(5) - else: - # runtime suspend re-enable or re-disable - for i in sv.rslist: - sv.setVal(sv.rstgt, i) - pprint('runtime suspend settings restored on %d devices' % len(sv.rslist)) - # Function: executeSuspend # Description: # Execute system suspend through the sysfs interface, then copy the output # dmesg and ftrace files to the test output directory. def executeSuspend(quiet=False): - pm = ProcessMonitor() - tp = sysvals.tpath - if sysvals.wifi: - wifi = sysvals.checkWifi() + sv, tp, pm = sysvals, sysvals.tpath, ProcessMonitor() + if sv.wifi: + wifi = sv.checkWifi() + sv.dlog('wifi check, connected device is "%s"' % wifi) testdata = [] # run these commands to prepare the system for suspend - if sysvals.display: + if sv.display: if not quiet: - pprint('SET DISPLAY TO %s' % sysvals.display.upper()) - displayControl(sysvals.display) + pprint('SET DISPLAY TO %s' % sv.display.upper()) + ret = sv.displayControl(sv.display) + sv.dlog('xset display %s, ret = %d' % (sv.display, ret)) time.sleep(1) - if sysvals.sync: + if sv.sync: if not quiet: pprint('SYNCING FILESYSTEMS') + sv.dlog('syncing filesystems') call('sync', shell=True) - # mark the start point in the kernel ring buffer just as we start - sysvals.initdmesg() - # start ftrace - if(sysvals.usecallgraph or sysvals.usetraceevents): - if not quiet: - pprint('START TRACING') - sysvals.fsetVal('1', 'tracing_on') - if sysvals.useprocmon: - pm.start() - sysvals.cmdinfo(True) + sv.dlog('read dmesg') + sv.initdmesg() + sv.dlog('cmdinfo before') + sv.cmdinfo(True) + sv.start(pm) # execute however many s/r runs requested - for count in range(1,sysvals.execcount+1): + for count in range(1,sv.execcount+1): # x2delay in between test runs - if(count > 1 and sysvals.x2delay > 0): - sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker') - time.sleep(sysvals.x2delay/1000.0) - sysvals.fsetVal('WAIT END', 'trace_marker') + if(count > 1 and sv.x2delay > 0): + sv.fsetVal('WAIT %d' % sv.x2delay, 'trace_marker') + time.sleep(sv.x2delay/1000.0) + sv.fsetVal('WAIT END', 'trace_marker') # start message - if sysvals.testcommand != '': + if sv.testcommand != '': pprint('COMMAND START') else: - if(sysvals.rtcwake): + if(sv.rtcwake): pprint('SUSPEND START') else: pprint('SUSPEND START (press a key to resume)') # set rtcwake - if(sysvals.rtcwake): + if(sv.rtcwake): if not quiet: - pprint('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) - sysvals.rtcWakeAlarmOn() + pprint('will issue an rtcwake in %d seconds' % sv.rtcwaketime) + sv.dlog('enable RTC wake alarm') + sv.rtcWakeAlarmOn() # start of suspend trace marker - if(sysvals.usecallgraph or sysvals.usetraceevents): - sysvals.fsetVal(datetime.now().strftime(sysvals.tmstart), 'trace_marker') + sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker') # predelay delay - if(count == 1 and sysvals.predelay > 0): - sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker') - time.sleep(sysvals.predelay/1000.0) - sysvals.fsetVal('WAIT END', 'trace_marker') + if(count == 1 and sv.predelay > 0): + sv.fsetVal('WAIT %d' % sv.predelay, 'trace_marker') + time.sleep(sv.predelay/1000.0) + sv.fsetVal('WAIT END', 'trace_marker') # initiate suspend or command + sv.dlog('system executing a suspend') tdata = {'error': ''} - if sysvals.testcommand != '': - res = call(sysvals.testcommand+' 2>&1', shell=True); + if sv.testcommand != '': + res = call(sv.testcommand+' 2>&1', shell=True); if res != 0: tdata['error'] = 'cmd returned %d' % res else: - mode = sysvals.suspendmode - if sysvals.memmode and os.path.exists(sysvals.mempowerfile): + s0ixready = sv.s0ixSupport() + mode = sv.suspendmode + if sv.memmode and os.path.exists(sv.mempowerfile): mode = 'mem' - pf = open(sysvals.mempowerfile, 'w') - pf.write(sysvals.memmode) - pf.close() - if sysvals.diskmode and os.path.exists(sysvals.diskpowerfile): + sv.testVal(sv.mempowerfile, 'radio', sv.memmode) + if sv.diskmode and os.path.exists(sv.diskpowerfile): mode = 'disk' - pf = open(sysvals.diskpowerfile, 'w') - pf.write(sysvals.diskmode) - pf.close() - if mode == 'freeze' and sysvals.haveTurbostat(): + sv.testVal(sv.diskpowerfile, 'radio', sv.diskmode) + if sv.acpidebug: + sv.testVal(sv.acpipath, 'acpi', '0xe') + if ((mode == 'freeze') or (sv.memmode == 's2idle')) \ + and sv.haveTurbostat(): # execution will pause here - turbo = sysvals.turbostat() + retval, turbo = sv.turbostat(s0ixready) + if retval != 0: + tdata['error'] ='turbostat returned %d' % retval if turbo: tdata['turbo'] = turbo else: - pf = open(sysvals.powerfile, 'w') + pf = open(sv.powerfile, 'w') pf.write(mode) # execution will pause here try: + pf.flush() pf.close() except Exception as e: tdata['error'] = str(e) - if(sysvals.rtcwake): - sysvals.rtcWakeAlarmOff() + sv.fsetVal('CMD COMPLETE', 'trace_marker') + sv.dlog('system returned') + # reset everything + sv.testVal('restoreall') + if(sv.rtcwake): + sv.dlog('disable RTC wake alarm') + sv.rtcWakeAlarmOff() # postdelay delay - if(count == sysvals.execcount and sysvals.postdelay > 0): - sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker') - time.sleep(sysvals.postdelay/1000.0) - sysvals.fsetVal('WAIT END', 'trace_marker') + if(count == sv.execcount and sv.postdelay > 0): + sv.fsetVal('WAIT %d' % sv.postdelay, 'trace_marker') + time.sleep(sv.postdelay/1000.0) + sv.fsetVal('WAIT END', 'trace_marker') # return from suspend pprint('RESUME COMPLETE') - if(sysvals.usecallgraph or sysvals.usetraceevents): - sysvals.fsetVal(datetime.now().strftime(sysvals.tmend), 'trace_marker') - if sysvals.wifi and wifi: - tdata['wifi'] = sysvals.pollWifi(wifi) - if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): + if(count < sv.execcount): + sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') + elif(not sv.wifitrace): + sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') + sv.stop(pm) + if sv.wifi and wifi: + tdata['wifi'] = sv.pollWifi(wifi) + sv.dlog('wifi check, %s' % tdata['wifi']) + if(count == sv.execcount and sv.wifitrace): + sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') + sv.stop(pm) + if sv.netfix: + tdata['netfix'] = sv.netfixon() + sv.dlog('netfix, %s' % tdata['netfix']) + if(sv.suspendmode == 'mem' or sv.suspendmode == 'command'): + sv.dlog('read the ACPI FPDT') tdata['fw'] = getFPDT(False) testdata.append(tdata) - cmdafter = sysvals.cmdinfo(False) - # stop ftrace - if(sysvals.usecallgraph or sysvals.usetraceevents): - if sysvals.useprocmon: - pm.stop() - sysvals.fsetVal('0', 'tracing_on') + sv.dlog('cmdinfo after') + cmdafter = sv.cmdinfo(False) # grab a copy of the dmesg output if not quiet: pprint('CAPTURING DMESG') - sysvals.getdmesg(testdata) + sv.getdmesg(testdata) # grab a copy of the ftrace output - if(sysvals.usecallgraph or sysvals.usetraceevents): + if sv.useftrace: if not quiet: pprint('CAPTURING TRACE') - op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata) - fp = open(tp+'trace', 'r') - for line in fp: - op.write(line) + op = sv.writeDatafileHeader(sv.ftracefile, testdata) + fp = open(tp+'trace', 'rb') + op.write(ascii(fp.read())) op.close() - sysvals.fsetVal('', 'trace') - sysvals.platforminfo(cmdafter) + sv.fsetVal('', 'trace') + sv.platforminfo(cmdafter) def readFile(file): if os.path.islink(file): @@ -5357,7 +5666,7 @@ def deviceInfo(output=''): tgtval = 'runtime_status' lines = dict() for dirname, dirnames, filenames in os.walk('/sys/devices'): - if(not re.match('.*/power', dirname) or + if(not re.match(r'.*/power', dirname) or 'control' not in filenames or tgtval not in filenames): continue @@ -5426,6 +5735,40 @@ def getModes(): fp.close() return modes +def dmidecode_backup(out, fatal=False): + cpath, spath, info = '/proc/cpuinfo', '/sys/class/dmi/id', { + 'bios-vendor': 'bios_vendor', + 'bios-version': 'bios_version', + 'bios-release-date': 'bios_date', + 'system-manufacturer': 'sys_vendor', + 'system-product-name': 'product_name', + 'system-version': 'product_version', + 'system-serial-number': 'product_serial', + 'baseboard-manufacturer': 'board_vendor', + 'baseboard-product-name': 'board_name', + 'baseboard-version': 'board_version', + 'baseboard-serial-number': 'board_serial', + 'chassis-manufacturer': 'chassis_vendor', + 'chassis-version': 'chassis_version', + 'chassis-serial-number': 'chassis_serial', + } + for key in info: + if key not in out: + val = sysvals.getVal(os.path.join(spath, info[key])).strip() + if val and val.lower() != 'to be filled by o.e.m.': + out[key] = val + if 'processor-version' not in out and os.path.exists(cpath): + with open(cpath, 'r') as fp: + for line in fp: + m = re.match(r'^model\s*name\s*\:\s*(?P<c>.*)', line) + if m: + out['processor-version'] = m.group('c').strip() + break + if fatal and len(out) < 1: + doError('dmidecode failed to get info from %s or %s' % \ + (sysvals.mempath, spath)) + return out + # Function: dmidecode # Description: # Read the bios tables and pull out system info @@ -5436,6 +5779,8 @@ def getModes(): # A dict object with all available key/values def dmidecode(mempath, fatal=False): out = dict() + if(not (os.path.exists(mempath) and os.access(mempath, os.R_OK))): + return dmidecode_backup(out, fatal) # the list of values to retrieve, with hardcoded (type, idx) info = { @@ -5451,24 +5796,14 @@ def dmidecode(mempath, fatal=False): 'baseboard-version': (2, 6), 'baseboard-serial-number': (2, 7), 'chassis-manufacturer': (3, 4), - 'chassis-type': (3, 5), 'chassis-version': (3, 6), 'chassis-serial-number': (3, 7), 'processor-manufacturer': (4, 7), 'processor-version': (4, 16), } - if(not os.path.exists(mempath)): - if(fatal): - doError('file does not exist: %s' % mempath) - return out - if(not os.access(mempath, os.R_OK)): - if(fatal): - doError('file is not readable: %s' % mempath) - return out # by default use legacy scan, but try to use EFI first - memaddr = 0xf0000 - memsize = 0x10000 + memaddr, memsize = 0xf0000, 0x10000 for ep in ['/sys/firmware/efi/systab', '/proc/efi/systab']: if not os.path.exists(ep) or not os.access(ep, os.R_OK): continue @@ -5489,11 +5824,7 @@ def dmidecode(mempath, fatal=False): fp.seek(memaddr) buf = fp.read(memsize) except: - if(fatal): - doError('DMI table is unreachable, sorry') - else: - pprint('WARNING: /dev/mem is not readable, ignoring DMI data') - return out + return dmidecode_backup(out, fatal) fp.close() # search for either an SM table or DMI table @@ -5509,10 +5840,7 @@ def dmidecode(mempath, fatal=False): break i += 16 if base == 0 and length == 0 and num == 0: - if(fatal): - doError('Neither SMBIOS nor DMI were found') - else: - return out + return dmidecode_backup(out, fatal) # read in the SM or DMI table try: @@ -5520,11 +5848,7 @@ def dmidecode(mempath, fatal=False): fp.seek(base) buf = fp.read(length) except: - if(fatal): - doError('DMI table is unreachable, sorry') - else: - pprint('WARNING: /dev/mem is not readable, ignoring DMI data') - return out + return dmidecode_backup(out, fatal) fp.close() # scan the table for the values we want @@ -5549,39 +5873,6 @@ def dmidecode(mempath, fatal=False): count += 1 return out -def displayControl(cmd): - xset, ret = 'timeout 10 xset -d :0.0 {0}', 0 - if sysvals.sudouser: - xset = 'sudo -u %s %s' % (sysvals.sudouser, xset) - if cmd == 'init': - ret = call(xset.format('dpms 0 0 0'), shell=True) - if not ret: - ret = call(xset.format('s off'), shell=True) - elif cmd == 'reset': - ret = call(xset.format('s reset'), shell=True) - elif cmd in ['on', 'off', 'standby', 'suspend']: - b4 = displayControl('stat') - ret = call(xset.format('dpms force %s' % cmd), shell=True) - if not ret: - curr = displayControl('stat') - sysvals.vprint('Display Switched: %s -> %s' % (b4, curr)) - if curr != cmd: - sysvals.vprint('WARNING: Display failed to change to %s' % cmd) - if ret: - sysvals.vprint('WARNING: Display failed to change to %s with xset' % cmd) - return ret - elif cmd == 'stat': - fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout - ret = 'unknown' - for line in fp: - m = re.match('[\s]*Monitor is (?P<m>.*)', ascii(line)) - if(m and len(m.group('m')) >= 2): - out = m.group('m').lower() - ret = out[3:] if out[0:2] == 'in' else out - break - fp.close() - return ret - # Function: getFPDT # Description: # Read the acpi bios tables and pull out FPDT, the firmware data @@ -5761,13 +6052,19 @@ def statusCheck(probecheck=False): pprint(' please choose one with -m') # check if ftrace is available - res = sysvals.colorText('NO') - ftgood = sysvals.verifyFtrace() - if(ftgood): - res = 'YES' - elif(sysvals.usecallgraph): - status = 'ftrace is not properly supported' - pprint(' is ftrace supported: %s' % res) + if sysvals.useftrace: + res = sysvals.colorText('NO') + sysvals.useftrace = sysvals.verifyFtrace() + efmt = '"{0}" uses ftrace, and it is not properly supported' + if sysvals.useftrace: + res = 'YES' + elif sysvals.usecallgraph: + status = efmt.format('-f') + elif sysvals.usedevsrc: + status = efmt.format('-dev') + elif sysvals.useprocmon: + status = efmt.format('-proc') + pprint(' is ftrace supported: %s' % res) # check if kprobes are available if sysvals.usekprobes: @@ -5780,8 +6077,8 @@ def statusCheck(probecheck=False): pprint(' are kprobes supported: %s' % res) # what data source are we using - res = 'DMESG' - if(ftgood): + res = 'DMESG (very limited, ftrace is preferred)' + if sysvals.useftrace: sysvals.usetraceevents = True for e in sysvals.traceevents: if not os.path.exists(sysvals.epath+e): @@ -5802,7 +6099,7 @@ def statusCheck(probecheck=False): pprint(' optional commands this tool may use for info:') no = sysvals.colorText('MISSING') yes = sysvals.colorText('FOUND', 32) - for c in ['turbostat', 'mcelog', 'lspci', 'lsusb']: + for c in ['turbostat', 'mcelog', 'lspci', 'lsusb', 'netfix']: if c == 'turbostat': res = yes if sysvals.haveTurbostat() else no else: @@ -5876,7 +6173,7 @@ def getArgFloat(name, args, min, max, main=True): def processData(live=False, quiet=False): if not quiet: - pprint('PROCESSING DATA') + pprint('PROCESSING: %s' % sysvals.htmlfile) sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \ (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes)) error = '' @@ -5894,7 +6191,7 @@ def processData(live=False, quiet=False): if not sysvals.stamp: pprint('ERROR: data does not include the expected stamp') return (testruns, {'error': 'timeline generation failed'}) - shown = ['bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', + shown = ['os', 'bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', 'memsz', 'mode', 'numcpu', 'plat', 'time', 'wifi'] sysvals.vprint('System Info:') for key in sorted(sysvals.stamp): @@ -5928,7 +6225,7 @@ def processData(live=False, quiet=False): sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) createHTML(testruns, error) if not quiet: - pprint('DONE') + pprint('DONE: %s' % sysvals.htmlfile) data = testruns[0] stamp = data.stamp stamp['suspend'], stamp['resume'] = data.getTimeValues() @@ -5964,8 +6261,21 @@ def rerunTest(htmlfile=''): # execute a suspend/resume, gather the logs, and generate the output def runTest(n=0, quiet=False): # prepare for the test - sysvals.initFtrace(quiet) sysvals.initTestOutput('suspend') + op = sysvals.writeDatafileHeader(sysvals.dmesgfile, []) + op.write('# EXECUTION TRACE START\n') + op.close() + if n <= 1: + if sysvals.rs != 0: + sysvals.dlog('%sabling runtime suspend' % ('en' if sysvals.rs > 0 else 'dis')) + sysvals.setRuntimeSuspend(True) + if sysvals.display: + ret = sysvals.displayControl('init') + sysvals.dlog('xset display init, ret = %d' % ret) + sysvals.testVal(sysvals.pmdpath, 'basic', '1') + sysvals.testVal(sysvals.s0ixpath, 'basic', 'Y') + sysvals.dlog('initialize ftrace') + sysvals.initFtrace(quiet) # execute the test executeSuspend(quiet) @@ -5984,31 +6294,36 @@ def runTest(n=0, quiet=False): return 0 def find_in_html(html, start, end, firstonly=True): - n, cnt, out = 0, len(html), [] - while n < cnt: - e = cnt if (n + 10000 > cnt or n == 0) else n + 10000 - m = re.search(start, html[n:e]) - if not m: - break - i = m.end() - m = re.search(end, html[n+i:e]) + cnt, out, list = len(html), [], [] + if firstonly: + m = re.search(start, html) + if m: + list.append(m) + else: + list = re.finditer(start, html) + for match in list: + s = match.end() + e = cnt if (len(out) < 1 or s + 10000 > cnt) else s + 10000 + m = re.search(end, html[s:e]) if not m: break - j = m.start() - str = html[n+i:n+i+j] + e = s + m.start() + str = html[s:e] if end == 'ms': num = re.search(r'[-+]?\d*\.\d+|\d+', str) str = num.group() if num else 'NaN' if firstonly: return str out.append(str) - n += i+j if firstonly: return '' return out def data_from_html(file, outpath, issues, fulldetail=False): - html = open(file, 'r').read() + try: + html = open(file, 'r').read() + except: + html = ascii(open(file, 'rb').read()) sysvals.htmlfile = os.path.relpath(file, outpath) # extract general info suspend = find_in_html(html, 'Kernel Suspend', 'ms') @@ -6026,7 +6341,7 @@ def data_from_html(file, outpath, issues, fulldetail=False): tstr = dt.strftime('%Y/%m/%d %H:%M:%S') error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>') if error: - m = re.match('[a-z0-9]* failed in (?P<p>\S*).*', error) + m = re.match(r'[a-z0-9]* failed in (?P<p>\S*).*', error) if m: result = 'fail in %s' % m.group('p') else: @@ -6034,7 +6349,7 @@ def data_from_html(file, outpath, issues, fulldetail=False): else: result = 'pass' # extract error info - ilist = [] + tp, ilist = False, [] extra = dict() log = find_in_html(html, '<div id="dmesglog" style="display:none;">', '</div>').strip() @@ -6042,9 +6357,10 @@ def data_from_html(file, outpath, issues, fulldetail=False): d = Data(0) d.end = 999999999 d.dmesgtext = log.split('\n') - msglist = d.extractErrorInfo() - for msg in msglist: - sysvals.errorSummary(issues, msg) + tp = d.extractErrorInfo() + if len(issues) < 100: + for msg in tp.msglist: + sysvals.errorSummary(issues, msg) if stmp[2] == 'freeze': extra = d.turbostatInfo() elist = dict() @@ -6055,12 +6371,28 @@ def data_from_html(file, outpath, issues, fulldetail=False): elist[err[0]] += 1 for i in elist: ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i) - wifi = find_in_html(html, 'Wifi Resume: ', '</td>') - if wifi: - extra['wifi'] = wifi + line = find_in_html(log, '# wifi ', '\n') + if line: + extra['wifi'] = line + line = find_in_html(log, '# netfix ', '\n') + if line: + extra['netfix'] = line + line = find_in_html(log, '# command ', '\n') + if line: + m = re.match(r'.* -m (?P<m>\S*).*', line) + if m: + extra['fullmode'] = m.group('m') low = find_in_html(html, 'freeze time: <b>', ' ms</b>') - if low and '|' in low: - issue = 'FREEZEx%d' % len(low.split('|')) + for lowstr in ['waking', '+']: + if not low: + break + if lowstr not in low: + continue + if lowstr == '+': + issue = 'S2LOOPx%d' % len(low.split('+')) + else: + m = re.match(r'.*waking *(?P<n>[0-9]*) *times.*', low) + issue = 'S2WAKEx%s' % m.group('n') if m else 'S2WAKExNaN' match = [i for i in issues if i['match'] == issue] if len(match) > 0: match[0]['count'] += 1 @@ -6077,13 +6409,15 @@ def data_from_html(file, outpath, issues, fulldetail=False): # extract device info devices = dict() for line in html.split('\n'): - m = re.match(' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line) + m = re.match(r' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line) if not m or 'thread kth' in line or 'thread sec' in line: continue - m = re.match('(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title')) + m = re.match(r'(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title')) if not m: continue name, time, phase = m.group('n'), m.group('t'), m.group('p') + if name == 'async_synchronize_full': + continue if ' async' in name or ' sync' in name: name = ' '.join(name.split(' ')[:-1]) if phase.startswith('suspend'): @@ -6126,6 +6460,11 @@ def data_from_html(file, outpath, issues, fulldetail=False): data[key] = extra[key] if fulldetail: data['funclist'] = find_in_html(html, '<div title="', '" class="traceevent"', False) + if tp: + for arg in ['-multi ', '-info ']: + if arg in tp.cmdline: + data['target'] = tp.cmdline[tp.cmdline.find(arg):].split()[1] + break return data def genHtml(subdir, force=False): @@ -6134,13 +6473,13 @@ def genHtml(subdir, force=False): for filename in filenames: file = os.path.join(dirname, filename) if sysvals.usable(file): - if(re.match('.*_dmesg.txt', filename)): + if(re.match(r'.*_dmesg.txt', filename)): sysvals.dmesgfile = file - elif(re.match('.*_ftrace.txt', filename)): + elif(re.match(r'.*_ftrace.txt', filename)): sysvals.ftracefile = file sysvals.setOutputFile() if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \ - (force or not sysvals.usable(sysvals.htmlfile)): + (force or not sysvals.usable(sysvals.htmlfile, True)): pprint('FTRACE: %s' % sysvals.ftracefile) if sysvals.dmesgfile: pprint('DMESG : %s' % sysvals.dmesgfile) @@ -6155,16 +6494,17 @@ def runSummary(subdir, local=True, genhtml=False): pprint('Generating a summary of folder:\n %s' % inpath) if genhtml: genHtml(subdir) - issues = [] - testruns = [] + target, issues, testruns = '', [], [] desc = {'host':[],'mode':[],'kernel':[]} for dirname, dirnames, filenames in os.walk(subdir): for filename in filenames: - if(not re.match('.*.html', filename)): + if(not re.match(r'.*.html', filename)): continue data = data_from_html(os.path.join(dirname, filename), outpath, issues) if(not data): continue + if 'target' in data: + target = data['target'] testruns.append(data) for key in desc: if data[key] not in desc[key]: @@ -6172,6 +6512,8 @@ def runSummary(subdir, local=True, genhtml=False): pprint('Summary files:') if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1: title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0]) + if target: + title += ' %s' % target else: title = inpath createHTMLSummarySimple(testruns, os.path.join(outpath, 'summary.html'), title) @@ -6427,6 +6769,9 @@ def printHelp(): ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\ ' -result fn Export a results table to a text file for parsing.\n'\ ' -wifi If a wifi connection is available, check that it reconnects after resume.\n'\ + ' -wifitrace Trace kernel execution through wifi reconnect.\n'\ + ' -netfix Use netfix to reset the network in the event it fails to resume.\n'\ + ' -debugtiming Add timestamp to each printed line\n'\ ' [testprep]\n'\ ' -sync Sync the filesystems before starting the test\n'\ ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\ @@ -6509,6 +6854,8 @@ if __name__ == '__main__': elif(arg == '-v'): pprint("Version %s" % sysvals.version) sys.exit(0) + elif(arg == '-debugtiming'): + debugtiming = True elif(arg == '-x2'): sysvals.execcount = 2 elif(arg == '-x2delay'): @@ -6551,6 +6898,10 @@ if __name__ == '__main__': sysvals.sync = True elif(arg == '-wifi'): sysvals.wifi = True + elif(arg == '-wifitrace'): + sysvals.wifitrace = True + elif(arg == '-netfix'): + sysvals.netfix = True elif(arg == '-gzip'): sysvals.gzip = True elif(arg == '-info'): @@ -6558,6 +6909,11 @@ if __name__ == '__main__': val = next(args) except: doError('-info requires one string argument', True) + elif(arg == '-desc'): + try: + val = next(args) + except: + doError('-desc requires one string argument', True) elif(arg == '-rs'): try: val = next(args) @@ -6721,7 +7077,6 @@ if __name__ == '__main__': except: doError('No result file supplied', True) sysvals.result = val - sysvals.signalHandlerInit() else: doError('Invalid argument: '+arg, True) @@ -6731,6 +7086,7 @@ if __name__ == '__main__': if(sysvals.usecallgraph and sysvals.useprocmon): doError('-proc is not compatible with -f') + sysvals.signalHandlerInit() if sysvals.usecallgraph and sysvals.cgskip: sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip) sysvals.setCallgraphBlacklist(sysvals.cgskip) @@ -6767,9 +7123,9 @@ if __name__ == '__main__': runSummary(sysvals.outdir, True, genhtml) elif(cmd in ['xon', 'xoff', 'xstandby', 'xsuspend', 'xinit', 'xreset']): sysvals.verbose = True - ret = displayControl(cmd[1:]) + ret = sysvals.displayControl(cmd[1:]) elif(cmd == 'xstat'): - pprint('Display Status: %s' % displayControl('stat').upper()) + pprint('Display Status: %s' % sysvals.displayControl('stat').upper()) elif(cmd == 'wificheck'): dev = sysvals.checkWifi() if dev: @@ -6807,12 +7163,8 @@ if __name__ == '__main__': if mode.startswith('disk-'): sysvals.diskmode = mode.split('-', 1)[-1] sysvals.suspendmode = 'disk' - sysvals.systemInfo(dmidecode(sysvals.mempath)) - setRuntimeSuspend(True) - if sysvals.display: - displayControl('init') failcnt, ret = 0, 0 if sysvals.multitest['run']: # run multiple tests in a separate subdirectory @@ -6835,12 +7187,11 @@ if __name__ == '__main__': time.sleep(sysvals.multitest['delay']) fmt = 'suspend-%y%m%d-%H%M%S' sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) - ret = runTest(i+1, True) + ret = runTest(i+1, not sysvals.verbose) failcnt = 0 if not ret else failcnt + 1 if sysvals.maxfail > 0 and failcnt >= sysvals.maxfail: pprint('Maximum fail count of %d reached, aborting multitest' % (sysvals.maxfail)) break - time.sleep(5) sysvals.resetlog() sysvals.multistat(False, i, finish) if 'time' in sysvals.multitest and datetime.now() >= finish: @@ -6853,7 +7204,10 @@ if __name__ == '__main__': sysvals.testdir = sysvals.outdir # run the test in the current directory ret = runTest() + + # reset to default values after testing if sysvals.display: - displayControl('reset') - setRuntimeSuspend(False) + sysvals.displayControl('reset') + if sysvals.rs != 0: + sysvals.setRuntimeSuspend(False) sys.exit(ret) |