diff options
Diffstat (limited to 'tools/power/pm-graph/sleepgraph.py')
| -rwxr-xr-x | tools/power/pm-graph/sleepgraph.py | 1960 |
1 files changed, 1171 insertions, 789 deletions
diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index f7d1c1f62f86..cfe343306e08 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -1,4 +1,4 @@ -#!/usr/bin/python +#!/usr/bin/env python3 # SPDX-License-Identifier: GPL-2.0-only # # Tool for analyzing suspend/resume timing @@ -58,7 +58,7 @@ import re import platform import signal import codecs -from datetime import datetime +from datetime import datetime, timedelta import struct import configparser import gzip @@ -66,8 +66,13 @@ from threading import Thread from subprocess import call, Popen, PIPE import base64 +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,23 +86,28 @@ def ascii(text): # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.5' + version = '5.10' 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 cgskip = '' - multitest = {'run': False, 'count': 0, 'delay': 0} + maxfail = 0 + multitest = {'run': False, 'count': 1000000, 'delay': 0} max_graph_depth = 0 callloopmaxgap = 0.0001 callloopmaxlen = 0.005 @@ -105,6 +115,7 @@ class SystemValues: cpucount = 0 memtotal = 204800 memfree = 204800 + osversion = '' srgap = 0 cgexp = False testdir = '' @@ -113,6 +124,9 @@ class SystemValues: fpdtpath = '/sys/firmware/acpi/tables/FPDT' epath = '/sys/kernel/debug/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', @@ -148,10 +162,11 @@ class SystemValues: x2delay = 0 skiphtml = False usecallgraph = False - ftopfunc = 'suspend_devices_and_enter' + ftopfunc = 'pm_suspend' ftop = False usetraceevents = False usetracemarkers = True + useftrace = True usekprobes = True usedevsrc = False useprocmon = False @@ -160,11 +175,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': {}, @@ -183,9 +201,11 @@ class SystemValues: 'acpi_s2idle_sync': {}, 'acpi_s2idle_begin': {}, 'acpi_s2idle_prepare': {}, + 'acpi_s2idle_prepare_late': {}, 'acpi_s2idle_wake': {}, 'acpi_s2idle_wakeup': {}, 'acpi_s2idle_restore': {}, + 'acpi_s2idle_restore_early': {}, 'hibernate_preallocate_memory': {}, 'create_basic_memory_bitmaps': {}, 'swsusp_write': {}, @@ -270,12 +290,30 @@ class SystemValues: 'intel_opregion_init': {}, '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', '-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'], + [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() timeformat = '%.3f' cmdline = '%s %s' % \ (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:])) - kparams = '' sudouser = '' def __init__(self): self.archargs = 'args_'+platform.machine() @@ -295,6 +333,9 @@ class SystemValues: if os.getuid() == 0 and 'SUDO_USER' in os.environ and \ os.environ['SUDO_USER']: self.sudouser = os.environ['SUDO_USER'] + def resetlog(self): + self.logmsg = '' + self.platinfo = [] def vprint(self, msg): self.logmsg += msg+'\n' if self.verbose or msg.startswith('WARNING:'): @@ -304,11 +345,11 @@ class SystemValues: 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) - sysvals.outputResult({'error':msg}) + self.outputResult({'error':msg}) sys.exit(3) def signalHandlerInit(self): capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT', - 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM', 'TSTP'] + 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM'] self.signames = dict() for i in capture: s = 'SIG'+i @@ -336,6 +377,19 @@ class SystemValues: self.outputResult({'error':msg}) sys.exit(1) return False + 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 @@ -389,18 +443,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) - try: - kcmd = open('/proc/cmdline', 'r').read().strip() - except: - kcmd = '' - if kcmd: - self.sysstamp += '\n# kparams | %s' % kcmd + 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))) @@ -408,20 +460,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('^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('^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')) + 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() @@ -441,6 +498,7 @@ class SystemValues: self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' if not os.path.isdir(self.testdir): os.makedirs(self.testdir) + self.sudoUserchown(self.testdir) def getValueList(self, value): out = [] for i in value.split(','): @@ -473,9 +531,9 @@ 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: @@ -483,10 +541,10 @@ class SystemValues: m = re.match('[ \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(sysvals.dmesgfile, testdata) + op = self.writeDatafileHeader(self.dmesgfile, testdata) # store all new dmesg lines since initdmesg was called fp = Popen('dmesg', stdout=PIPE).stdout for line in fp: @@ -679,6 +737,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 = '' @@ -692,14 +752,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]) @@ -716,17 +776,15 @@ class SystemValues: if name == f: return True return False - def initFtrace(self): - self.printSystemInfo(False) - pprint('INITIALIZING FTRACE...') + def initFtrace(self, quiet=False): + if not self.useftrace: + return + if not quiet: + sysvals.printSystemInfo(False) + 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') @@ -746,12 +804,16 @@ class SystemValues: if tgtsize < 65536: tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus break - pprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)) + self.vprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)) # initialize the callgraph trace if(self.usecallgraph): # 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') @@ -782,7 +844,8 @@ class SystemValues: if self.usedevsrc: for name in self.dev_tracefuncs: self.defaultKprobe(name, self.dev_tracefuncs[name]) - pprint('INITIALIZING KPROBES...') + if not quiet: + pprint('INITIALIZING KPROBES') self.addKprobes(self.verbose) if(self.usetraceevents): # turn trace events on @@ -827,21 +890,12 @@ class SystemValues: fw = test['fw'] if(fw): fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) - if 'mcelog' in test: - fp.write('# mcelog %s\n' % test['mcelog']) if 'turbo' in test: fp.write('# turbostat %s\n' % test['turbo']) - if 'bat' in test: - (a1, c1), (a2, c2) = test['bat'] - fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2)) if 'wifi' in test: - wstr = [] - for wifi in test['wifi']: - tmp = [] - for key in sorted(wifi): - tmp.append('%s:%s' % (key, wifi[key])) - wstr.append('|'.join(tmp)) - fp.write('# wifi %s\n' % (','.join(wstr))) + 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 @@ -861,6 +915,8 @@ class SystemValues: 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])) @@ -892,6 +948,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() @@ -901,23 +967,7 @@ class SystemValues: def b64zip(self, data): out = base64.b64encode(codecs.encode(data.encode(), 'zlib')).decode() return out - def mcelog(self, clear=False): - cmd = self.getExec('mcelog') - if not cmd: - return '' - if clear: - call(cmd+' > /dev/null 2>&1', shell=True) - return '' - try: - fp = Popen([cmd], stdout=PIPE, stderr=PIPE).stdout - out = ascii(fp.read()).strip() - fp.close() - except: - return '' - if not out: - return '' - return self.b64zip(out) - def platforminfo(self): + def platforminfo(self, cmdafter): # add platform info on to a completed ftrace file if not os.path.exists(self.ftracefile): return False @@ -932,10 +982,7 @@ 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) @@ -961,34 +1008,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(';', ' ') @@ -1001,31 +1045,107 @@ class SystemValues: footer += '# platform-devinfo: %s\n' % self.b64zip(out) # add a line for each of these commands with their outputs - cmds = [ - ['pcidevices', 'lspci', '-tv'], - ['interrupts', 'cat', '/proc/interrupts'], - ['gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/gpe*'], - ] - for cargs in cmds: - name = cargs[0] - cmdline = ' '.join(cargs[1:]) - cmdpath = self.getExec(cargs[1]) - if not cmdpath: + for name, cmdline, info in cmdafter: + footer += '# platform-%s: %s | %s\n' % (name, cmdline, self.b64zip(info)) + self.flog(footer) + return True + def commonPrefix(self, list): + if len(list) < 2: + return '' + prefix = list[0] + for s in list[1:]: + while s[:len(prefix)] != prefix and prefix: + prefix = prefix[:len(prefix)-1] + if not prefix: + break + if '/' in prefix and prefix[-1] != '/': + prefix = prefix[0:prefix.rfind('/')+1] + return prefix + def dictify(self, text, format): + out = dict() + header = True if format == 1 else False + delim = ' ' if format == 1 else ':' + for line in text.split('\n'): + if header: + header, out['@'] = False, line continue - cmd = [cmdpath] + cargs[2:] + line = line.strip() + if delim in line: + data = line.split(delim, 1) + num = re.search(r'[\d]+', data[1]) + if format == 2 and num: + out[data[0].strip()] = num.group() + else: + out[data[0].strip()] = data[1] + return out + 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]) + if not cmdpath or (begin and not delta): + continue + self.dlog('[%s]' % cmdline) try: - fp = Popen(cmd, stdout=PIPE, stderr=PIPE).stdout + fp = Popen([cmdpath]+cargs[3:], stdout=PIPE, stderr=PIPE).stdout info = ascii(fp.read()).strip() fp.close() except: continue - if not info: - continue - footer += '# platform-%s: %s | %s\n' % (name, cmdline, self.b64zip(info)) - - with self.openlog(self.ftracefile, 'a') as fp: - fp.write(footer) - return True + if not debug and begin: + 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 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]: + title = key.replace(prefix, '') + if delta == 2: + dinfo += '\t%s : %s -> %s\n' % \ + (title, before[key].strip(), after[key].strip()) + else: + dinfo += '%10s (start) : %s\n%10s (after) : %s\n' % \ + (title, before[key], title, after[key]) + dinfo = '\tnothing changed' if not dinfo else dinfo.rstrip() + out.append((name, cmdline, dinfo)) + 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('.*\[(?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('.* (?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 @@ -1035,11 +1155,11 @@ class SystemValues: fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr out = ascii(fp.read()).strip() fp.close() - if re.match('turbostat version [0-9\.]* .*', out): - sysvals.vprint(out) + if re.match('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) @@ -1056,42 +1176,58 @@ class SystemValues: fp.close() if not keyline or not valline or len(keyline) != len(valline): errmsg = 'unrecognized turbostat output:\n'+rawout.strip() - sysvals.vprint(errmsg) - if not sysvals.verbose: + self.vprint(errmsg) + if not self.verbose: pprint(errmsg) return '' - if sysvals.verbose: + 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('^[0\.]*$', val): + continue out.append('%s=%s' % (key, val)) return '|'.join(out) - def checkWifi(self): - out = dict() - iwcmd, ifcmd = self.getExec('iwconfig'), self.getExec('ifconfig') - if not iwcmd or not ifcmd: - return out - fp = Popen(iwcmd, stdout=PIPE, stderr=PIPE).stdout - for line in fp: - m = re.match('(?P<dev>\S*) .* ESSID:(?P<ess>\S*)', ascii(line)) - if not m: - continue - out['device'] = m.group('dev') - if '"' in m.group('ess'): - out['essid'] = m.group('ess').strip('"') - break + 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() - if 'device' in out: - fp = Popen([ifcmd, out['device']], stdout=PIPE, stderr=PIPE).stdout - for line in fp: - m = re.match('.* inet (?P<ip>[0-9\.]*)', ascii(line)) - if m: - out['ip'] = m.group('ip') - break - fp.close() return out + def wifiDetails(self, dev): + try: + info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip() + except: + return dev + vals = [dev] + for prop in info.split('\n'): + if prop.startswith('DRIVER=') or prop.startswith('PCI_ID='): + vals.append(prop.split('=')[-1]) + return ':'.join(vals) + def checkWifi(self, dev=''): + try: + w = open('/proc/net/wireless', 'r').read().strip() + except: + return '' + for line in reversed(w.split('\n')): + m = re.match(' *(?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=10): + start = time.time() + while (time.time() - start) < timeout: + w = self.checkWifi(dev) + if w: + return '%s reconnected %.2f' % \ + (self.wifiDetails(dev), max(0, time.time() - start)) + time.sleep(0.01) + return '%s timeout %d' % (self.wifiDetails(dev), timeout) def errorSummary(self, errinfo, msg): found = False for entry in errinfo: @@ -1113,8 +1249,9 @@ class SystemValues: arr[j] = arr[j]\ .replace('\\', '\\\\').replace(']', '\]').replace('[', '\[')\ .replace('.', '\.').replace('+', '\+').replace('*', '\*')\ - .replace('(', '\(').replace(')', '\)') - mstr = ' '.join(arr) + .replace('(', '\(').replace(')', '\)').replace('}', '\}')\ + .replace('{', '\{') + mstr = ' *'.join(arr) entry = { 'line': msg, 'match': mstr, @@ -1122,15 +1259,118 @@ class SystemValues: 'urls': {self.hostname: [self.htmlfile]} } errinfo.append(entry) + def multistat(self, start, idx, finish): + if 'time' in self.multitest: + id = '%d Duration=%dmin' % (idx+1, self.multitest['time']) + else: + id = '%d/%d' % (idx+1, self.multitest['count']) + t = time.time() + if 'start' not in self.multitest: + self.multitest['start'] = self.multitest['last'] = t + self.multitest['total'] = 0.0 + pprint('TEST (%s) START' % id) + return + dt = t - self.multitest['last'] + if not start: + if idx == 0 and self.multitest['delay'] > 0: + self.multitest['total'] += self.multitest['delay'] + pprint('TEST (%s) COMPLETE -- Duration %.1fs' % (id, dt)) + return + self.multitest['total'] += dt + self.multitest['last'] = t + avg = self.multitest['total'] / idx + if 'time' in self.multitest: + left = finish - datetime.now() + left -= timedelta(microseconds=left.microseconds) + else: + left = timedelta(seconds=((self.multitest['count'] - idx) * int(avg))) + pprint('TEST (%s) START - Avg Duration %.1fs, Time left %s' % \ + (id, avg, str(left))) + def multiinit(self, c, d): + sz, unit = 'count', 'm' + if c.endswith('d') or c.endswith('h') or c.endswith('m'): + sz, unit, c = 'time', c[-1], c[:-1] + self.multitest['run'] = True + self.multitest[sz] = getArgInt('multi: n d (exec count)', c, 1, 1000000, False) + self.multitest['delay'] = getArgInt('multi: n d (delay between tests)', d, 0, 3600, False) + if unit == 'd': + 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('[\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 @@ -1162,8 +1402,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: @@ -1210,25 +1450,32 @@ class Data: 'resume_complete': {'order': 9, 'color': '#FFFFCC'}, } errlist = { - 'HWERROR' : '.*\[ *Hardware Error *\].*', - 'FWBUG' : '.*\[ *Firmware Bug *\].*', - 'BUG' : '.*BUG.*', - 'ERROR' : '.*ERROR.*', - 'WARNING' : '.*WARNING.*', - 'IRQ' : '.*genirq: .*', - 'TASKFAIL': '.*Freezing of tasks *.*', - 'ACPI' : '.*ACPI *(?P<b>[A-Za-z]*) *Error[: ].*', - 'DEVFAIL' : '.* failed to (?P<b>[a-z]*) async: .*', - 'DISKFULL': '.*No space left on device.*', - 'USBERR' : '.*usb .*device .*, error [0-9-]*', - 'ATAERR' : ' *ata[0-9\.]*: .*failed.*', - 'MEIERR' : ' *mei.*: .*failed.*', - 'TPMERR' : '(?i) *tpm *tpm[0-9]*: .*error.*', + 'HWERROR' : r'.*\[ *Hardware Error *\].*', + 'FWBUG' : r'.*\[ *Firmware Bug *\].*', + 'BUG' : r'(?i).*\bBUG\b.*', + 'ERROR' : r'(?i).*\bERROR\b.*', + 'WARNING' : r'(?i).*\bWARNING\b.*', + 'FAULT' : r'(?i).*\bFAULT\b.*', + '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-]*', + 'ATAERR' : r' *ata[0-9\.]*: .*failed.*', + 'MEIERR' : r' *mei.*: .*failed.*', + 'TPMERR' : r'(?i) *tpm *tpm[0-9]*: .*error.*', } def __init__(self, num): idchar = 'abcdefghij' self.start = 0.0 # test start self.end = 0.0 # test end + self.hwstart = 0 # rtc test start + self.hwend = 0 # rtc test end self.tSuspended = 0.0 # low-level suspend start self.tResumed = 0.0 # low-level resume start self.tKernSus = 0.0 # kernel level suspend start @@ -1240,10 +1487,8 @@ class Data: self.stamp = 0 self.outfile = '' self.kerror = False - self.battery = 0 - self.wifi = 0 + self.wifi = dict() self.turbostat = 0 - self.mcelog = 0 self.enterfail = '' self.currphase = '' self.pstl = dict() # process timeline @@ -1273,11 +1518,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'} @@ -1297,9 +1542,12 @@ 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 + if tp.stampInfo(line, sysvals): + continue m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if not m: continue @@ -1308,25 +1556,36 @@ class Data: continue dir = 'suspend' if t < self.tSuspended else 'resume' msg = m.group('msg') + if re.match('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) - sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t)) + 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 - def setStart(self, time): + return tp + def setStart(self, time, msg=''): self.start = time - def setEnd(self, time): + if msg: + try: + self.hwstart = datetime.strptime(msg, sysvals.tmstart) + except: + self.hwstart = 0 + def setEnd(self, time, msg=''): self.end = time + if msg: + try: + self.hwend = datetime.strptime(msg, sysvals.tmend) + except: + self.hwend = 0 def isTraceEventOutsideDeviceCalls(self, pid, time): for phase in self.sortedPhases(): list = self.dmesg[phase]['list'] @@ -1400,19 +1659,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('\(.*\) *(?P<args>.*)', cdata) + mr = re.match('\((?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) @@ -1527,6 +1787,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]: @@ -1541,11 +1811,29 @@ 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: + return + stime = (self.tSuspended - self.start) * 1000000 + rtime = (self.end - self.tResumed) * 1000000 + hws = self.hwstart + timedelta(microseconds=stime) + 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 @@ -1672,7 +1960,7 @@ class Data: length = -1.0 if(start >= 0 and end >= 0): length = end - start - if pid == -2: + if pid == -2 or name not in sysvals.tracefuncs.keys(): i = 2 origname = name while(name in list): @@ -1685,6 +1973,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('^%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'] @@ -1800,7 +2097,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): @@ -1814,78 +2111,46 @@ 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 = [] - 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 = [] + # get an array of process names and times + proclist = {'sus': dict(), 'res': dict()} + tdata = {'sus': [], 'res': []} 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)) - def handleEndMarker(self, time): + 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) + self.setEnd(time, msg) self.initDevicegroups() # give suspend_prepare an end if needed if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0: @@ -1904,6 +2169,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('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + 'PM: *calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + 'calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ + '(?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('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: PM: '+\ + '.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + '.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ + '(?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'] @@ -2071,7 +2360,7 @@ class FTraceLine: if not self.fevent: return False if sysvals.usetracemarkers: - if(self.name == 'SUSPEND START'): + if(self.name.startswith('SUSPEND START')): return True return False else: @@ -2084,7 +2373,7 @@ class FTraceLine: if not self.fevent: return False if sysvals.usetracemarkers: - if(self.name == 'RESUME COMPLETE'): + if(self.name.startswith('RESUME COMPLETE')): return True return False else: @@ -2444,7 +2733,7 @@ class Timeline: def createHeader(self, sv, stamp): if(not stamp['time']): return - self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \ + self.html += '<div class="version"><a href="https://01.org/pm-graph">%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>' @@ -2670,36 +2959,36 @@ 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>.*)$' - batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)' - wififmt = '^# wifi (?P<w>.*)' + wififmt = '^# wifi *(?P<d>\S*) *(?P<s>\S*) *(?P<t>[0-9\.]+).*' tstatfmt = '^# turbostat (?P<t>\S*)' - mcelogfmt = '^# mcelog (?P<m>\S*)' testerrfmt = '^# enter_sleep_error (?P<e>.*)' sysinfofmt = '^# sysinfo .*' cmdlinefmt = '^# command \| (?P<cmd>.*)' kparamsfmt = '^# kparams \| (?P<kp>.*)' devpropfmt = '# Device Properties: .*' - pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9]*): (?P<info>.*)' + 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>.*)$' + procmultifmt = '@(?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>.*)' ftrace_line_fmt_nop = \ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ - '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ + '(?P<flags>\S*) *(?P<time>[0-9\.]*): *'+\ '(?P<msg>.*)' + machinesuspend = 'machine_suspend\[.*' + multiproclist = dict() + multiproctime = 0.0 + multiproccnt = 0 def __init__(self): self.stamp = '' self.sysinfo = '' self.cmdline = '' - self.kparams = '' self.testerror = [] - self.mcelog = [] self.turbostat = [] - self.battery = [] self.wifi = [] self.fwdata = [] self.ftrace_line_fmt = self.ftrace_line_fmt_nop @@ -2714,28 +3003,16 @@ 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.kparamsfmt, line): - self.kparams = line - return True - elif re.match(self.cmdlinefmt, line): - self.cmdline = line - return True - elif re.match(self.mcelogfmt, line): - self.mcelog.append(line) - return True elif re.match(self.tstatfmt, line): self.turbostat.append(line) return True - elif re.match(self.batteryfmt, line): - self.battery.append(line) - return True elif re.match(self.wififmt, line): self.wifi.append(line) return True @@ -2745,10 +3022,26 @@ 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 m = re.match(self.stampfmt, self.stamp) + if not self.stamp or not m: + doError('data does not include the expected stamp') data.stamp = {'time': '', 'host': '', 'mode': ''} dt = datetime(int(m.group('y'))+2000, int(m.group('m')), int(m.group('d')), int(m.group('H')), int(m.group('M')), @@ -2767,9 +3060,13 @@ class TestProps: data.stamp[key] = val sv.hostname = data.stamp['host'] sv.suspendmode = data.stamp['mode'] + if sv.suspendmode == 'freeze': + self.machinesuspend = 'timekeeping_freeze\[.*' + else: + self.machinesuspend = '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) if m and m.group('mode') in ['1', '2', '3', '4']: @@ -2777,13 +3074,7 @@ class TestProps: data.stamp['mode'] = sv.suspendmode break fp.close() - m = re.match(self.cmdlinefmt, self.cmdline) - if m: - sv.cmdline = m.group('cmd') - if self.kparams: - m = re.match(self.kparamsfmt, self.kparams) - if m: - sv.kparams = m.group('kp') + sv.cmdline = self.cmdline if not sv.stamp: sv.stamp = data.stamp # firmware data @@ -2793,26 +3084,18 @@ class TestProps: data.fwSuspend, data.fwResume = int(m.group('s')), int(m.group('r')) if(data.fwSuspend > 0 or data.fwResume > 0): data.fwValid = True - # mcelog data - if len(self.mcelog) > data.testnumber: - m = re.match(self.mcelogfmt, self.mcelog[data.testnumber]) - if m: - data.mcelog = sv.b64unzip(m.group('m')) # turbostat data if len(self.turbostat) > data.testnumber: m = re.match(self.tstatfmt, self.turbostat[data.testnumber]) if m: data.turbostat = m.group('t') - # battery data - if len(self.battery) > data.testnumber: - m = re.match(self.batteryfmt, self.battery[data.testnumber]) - if m: - data.battery = m.groups() # wifi data if len(self.wifi) > data.testnumber: m = re.match(self.wififmt, self.wifi[data.testnumber]) if m: - data.wifi = m.group('w') + data.wifi = {'dev': m.group('d'), 'stat': m.group('s'), + 'time': float(m.group('t'))} + data.stamp['wifi'] = m.group('d') # sleep mode enter errors if len(self.testerror) > data.testnumber: m = re.match(self.testerrfmt, self.testerror[data.testnumber]) @@ -2870,6 +3153,7 @@ class TestRun: self.ttemp = dict() class ProcessMonitor: + maxchars = 512 def __init__(self): self.proclist = dict() self.running = False @@ -2895,19 +3179,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 @@ -2923,7 +3211,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') @@ -2946,12 +3234,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: @@ -2973,20 +3260,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) @@ -3012,13 +3286,13 @@ def appendIncompleteTraceLog(testruns): if(t.startMarker()): data = testrun[testidx].data tp.parseStamp(data, sysvals) - data.setStart(t.time) + data.setStart(t.time, t.name) continue if(not data): continue # find the end of resume if(t.endMarker()): - data.setEnd(t.time) + data.setEnd(t.time, t.name) testidx += 1 if(testidx >= testcnt): break @@ -3066,6 +3340,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('.* timekeeping_freeze.*begin', blk[i][3]): + last.append(i) + elif re.match('.* 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 @@ -3081,56 +3410,22 @@ def parseTraceLog(live=False): doError('%s does not exist' % sysvals.ftracefile) if not live: sysvals.setupAllKprobes() - ksuscalls = ['pm_prepare_console'] + ksuscalls = ['ksys_sync', 'pm_prepare_console'] krescalls = ['pm_restore_console'] 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'] + 'CPU_OFF', 'acpi_suspend'] # extract the callgraph and traceevent data - tp = TestProps() - testruns = [] - testdata = [] - testrun = 0 - data = 0 - 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) @@ -3141,40 +3436,59 @@ def parseTraceLog(live=False): continue # find the start of suspend if(t.startMarker()): - data = Data(len(testdata)) + data, limbo = Data(len(testdata)), False testdata.append(data) testrun = TestRun(data) testruns.append(testrun) tp.parseStamp(data, sysvals) - data.setStart(t.time) + data.setStart(t.time, t.name) data.first_suspend_prepare = True phase = data.setPhase('suspend_prepare', t.time, True) continue - if(not data): + if(not data or limbo): 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()): - data.handleEndMarker(t.time) + if data.tKernRes == 0: + data.tKernRes = t.time + data.handleEndMarker(t.time, t.name) if(not sysvals.usetracemarkers): # no trace markers? then quit and be sure to finish recording # the event we used to trigger resume end if('thaw_processes' in testrun.ttemp and len(testrun.ttemp['thaw_processes']) > 0): # if an entry exists, assume this is its end testrun.ttemp['thaw_processes'][-1]['end'] = t.time - break + limbo = True continue # trace event processing if(t.fevent): @@ -3197,7 +3511,7 @@ def parseTraceLog(live=False): # -- phase changes -- # start of kernel suspend if(re.match('suspend_enter\[.*', t.name)): - if(isbegin): + if(isbegin and data.tKernSus == 0): data.tKernSus = t.time continue # suspend_prepare start @@ -3222,16 +3536,30 @@ def parseTraceLog(live=False): 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() - if lp == 'resume_machine': - data.dmesg[lp]['end'] = t.time + hwsus = True + if lp.startswith('resume_machine'): + # 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') @@ -3262,6 +3590,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(\ @@ -3293,9 +3634,8 @@ def parseTraceLog(live=False): 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 @@ -3320,7 +3660,8 @@ def parseTraceLog(live=False): 'proc': m_proc, }) # start of kernel resume - if(phase == 'suspend_prepare' and kprobename in ksuscalls): + if(data.tKernSus == 0 and phase == 'suspend_prepare' \ + and kprobename in ksuscalls): data.tKernSus = t.time elif(t.freturn): if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1: @@ -3328,6 +3669,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 @@ -3350,12 +3694,11 @@ 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: sysvals.vprint('WARNING: ftrace end marker is missing') - data.handleEndMarker(t.time) + data.handleEndMarker(t.time, t.name) if sysvals.suspendmode == 'command': for test in testruns: @@ -3397,7 +3740,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 @@ -3466,8 +3814,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'] @@ -3476,6 +3831,10 @@ def parseTraceLog(live=False): data.fwValid = False sysvals.vprint('WARNING: phase "%s" is missing!' % p) lp = p + if not terr and 'dev' in data.wifi and data.wifi['stat'] == 'timeout': + terr = '%s%s failed in wifi_resume <i>(%s %.0fs timeout)</i>' % \ + (sysvals.suspendmode, tn, data.wifi['dev'], data.wifi['time']) + error.append(terr) if not terr and data.enterfail: pprint('test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail)) terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode) @@ -3503,9 +3862,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(): @@ -3525,13 +3882,14 @@ 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) if(not m): continue msg = m.group("msg") - if(re.match('PM: Syncing filesystems.*', msg)): + if re.match('PM: Syncing filesystems.*', msg) or \ + re.match('PM: suspend entry.*', msg): if(data): testruns.append(data) data = Data(len(testruns)) @@ -3542,11 +3900,17 @@ def loadKernelLog(): if(m): sysvals.stamp['kernel'] = m.group('k') m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg) - if(m): + if not m: + m = re.match('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: @@ -3557,12 +3921,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 @@ -3572,7 +3933,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 @@ -3591,30 +3951,30 @@ 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.*'], + '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', + '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': ['.*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 = { @@ -3662,12 +4022,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) @@ -3740,26 +4101,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): @@ -3801,6 +4154,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: @@ -3856,6 +4211,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) @@ -3873,18 +4230,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): @@ -3933,7 +4292,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title): tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()] iMin, iMed, iMax = [0, 0], [0, 0], [0, 0] num = 0 - useturbo = False + useturbo = usewifi = False lastmode = '' cnt = dict() for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])): @@ -3952,17 +4311,17 @@ def createHTMLSummarySimple(testruns, htmlfile, title): tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()] iMin, iMed, iMax = [0, 0], [0, 0], [0, 0] num = 0 - pkgpc10 = syslpi = '' + pkgpc10 = syslpi = wifi = '' if 'pkgpc10' in data and 'syslpi' in data: - pkgpc10 = data['pkgpc10'] - syslpi = data['syslpi'] - useturbo = True + pkgpc10, syslpi, useturbo = data['pkgpc10'], data['syslpi'], True + if 'wifi' in data: + wifi, usewifi = data['wifi'], True res = data['result'] tVal = [float(data['suspend']), float(data['resume'])] 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]) + data['res_worst'], data['res_worsttime'], pkgpc10, syslpi, wifi]) idx = len(list[mode]['data']) - 1 if res.startswith('fail in'): res = 'fail' @@ -4002,7 +4361,12 @@ def createHTMLSummarySimple(testruns, htmlfile, title): td = '\t<td>{0}</td>\n' tdh = '\t<td{1}>{0}</td>\n' tdlink = '\t<td><a href="{0}">html</a></td>\n' - colspan = '14' if useturbo else '12' + cols = 12 + if useturbo: + cols += 2 + if usewifi: + cols += 1 + colspan = '%d' % cols # table header html += '<table>\n<tr>\n' + th.format('#') +\ @@ -4013,6 +4377,8 @@ def createHTMLSummarySimple(testruns, htmlfile, title): th.format('Worst Resume Device') + th.format('RD Time') if useturbo: html += th.format('PkgPC10') + th.format('SysLPI') + if usewifi: + html += th.format('Wifi') html += th.format('Detail')+'</tr>\n' # export list into html head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\ @@ -4076,6 +4442,8 @@ def createHTMLSummarySimple(testruns, htmlfile, title): if useturbo: html += td.format(d[12]) # pkg_pc10 html += td.format(d[13]) # syslpi + if usewifi: + html += td.format(d[14]) # wifi html += tdlink.format(d[5]) if d[5] else td.format('') # url html += '</tr>\n' num += 1 @@ -4224,6 +4592,8 @@ def createHTML(testruns, testfail): kerror = True if(sysvals.suspendmode in ['freeze', 'standby']): data.trimFreezeTime(testruns[-1].tSuspended) + else: + data.getMemTime() # html function templates html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</div>\n' @@ -4242,13 +4612,10 @@ def createHTML(testruns, testfail): '<td class="green">Execution Time: <b>{0} ms</b></td>'\ '<td class="yellow">Command: <b>{1}</b></td>'\ '</tr>\n</table>\n' - html_timegroups = '<table class="time2">\n<tr>'\ - '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\ - '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\ - '<td class="purple">{4}Firmware Resume: {2} ms</td>'\ - '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\ - '</tr>\n</table>\n' html_fail = '<table class="testfail"><tr><td>{0}</td></tr></table>\n' + html_kdesc = '<td class="{3}" title="time spent in kernel execution">{0}Kernel {2}: {1} ms</td>' + html_fwdesc = '<td class="{3}" title="time spent in firmware">{0}Firmware {2}: {1} ms</td>' + html_wifdesc = '<td class="yellow" title="time for wifi to reconnect after resume complete ({2})">{0}Wifi Resume: {1}</td>' # html format variables scaleH = 20 @@ -4264,13 +4631,10 @@ def createHTML(testruns, testfail): # Generate the header for this timeline for data in testruns: tTotal = data.end - data.start - sktime, rktime = data.getTimeValues() if(tTotal == 0): doError('No timeline data') - if(len(data.tLow) > 0): - low_time = '+'.join(data.tLow) if sysvals.suspendmode == 'command': - run_time = '%.0f'%((data.end-data.start)*1000) + run_time = '%.0f' % (tTotal * 1000) if sysvals.testcommand: testdesc = sysvals.testcommand else: @@ -4279,43 +4643,55 @@ def createHTML(testruns, testfail): testdesc = ordinal(data.testnumber+1)+' '+testdesc thtml = html_timetotal3.format(run_time, testdesc) devtl.html += thtml - elif data.fwValid: - suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0)) - resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0)) - testdesc1 = 'Total' - testdesc2 = '' - stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode - rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode - if(len(testruns) > 1): - testdesc1 = testdesc2 = ordinal(data.testnumber+1) - testdesc2 += ' ' - if(len(data.tLow) == 0): - thtml = html_timetotal.format(suspend_time, \ - resume_time, testdesc1, stitle, rtitle) - else: - thtml = html_timetotal2.format(suspend_time, low_time, \ - resume_time, testdesc1, stitle, rtitle) - devtl.html += thtml + continue + # typical full suspend/resume header + stot, rtot = sktime, rktime = data.getTimeValues() + ssrc, rsrc, testdesc, testdesc2 = ['kernel'], ['kernel'], 'Kernel', '' + if data.fwValid: + stot += (data.fwSuspend/1000000.0) + rtot += (data.fwResume/1000000.0) + ssrc.append('firmware') + rsrc.append('firmware') + testdesc = 'Total' + if 'time' in data.wifi and data.wifi['stat'] != 'timeout': + rtot += data.end - data.tKernRes + (data.wifi['time'] * 1000.0) + rsrc.append('wifi') + testdesc = 'Total' + suspend_time, resume_time = '%.3f' % stot, '%.3f' % rtot + stitle = 'time from kernel suspend start to %s mode [%s time]' % \ + (sysvals.suspendmode, ' & '.join(ssrc)) + rtitle = 'time from %s mode to kernel resume complete [%s time]' % \ + (sysvals.suspendmode, ' & '.join(rsrc)) + if(len(testruns) > 1): + testdesc = testdesc2 = ordinal(data.testnumber+1) + testdesc2 += ' ' + if(len(data.tLow) == 0): + thtml = html_timetotal.format(suspend_time, \ + resume_time, testdesc, stitle, rtitle) + else: + low_time = '+'.join(data.tLow) + thtml = html_timetotal2.format(suspend_time, low_time, \ + resume_time, testdesc, stitle, rtitle) + devtl.html += thtml + if not data.fwValid and 'dev' not in data.wifi: + continue + # extra detail when the times come from multiple sources + thtml = '<table class="time2">\n<tr>' + thtml += html_kdesc.format(testdesc2, '%.3f'%sktime, 'Suspend', 'green') + if data.fwValid: sftime = '%.3f'%(data.fwSuspend / 1000000.0) rftime = '%.3f'%(data.fwResume / 1000000.0) - devtl.html += html_timegroups.format('%.3f'%sktime, \ - sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode) - else: - suspend_time = '%.3f' % sktime - resume_time = '%.3f' % rktime - testdesc = 'Kernel' - stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode - rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode - if(len(testruns) > 1): - testdesc = ordinal(data.testnumber+1)+' '+testdesc - if(len(data.tLow) == 0): - thtml = html_timetotal.format(suspend_time, \ - resume_time, testdesc, stitle, rtitle) + thtml += html_fwdesc.format(testdesc2, sftime, 'Suspend', 'green') + thtml += html_fwdesc.format(testdesc2, rftime, 'Resume', 'yellow') + thtml += html_kdesc.format(testdesc2, '%.3f'%rktime, 'Resume', 'yellow') + if 'time' in data.wifi: + if data.wifi['stat'] != 'timeout': + wtime = '%.0f ms'%(data.end - data.tKernRes + (data.wifi['time'] * 1000.0)) else: - thtml = html_timetotal2.format(suspend_time, low_time, \ - resume_time, testdesc, stitle, rtitle) - devtl.html += thtml - + wtime = 'TIMEOUT' + thtml += html_wifdesc.format(testdesc2, wtime, data.wifi['dev']) + thtml += '</tr>\n</table>\n' + devtl.html += thtml if testfail: devtl.html += html_fail.format(testfail) @@ -4414,12 +4790,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: @@ -4450,24 +4823,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) @@ -5054,157 +5426,142 @@ def addScriptCode(hf, testruns): '</script>\n' 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(): - pm = ProcessMonitor() - tp = sysvals.tpath - wifi = sysvals.checkWifi() +def executeSuspend(quiet=False): + sv, tp, pm = sysvals, sysvals.tpath, ProcessMonitor() + if sv.wifi: + wifi = sv.checkWifi() + sv.dlog('wifi check, connected device is "%s"' % wifi) testdata = [] - battery = True if getBattery() else False # run these commands to prepare the system for suspend - if sysvals.display: - pprint('SET DISPLAY TO %s' % sysvals.display.upper()) - displayControl(sysvals.display) + if sv.display: + if not quiet: + 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: - pprint('SYNCING FILESYSTEMS') + 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): - pprint('START TRACING') - sysvals.fsetVal('1', 'tracing_on') - if sysvals.useprocmon: - pm.start() + 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)') - sysvals.mcelog(True) - bat1 = getBattery() if battery else False # set rtcwake - if(sysvals.rtcwake): - pprint('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) - sysvals.rtcWakeAlarmOn() + if(sv.rtcwake): + if not quiet: + 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('SUSPEND START', '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() + turbo = sv.turbostat(s0ixready) 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.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('RESUME COMPLETE', 'trace_marker') - 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) - mcelog = sysvals.mcelog() - if mcelog: - tdata['mcelog'] = mcelog - bat2 = getBattery() if battery else False - if battery and bat1 and bat2: - tdata['bat'] = (bat1, bat2) - if 'device' in wifi and 'ip' in wifi: - tdata['wifi'] = (wifi, sysvals.checkWifi()) testdata.append(tdata) - # 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 - pprint('CAPTURING DMESG') - sysvals.getdmesg(testdata) + if not quiet: + pprint('CAPTURING DMESG') + sv.getdmesg(testdata) # grab a copy of the ftrace output - if(sysvals.usecallgraph or sysvals.usetraceevents): - pprint('CAPTURING TRACE') - op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata) + if sv.useftrace: + if not quiet: + pprint('CAPTURING TRACE') + op = sv.writeDatafileHeader(sv.ftracefile, testdata) fp = open(tp+'trace', 'r') for line in fp: op.write(line) op.close() - sysvals.fsetVal('', 'trace') - sysvals.platforminfo() - return testdata + sv.fsetVal('', 'trace') + sv.platforminfo(cmdafter) def readFile(file): if os.path.islink(file): @@ -5447,58 +5804,6 @@ def dmidecode(mempath, fatal=False): count += 1 return out -def getBattery(): - p, charge, bat = '/sys/class/power_supply', 0, {} - if not os.path.exists(p): - return False - for d in os.listdir(p): - type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower() - if type != 'battery': - continue - for v in ['status', 'energy_now', 'capacity_now']: - bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower() - break - if 'status' not in bat: - return False - ac = False if 'discharging' in bat['status'] else True - for v in ['energy_now', 'capacity_now']: - if v in bat and bat[v]: - charge = int(bat[v]) - return (ac, charge) - -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 @@ -5678,13 +5983,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: @@ -5697,8 +6008,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): @@ -5715,6 +6026,17 @@ def statusCheck(probecheck=False): status = 'rtcwake is not properly supported' pprint(' is rtcwake supported: %s' % res) + # check info commands + 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', 'netfix']: + if c == 'turbostat': + res = yes if sysvals.haveTurbostat() else no + else: + res = yes if sysvals.getExec(c) else no + pprint(' %s: %s' % (c, res)) + if not probecheck: return status @@ -5780,8 +6102,9 @@ def getArgFloat(name, args, min, max, main=True): doError(name+': value should be between %f and %f' % (min, max), True) return val -def processData(live=False): - pprint('PROCESSING DATA') +def processData(live=False, quiet=False): + if not quiet: + pprint('PROCESSING: %s' % sysvals.htmlfile) sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \ (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes)) error = '' @@ -5796,20 +6119,17 @@ def processData(live=False): parseKernelLog(data) if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)): appendIncompleteTraceLog(testruns) - shown = ['bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', - 'memsz', 'mode', 'numcpu', 'plat', 'time'] + if not sysvals.stamp: + pprint('ERROR: data does not include the expected stamp') + return (testruns, {'error': 'timeline generation failed'}) + 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): if key in shown: sysvals.vprint(' %-8s : %s' % (key.upper(), sysvals.stamp[key])) - if sysvals.kparams: - sysvals.vprint('Kparams:\n %s' % sysvals.kparams) sysvals.vprint('Command:\n %s' % sysvals.cmdline) for data in testruns: - if data.mcelog: - sysvals.vprint('MCELOG Data:') - for line in data.mcelog.split('\n'): - sysvals.vprint(' %s' % line) if data.turbostat: idx, s = 0, 'Turbostat:\n ' for val in data.turbostat.split('|'): @@ -5819,23 +6139,13 @@ def processData(live=False): s += '\n ' s += val + ' ' sysvals.vprint(s) - if data.battery: - a1, c1, a2, c2 = data.battery - s = 'Battery:\n Before - AC: %s, Charge: %d\n After - AC: %s, Charge: %d' % \ - (a1, int(c1), a2, int(c2)) - sysvals.vprint(s) - if data.wifi: - w = data.wifi.replace('|', ' ').split(',') - s = 'Wifi:\n Before %s\n After %s' % \ - (w[0], w[1]) - sysvals.vprint(s) data.printDetails() - if len(sysvals.platinfo) > 0: - sysvals.vprint('\nPlatform Info:') - for info in sysvals.platinfo: - sysvals.vprint(info[0]+' - '+info[1]) - sysvals.vprint(info[2]) - sysvals.vprint('') + if len(sysvals.platinfo) > 0: + sysvals.vprint('\nPlatform Info:') + for info in sysvals.platinfo: + sysvals.vprint('[%s - %s]' % (info[0], info[1])) + sysvals.vprint(info[2]) + sysvals.vprint('') if sysvals.cgdump: for data in testruns: data.debugPrint() @@ -5845,7 +6155,8 @@ def processData(live=False): return (testruns, {'error': 'timeline generation failed'}) sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) createHTML(testruns, error) - pprint('DONE') + if not quiet: + pprint('DONE: %s' % sysvals.htmlfile) data = testruns[0] stamp = data.stamp stamp['suspend'], stamp['resume'] = data.getTimeValues() @@ -5872,31 +6183,41 @@ def rerunTest(htmlfile=''): doError('a directory already exists with this name: %s' % sysvals.htmlfile) elif not os.access(sysvals.htmlfile, os.W_OK): doError('missing permission to write to %s' % sysvals.htmlfile) - testruns, stamp = processData(False) - sysvals.logmsg = '' + testruns, stamp = processData() + sysvals.resetlog() return stamp # Function: runTest # Description: # execute a suspend/resume, gather the logs, and generate the output -def runTest(n=0): +def runTest(n=0, quiet=False): # prepare for the test - sysvals.initFtrace() 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 - testdata = executeSuspend() + executeSuspend(quiet) sysvals.cleanupFtrace() if sysvals.skiphtml: + sysvals.outputResult({}, n) sysvals.sudoUserchown(sysvals.testdir) return - if not testdata[0]['error']: - testruns, stamp = processData(True) - for data in testruns: - del data - else: - stamp = testdata[0] - + testruns, stamp = processData(True, quiet) + for data in testruns: + del data sysvals.sudoUserchown(sysvals.testdir) sysvals.outputResult(stamp, n) if 'error' in stamp: @@ -5904,24 +6225,27 @@ def runTest(n=0): return 0 def find_in_html(html, start, end, firstonly=True): - n, out = 0, [] - while n < len(html): - m = re.search(start, html[n:]) - if not m: - break - i = m.end() - m = re.search(end, html[n+i:]) + 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 @@ -5945,7 +6269,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-z]* failed in (?P<p>[a-z0-9_]*) phase', error) + m = re.match('[a-z0-9]* failed in (?P<p>\S*).*', error) if m: result = 'fail in %s' % m.group('p') else: @@ -5953,7 +6277,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() @@ -5961,8 +6285,8 @@ 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: + tp = d.extractErrorInfo() + for msg in tp.msglist: sysvals.errorSummary(issues, msg) if stmp[2] == 'freeze': extra = d.turbostatInfo() @@ -5974,9 +6298,23 @@ 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) + line = find_in_html(log, '# wifi ', '\n') + if line: + extra['wifi'] = line + line = find_in_html(log, '# netfix ', '\n') + if line: + extra['netfix'] = line 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('.*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 @@ -6000,6 +6338,8 @@ def data_from_html(file, outpath, issues, fulldetail=False): 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'): @@ -6042,19 +6382,26 @@ 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): for dirname, dirnames, filenames in os.walk(subdir): sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = '' for filename in filenames: - if(re.match('.*_dmesg.txt', filename)): - sysvals.dmesgfile = os.path.join(dirname, filename) - elif(re.match('.*_ftrace.txt', filename)): - sysvals.ftracefile = os.path.join(dirname, filename) + file = os.path.join(dirname, filename) + if sysvals.usable(file): + if(re.match('.*_dmesg.txt', filename)): + sysvals.dmesgfile = file + elif(re.match('.*_ftrace.txt', filename)): + sysvals.ftracefile = file sysvals.setOutputFile() - if sysvals.ftracefile and sysvals.htmlfile and \ - (force or not os.path.exists(sysvals.htmlfile)): + if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \ + (force or not sysvals.usable(sysvals.htmlfile, True)): pprint('FTRACE: %s' % sysvals.ftracefile) if sysvals.dmesgfile: pprint('DMESG : %s' % sysvals.dmesgfile) @@ -6069,8 +6416,7 @@ 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: @@ -6079,6 +6425,8 @@ def runSummary(subdir, local=True, genhtml=False): 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]: @@ -6086,6 +6434,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) @@ -6169,9 +6519,9 @@ def configFromFile(file): sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False) elif(option == 'cgphase'): d = Data(0) - if value not in d.sortedPhases(): + if value not in d.phasedef: doError('invalid phase --> (%s: %s), valid phases are %s'\ - % (option, value, d.sortedPhases()), True) + % (option, value, d.phasedef.keys()), True) sysvals.cgphase = value elif(option == 'fadd'): file = sysvals.configFile(value) @@ -6184,9 +6534,7 @@ def configFromFile(file): nums = value.split() if len(nums) != 2: doError('multi requires 2 integers (exec_count and delay)', True) - sysvals.multitest['run'] = True - sysvals.multitest['count'] = getArgInt('multi: n d (exec count)', nums[0], 2, 1000000, False) - sysvals.multitest['delay'] = getArgInt('multi: n d (delay between tests)', nums[1], 0, 3600, False) + sysvals.multiinit(nums[0], nums[1]) elif(option == 'devicefilter'): sysvals.setDeviceFilter(value) elif(option == 'expandcg'): @@ -6342,6 +6690,9 @@ def printHelp(): ' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\ ' -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'\ ' [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'\ @@ -6356,8 +6707,10 @@ def printHelp(): ' -predelay t Include t ms delay before 1st suspend (default: 0 ms)\n'\ ' -postdelay t Include t ms delay after last resume (default: 0 ms)\n'\ ' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)\n'\ - ' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will\n'\ - ' be created in a new subdirectory with a summary page.\n'\ + ' -multi n d Execute <n> consecutive tests at <d> seconds intervals. If <n> is followed\n'\ + ' by a "d", "h", or "m" execute for <n> days, hours, or mins instead.\n'\ + ' The outputs will be created in a new subdirectory with a summary page.\n'\ + ' -maxfail n Abort a -multi run after n consecutive fails (default is 0 = never abort)\n'\ ' [debug]\n'\ ' -f Use ftrace to create device callgraphs (default: disabled)\n'\ ' -ftop Use ftrace on the top level call: "%s" (default: disabled)\n'\ @@ -6379,11 +6732,11 @@ def printHelp(): ' -modes List available suspend modes\n'\ ' -status Test to see if the system is enabled to run this tool\n'\ ' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\ - ' -battery Print out battery info (if available)\n'\ - ' -wifi Print out wifi connection info (if wireless-tools and device exists)\n'\ + ' -wificheck Print out wifi connection info\n'\ ' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\ ' -sysinfo Print out system info extracted from BIOS\n'\ ' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\ + ' -cmdinfo Print out all the platform info collected before and after suspend/resume\n'\ ' -flist Print the list of functions currently being captured in ftrace\n'\ ' -flistall Print all functions capable of being captured in ftrace\n'\ ' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]\n'\ @@ -6399,8 +6752,8 @@ if __name__ == '__main__': genhtml = False cmd = '' simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', - '-devinfo', '-status', '-battery', '-xon', '-xoff', '-xstandby', - '-xsuspend', '-xinit', '-xreset', '-xstat', '-wifi'] + '-devinfo', '-status', '-xon', '-xoff', '-xstandby', '-xsuspend', + '-xinit', '-xreset', '-xstat', '-wificheck', '-cmdinfo'] if '-f' in sys.argv: sysvals.cgskip = sysvals.configFile('cgskip.txt') # loop through the command line arguments @@ -6422,6 +6775,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'): @@ -6462,8 +6817,24 @@ if __name__ == '__main__': sysvals.usedevsrc = True elif(arg == '-sync'): 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'): + try: + 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) @@ -6555,10 +6926,14 @@ if __name__ == '__main__': sysvals.cgexp = True elif(arg == '-srgap'): sysvals.srgap = 5 + elif(arg == '-maxfail'): + sysvals.maxfail = getArgInt('-maxfail', args, 0, 1000000) elif(arg == '-multi'): - sysvals.multitest['run'] = True - sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000) - sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600) + try: + c, d = next(args), next(args) + except: + doError('-multi requires two values', True) + sysvals.multiinit(c, d) elif(arg == '-o'): try: val = next(args) @@ -6655,13 +7030,6 @@ if __name__ == '__main__': elif(cmd == 'fpdt'): if not getFPDT(True): ret = 1 - elif(cmd == 'battery'): - out = getBattery() - if out: - pprint('AC Connect : %s\nBattery Charge: %d' % out) - else: - pprint('no battery found') - ret = 1 elif(cmd == 'sysinfo'): sysvals.printSystemInfo(True) elif(cmd == 'devinfo'): @@ -6676,16 +7044,18 @@ 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()) - elif(cmd == 'wifi'): - out = sysvals.checkWifi() - if 'device' not in out: - pprint('WIFI interface not found') + pprint('Display Status: %s' % sysvals.displayControl('stat').upper()) + elif(cmd == 'wificheck'): + dev = sysvals.checkWifi() + if dev: + print('%s is connected' % sysvals.wifiDetails(dev)) else: - for key in sorted(out): - pprint('%6s: %s' % (key.upper(), out[key])) + print('No wifi connection found') + elif(cmd == 'cmdinfo'): + for out in sysvals.cmdinfo(False, True): + print('[%s - %s]\n%s\n' % out) sys.exit(ret) # if instructed, re-analyze existing data files @@ -6714,30 +7084,39 @@ 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') - ret = 0 + failcnt, ret = 0, 0 if sysvals.multitest['run']: # run multiple tests in a separate subdirectory if not sysvals.outdir: - s = 'suspend-x%d' % sysvals.multitest['count'] - sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S') + if 'time' in sysvals.multitest: + s = '-%dm' % sysvals.multitest['time'] + else: + s = '-x%d' % sysvals.multitest['count'] + sysvals.outdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S'+s) if not os.path.isdir(sysvals.outdir): os.makedirs(sysvals.outdir) + sysvals.sudoUserchown(sysvals.outdir) + finish = datetime.now() + if 'time' in sysvals.multitest: + finish += timedelta(minutes=sysvals.multitest['time']) for i in range(sysvals.multitest['count']): - if(i != 0): + sysvals.multistat(True, i, finish) + if i != 0 and sysvals.multitest['delay'] > 0: pprint('Waiting %d seconds...' % (sysvals.multitest['delay'])) time.sleep(sysvals.multitest['delay']) - pprint('TEST (%d/%d) START' % (i+1, sysvals.multitest['count'])) fmt = 'suspend-%y%m%d-%H%M%S' sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) - ret = runTest(i+1) - pprint('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count'])) - sysvals.logmsg = '' + 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 + sysvals.resetlog() + sysvals.multistat(False, i, finish) + if 'time' in sysvals.multitest and datetime.now() >= finish: + break if not sysvals.skiphtml: runSummary(sysvals.outdir, False, False) sysvals.sudoUserchown(sysvals.outdir) @@ -6746,7 +7125,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) |