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):
# store system values and test parameters
class SystemValues:
title = 'SleepGraph'
- version = '5.8'
+ version = '5.9'
ansi = False
rs = 0
display = ''
gzip = False
sync = False
wifi = False
+ netfix = False
verbose = False
testlog = True
dmesglog = True
cpucount = 0
memtotal = 204800
memfree = 204800
+ osversion = ''
srgap = 0
cgexp = False
testdir = ''
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'
acpipath='/sys/module/acpi/parameters/debug_level'
traceevents = [
'suspend_resume',
ftop = False
usetraceevents = False
usetracemarkers = True
+ useftrace = True
usekprobes = True
usedevsrc = False
useprocmon = False
'intel_fbdev_set_suspend': {},
}
infocmds = [
+ [0, 'sysinfo', 'uname', '-a'],
+ [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'],
[0, 'kparams', 'cat', '/proc/cmdline'],
[0, 'mcelog', 'mcelog'],
[0, 'pcidevices', 'lspci', '-tv'],
- [0, 'usbdevices', 'lsusb', '-t'],
+ [0, 'usbdevices', 'lsusb', '-tv'],
+ [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'],
+ [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'],
+ [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'],
+ [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/*'],
self.outputResult({'error':msg})
sys.exit(1)
return False
- def usable(self, file):
- return (os.path.exists(file) and os.path.getsize(file) > 0)
+ def usable(self, file, ishtml=False):
+ if not os.path.exists(file) or os.path.getsize(file) < 1:
+ return False
+ if ishtml:
+ try:
+ fp = open(file, 'r')
+ res = fp.read(1000)
+ fp.close()
+ except:
+ return False
+ if '<html>' not in res:
+ return False
+ return True
def getExec(self, cmd):
try:
fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout
r = info['bios-release-date'] if 'bios-release-date' in info else ''
self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \
(m, p, c, b, r, self.cpucount, self.memtotal, self.memfree)
+ if self.osversion:
+ self.sysstamp += ' | os:%s' % self.osversion
def printSystemInfo(self, fatal=False):
self.rootCheck(True)
out = dmidecode(self.mempath, fatal)
if len(out) < 1:
return
fmt = '%-24s: %s'
+ if self.osversion:
+ print(fmt % ('os-version', self.osversion))
for name in sorted(out):
print(fmt % (name, out[name]))
print(fmt % ('cpucount', ('%d' % self.cpucount)))
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()
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 = ''
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')
return True
return False
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()
- self.testVal(self.pmdpath, 'basic', '1')
# set the trace clock to global
self.fsetVal('global', 'trace_clock')
self.fsetVal('nop', 'current_tracer')
# 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')
fp.write('# turbostat %s\n' % test['turbo'])
if 'wifi' in test:
fp.write('# wifi %s\n' % test['wifi'])
+ if 'netfix' in test:
+ fp.write('# netfix %s\n' % test['netfix'])
if test['error'] or len(testdata) > 1:
fp.write('# enter_sleep_error %s\n' % test['error'])
return fp
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]))
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)
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(';', ' ')
self.cmd1[name] = self.dictify(info, delta)
elif not debug and delta and name in self.cmd1:
before, after = self.cmd1[name], self.dictify(info, delta)
- dinfo = ('\t%s\n' % before['@']) if '@' in before else ''
+ dinfo = ('\t%s\n' % before['@']) if '@' in before and len(before) > 1 else ''
prefix = self.commonPrefix(list(before.keys()))
for key in sorted(before):
if key in after and before[key] != after[key]:
val = valline[idx]
out.append('%s=%s' % (key, val))
return '|'.join(out)
+ def netfixon(self, net='both'):
+ cmd = self.getExec('netfix')
+ if not cmd:
+ return ''
+ fp = Popen([cmd, '-s', net, 'on'], stdout=PIPE, stderr=PIPE).stdout
+ out = ascii(fp.read()).strip()
+ fp.close()
+ return out
+ def wifiRepair(self):
+ out = self.netfixon('wifi')
+ if not out or 'error' in out.lower():
+ return ''
+ m = re.match('WIFI \S* ONLINE (?P<action>\S*)', out)
+ if not m:
+ return 'dead'
+ return m.group('action')
def wifiDetails(self, dev):
try:
info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip()
except:
return ''
for line in reversed(w.split('\n')):
- m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', w.split('\n')[-1])
+ m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', line)
if not m or (dev and dev != m.group('dev')):
continue
return m.group('dev')
return ''
- def pollWifi(self, dev, timeout=60):
+ def pollWifi(self, dev, timeout=10):
start = time.time()
while (time.time() - start) < timeout:
w = self.checkWifi(dev)
return '%s reconnected %.2f' % \
(self.wifiDetails(dev), max(0, time.time() - start))
time.sleep(0.01)
+ if self.netfix:
+ res = self.wifiRepair()
+ if res:
+ timeout = max(0, time.time() - start)
+ return '%s %s %d' % (self.wifiDetails(dev), res, timeout)
return '%s timeout %d' % (self.wifiDetails(dev), timeout)
def errorSummary(self, errinfo, msg):
found = False
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
'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[: ].*',
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))
+ tTry = '%.0f' % (round(self.dmesg[lp]['waking'][1] * 1000))
else:
- tTry = '-%.3f' % (self.dmesg[lp]['waking'][1] * 1000)
+ tTry = '%.3f' % (self.dmesg[lp]['waking'][1] * 1000)
text = '%.0f (%s ms waking %d times)' % (tL * 1000, tTry, tCnt)
else:
text = '%.0f' % (tL * 1000)
# 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']
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<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.ttemp = dict()
class ProcessMonitor:
+ maxchars = 512
def __init__(self):
self.proclist = dict()
self.running = False
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
# 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:
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
# extract the callgraph and traceevent data
s2idle_enter = hwsus = False
- tp = TestProps()
testruns, testdata = [], []
testrun, data, limbo = 0, 0, True
- tf = sysvals.openlog(sysvals.ftracefile, 'r')
phase = 'suspend_prepare'
- 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
+ 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)
if t.type == 'tracing_mark_write':
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()):
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:
if p not in data.dmesg:
if not terr:
ph = p if 'machine' in p else lp
- terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph)
+ 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:
# 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():
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))
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:
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
# 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
# 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 = {
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)
# -- 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):
# 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:
sv.dlog('read dmesg')
sv.initdmesg()
# start ftrace
- if(sv.usecallgraph or sv.usetraceevents):
+ if sv.useftrace:
if not quiet:
pprint('START TRACING')
sv.dlog('start ftrace tracing')
sv.dlog('enable RTC wake alarm')
sv.rtcWakeAlarmOn()
# start of suspend trace marker
- if(sv.usecallgraph or sv.usetraceevents):
- sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker')
+ sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker')
# predelay delay
if(count == 1 and sv.predelay > 0):
sv.fsetVal('WAIT %d' % sv.predelay, 'trace_marker')
sv.fsetVal('WAIT END', 'trace_marker')
# return from suspend
pprint('RESUME COMPLETE')
- if(sv.usecallgraph or sv.usetraceevents):
- sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker')
+ sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker')
if sv.wifi and wifi:
tdata['wifi'] = sv.pollWifi(wifi)
sv.dlog('wifi check, %s' % tdata['wifi'])
+ if sv.netfix:
+ netfixout = sv.netfixon('wired')
+ elif sv.netfix:
+ netfixout = sv.netfixon()
+ if sv.netfix and netfixout:
+ tdata['netfix'] = netfixout
+ sv.dlog('netfix, %s' % tdata['netfix'])
if(sv.suspendmode == 'mem' or sv.suspendmode == 'command'):
sv.dlog('read the ACPI FPDT')
tdata['fw'] = getFPDT(False)
sv.dlog('run the cmdinfo list after')
cmdafter = sv.cmdinfo(False)
# stop ftrace
- if(sv.usecallgraph or sv.usetraceevents):
+ if sv.useftrace:
if sv.useprocmon:
sv.dlog('stop the process monitor')
pm.stop()
sysvals.dlog('EXECUTION TRACE END')
sv.getdmesg(testdata)
# grab a copy of the ftrace output
- if(sv.usecallgraph or sv.usetraceevents):
+ if sv.useftrace:
if not quiet:
pprint('CAPTURING TRACE')
op = sv.writeDatafileHeader(sv.ftracefile, testdata)
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:
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):
pprint(' optional commands this tool may use for info:')
no = sysvals.colorText('MISSING')
yes = sysvals.colorText('FOUND', 32)
- for c in ['turbostat', 'mcelog', 'lspci', 'lsusb']:
+ for c in ['turbostat', 'mcelog', 'lspci', 'lsusb', 'netfix']:
if c == 'turbostat':
res = yes if sysvals.haveTurbostat() else no
else:
if not sysvals.stamp:
pprint('ERROR: data does not include the expected stamp')
return (testruns, {'error': 'timeline generation failed'})
- shown = ['bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr',
+ shown = ['os', 'bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr',
'memsz', 'mode', 'numcpu', 'plat', 'time', 'wifi']
sysvals.vprint('System Info:')
for key in sorted(sysvals.stamp):
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)
elist[err[0]] += 1
for i in elist:
ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i)
- wifi = find_in_html(html, 'Wifi Resume: ', '</td>')
- if wifi:
- extra['wifi'] = wifi
+ line = find_in_html(log, '# wifi ', '\n')
+ if line:
+ extra['wifi'] = line
+ line = find_in_html(log, '# netfix ', '\n')
+ if line:
+ extra['netfix'] = line
low = find_in_html(html, 'freeze time: <b>', ' ms</b>')
for lowstr in ['waking', '+']:
if not low:
sysvals.ftracefile = file
sysvals.setOutputFile()
if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \
- (force or not sysvals.usable(sysvals.htmlfile)):
+ (force or not sysvals.usable(sysvals.htmlfile, True)):
pprint('FTRACE: %s' % sysvals.ftracefile)
if sysvals.dmesgfile:
pprint('DMESG : %s' % sysvals.dmesgfile)
' -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'\
+ ' -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'\
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'):
sysvals.sync = True
elif(arg == '-wifi'):
sysvals.wifi = True
+ elif(arg == '-netfix'):
+ sysvals.netfix = True
elif(arg == '-gzip'):
sysvals.gzip = True
elif(arg == '-info'):
sysvals.outdir = val
sysvals.notestrun = True
if(os.path.isdir(val) == False):
- doError('%s is not accessible' % val)
+ doError('%s is not accesible' % val)
elif(arg == '-filter'):
try:
val = next(args)
time.sleep(sysvals.multitest['delay'])
fmt = 'suspend-%y%m%d-%H%M%S'
sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
- ret = runTest(i+1, True)
+ ret = runTest(i+1, not sysvals.verbose)
failcnt = 0 if not ret else failcnt + 1
if sysvals.maxfail > 0 and failcnt >= sysvals.maxfail:
pprint('Maximum fail count of %d reached, aborting multitest' % (sysvals.maxfail))
break
- time.sleep(5)
sysvals.resetlog()
sysvals.multistat(False, i, finish)
if 'time' in sysvals.multitest and datetime.now() >= finish:
projects / linux-2.6-microblaze.git / commitdiff