Commit 5484f033 authored by Todd Brandt's avatar Todd Brandt Committed by Rafael J. Wysocki

PM / tools: sleepgraph: first batch of v5.2 changes

general:
- add battery charge data before and after test
- remove special s0i3 handling
- remove melding of dmesg & ftrace data in old kernels, use one only
- updates to various kprobes in trace (ksys_sync, etc)
- enable pm_debug_messages during the test
- instrument more subsystems with dev functions (phy0)

error handling:
- return codes for tool show the status of the test run
- 0: success, 1: general error (no timeline), 2: fail (suspend aborted)
- monitor output of /sys/power/state, mark as failure if exception occurs
- add signal handler when using -result to catch tool exceptions

display control
- add -x commands for testing xset with mode settings and status
- allow display setting to on, off, suspend, standby
- add display mode change info to the log, along with a warning on fail

s2idle (freeze)
- remove fixed 10-phase dependency, allow any phase order & any count
- multiple phase occurences show as phase_nameN e.g. suspend_noirq3
- if multiple freezes occur, print multiple time values in header

summary:
- add new columns to summary output: issues, worst suspend/resume devices
- worst device: includes summation of all phases of suspend or resume
- issues: includes WARNING/ERROR/BUG from dmesg log, and other issues
- s2idle: multiple freezes show as FREEZExN in the issues column
Signed-off-by: default avatarTodd Brandt <todd.e.brandt@linux.intel.com>
Signed-off-by: default avatarRafael J. Wysocki <rafael.j.wysocki@intel.com>
parent 0238df64
...@@ -23,8 +23,8 @@ install : uninstall ...@@ -23,8 +23,8 @@ install : uninstall
install -m 644 config/suspend-x2-proc.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config install -m 644 config/suspend-x2-proc.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -d $(DESTDIR)$(PREFIX)/bin install -d $(DESTDIR)$(PREFIX)/bin
ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/bootgraph.py $(DESTDIR)$(PREFIX)/bin/bootgraph ln -s ../lib/pm-graph/bootgraph.py $(DESTDIR)$(PREFIX)/bin/bootgraph
ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/sleepgraph.py $(DESTDIR)$(PREFIX)/bin/sleepgraph ln -s ../lib/pm-graph/sleepgraph.py $(DESTDIR)$(PREFIX)/bin/sleepgraph
install -d $(DESTDIR)$(PREFIX)/share/man/man8 install -d $(DESTDIR)$(PREFIX)/share/man/man8
install bootgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8 install bootgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8
......
...@@ -65,9 +65,9 @@ During test, enable/disable runtime suspend for all devices. The test is delayed ...@@ -65,9 +65,9 @@ During test, enable/disable runtime suspend for all devices. The test is delayed
by 5 seconds to allow runtime suspend changes to occur. The settings are restored by 5 seconds to allow runtime suspend changes to occur. The settings are restored
after the test is complete. after the test is complete.
.TP .TP
\fB-display \fIon/off\fR \fB-display \fIon/off/standby/suspend\fR
Turn the display on or off for the test using the xset command. This helps Switch the display to the requested mode for the test using the xset command.
maintain the consistecy of test data for better comparison. This helps maintain the consistency of test data for better comparison.
.TP .TP
\fB-skiphtml\fR \fB-skiphtml\fR
Run the test and capture the trace logs, but skip the timeline generation. Run the test and capture the trace logs, but skip the timeline generation.
...@@ -183,6 +183,13 @@ Print out the contents of the ACPI Firmware Performance Data Table. ...@@ -183,6 +183,13 @@ Print out the contents of the ACPI Firmware Performance Data Table.
\fB-battery\fR \fB-battery\fR
Print out battery status and current charge. Print out battery status and current charge.
.TP .TP
\fB-xon/-xoff/-xstandby/-xsuspend\fR
Test xset by attempting to switch the display to the given mode. This
is the same command which will be issued by \fB-display \fImode\fR.
.TP
\fB-xstat\fR
Get the current DPMS display mode.
.TP
\fB-sysinfo\fR \fB-sysinfo\fR
Print out system info extracted from BIOS. Reads /dev/mem directly instead of going through dmidecode. Print out system info extracted from BIOS. Reads /dev/mem directly instead of going through dmidecode.
.TP .TP
......
...@@ -54,6 +54,7 @@ import os ...@@ -54,6 +54,7 @@ import os
import string import string
import re import re
import platform import platform
import signal
from datetime import datetime from datetime import datetime
import struct import struct
import ConfigParser import ConfigParser
...@@ -72,7 +73,7 @@ class SystemValues: ...@@ -72,7 +73,7 @@ class SystemValues:
version = '5.1' version = '5.1'
ansi = False ansi = False
rs = 0 rs = 0
display = 0 display = ''
gzip = False gzip = False
sync = False sync = False
verbose = False verbose = False
...@@ -99,6 +100,7 @@ class SystemValues: ...@@ -99,6 +100,7 @@ class SystemValues:
tpath = '/sys/kernel/debug/tracing/' tpath = '/sys/kernel/debug/tracing/'
fpdtpath = '/sys/firmware/acpi/tables/FPDT' fpdtpath = '/sys/firmware/acpi/tables/FPDT'
epath = '/sys/kernel/debug/tracing/events/power/' epath = '/sys/kernel/debug/tracing/events/power/'
pmdpath = '/sys/power/pm_debug_messages'
traceevents = [ traceevents = [
'suspend_resume', 'suspend_resume',
'device_pm_callback_end', 'device_pm_callback_end',
...@@ -141,12 +143,10 @@ class SystemValues: ...@@ -141,12 +143,10 @@ class SystemValues:
devprops = dict() devprops = dict()
predelay = 0 predelay = 0
postdelay = 0 postdelay = 0
procexecfmt = 'ps - (?P<ps>.*)$' pmdebug = ''
devpropfmt = '# Device Properties: .*'
tracertypefmt = '# tracer: (?P<t>.*)'
firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
tracefuncs = { tracefuncs = {
'sys_sync': {}, 'sys_sync': {},
'ksys_sync': {},
'__pm_notifier_call_chain': {}, '__pm_notifier_call_chain': {},
'pm_prepare_console': {}, 'pm_prepare_console': {},
'pm_notifier_call_chain': {}, 'pm_notifier_call_chain': {},
...@@ -187,7 +187,6 @@ class SystemValues: ...@@ -187,7 +187,6 @@ class SystemValues:
dev_tracefuncs = { dev_tracefuncs = {
# general wait/delay/sleep # general wait/delay/sleep
'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 }, 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 }, 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
...@@ -199,6 +198,9 @@ class SystemValues: ...@@ -199,6 +198,9 @@ class SystemValues:
# filesystem # filesystem
'ext4_sync_fs': {}, 'ext4_sync_fs': {},
# 80211 # 80211
'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} },
'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} },
'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} },
'iwlagn_mac_start': {}, 'iwlagn_mac_start': {},
'iwlagn_alloc_bcast_station': {}, 'iwlagn_alloc_bcast_station': {},
'iwl_trans_pcie_start_hw': {}, 'iwl_trans_pcie_start_hw': {},
...@@ -241,6 +243,7 @@ class SystemValues: ...@@ -241,6 +243,7 @@ class SystemValues:
timeformat = '%.3f' timeformat = '%.3f'
cmdline = '%s %s' % \ cmdline = '%s %s' % \
(os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:])) (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
sudouser = ''
def __init__(self): def __init__(self):
self.archargs = 'args_'+platform.machine() self.archargs = 'args_'+platform.machine()
self.hostname = platform.node() self.hostname = platform.node()
...@@ -256,10 +259,32 @@ class SystemValues: ...@@ -256,10 +259,32 @@ class SystemValues:
if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
self.ansi = True self.ansi = True
self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S') self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
if os.getuid() == 0 and 'SUDO_USER' in os.environ and \
os.environ['SUDO_USER']:
self.sudouser = os.environ['SUDO_USER']
def vprint(self, msg): def vprint(self, msg):
self.logmsg += msg+'\n' self.logmsg += msg+'\n'
if(self.verbose): if self.verbose or msg.startswith('WARNING:'):
print(msg) print(msg)
def signalHandler(self, signum, frame):
if not self.result:
return
signame = self.signames[signum] if signum in self.signames else 'UNKNOWN'
msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno)
sysvals.outputResult({'error':msg})
sys.exit(3)
def signalHandlerInit(self):
capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT',
'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM', 'TSTP']
self.signames = dict()
for i in capture:
s = 'SIG'+i
try:
signum = getattr(signal, s)
signal.signal(signum, self.signalHandler)
except:
continue
self.signames[signum] = s
def rootCheck(self, fatal=True): def rootCheck(self, fatal=True):
if(os.access(self.powerfile, os.W_OK)): if(os.access(self.powerfile, os.W_OK)):
return True return True
...@@ -267,7 +292,7 @@ class SystemValues: ...@@ -267,7 +292,7 @@ class SystemValues:
msg = 'This command requires sysfs mount and root access' msg = 'This command requires sysfs mount and root access'
print('ERROR: %s\n') % msg print('ERROR: %s\n') % msg
self.outputResult({'error':msg}) self.outputResult({'error':msg})
sys.exit() sys.exit(1)
return False return False
def rootUser(self, fatal=False): def rootUser(self, fatal=False):
if 'USER' in os.environ and os.environ['USER'] == 'root': if 'USER' in os.environ and os.environ['USER'] == 'root':
...@@ -276,7 +301,7 @@ class SystemValues: ...@@ -276,7 +301,7 @@ class SystemValues:
msg = 'This command must be run as root' msg = 'This command must be run as root'
print('ERROR: %s\n') % msg print('ERROR: %s\n') % msg
self.outputResult({'error':msg}) self.outputResult({'error':msg})
sys.exit() sys.exit(1)
return False return False
def getExec(self, cmd): def getExec(self, cmd):
dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin', dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
...@@ -406,8 +431,8 @@ class SystemValues: ...@@ -406,8 +431,8 @@ class SystemValues:
ktime = m.group('ktime') ktime = m.group('ktime')
fp.close() fp.close()
self.dmesgstart = float(ktime) self.dmesgstart = float(ktime)
def getdmesg(self, fwdata=[]): def getdmesg(self, testdata):
op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata) op = self.writeDatafileHeader(sysvals.dmesgfile, testdata)
# store all new dmesg lines since initdmesg was called # store all new dmesg lines since initdmesg was called
fp = Popen('dmesg', stdout=PIPE).stdout fp = Popen('dmesg', stdout=PIPE).stdout
for line in fp: for line in fp:
...@@ -619,6 +644,8 @@ class SystemValues: ...@@ -619,6 +644,8 @@ class SystemValues:
self.fsetVal('0', 'events/kprobes/enable') self.fsetVal('0', 'events/kprobes/enable')
self.fsetVal('', 'kprobe_events') self.fsetVal('', 'kprobe_events')
self.fsetVal('1024', 'buffer_size_kb') self.fsetVal('1024', 'buffer_size_kb')
if self.pmdebug:
self.setVal(self.pmdebug, self.pmdpath)
def setupAllKprobes(self): def setupAllKprobes(self):
for name in self.tracefuncs: for name in self.tracefuncs:
self.defaultKprobe(name, self.tracefuncs[name]) self.defaultKprobe(name, self.tracefuncs[name])
...@@ -641,6 +668,11 @@ class SystemValues: ...@@ -641,6 +668,11 @@ class SystemValues:
# turn trace off # turn trace off
self.fsetVal('0', 'tracing_on') self.fsetVal('0', 'tracing_on')
self.cleanupFtrace() 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 # set the trace clock to global
self.fsetVal('global', 'trace_clock') self.fsetVal('global', 'trace_clock')
self.fsetVal('nop', 'current_tracer') self.fsetVal('nop', 'current_tracer')
...@@ -728,19 +760,24 @@ class SystemValues: ...@@ -728,19 +760,24 @@ class SystemValues:
if not self.ansi: if not self.ansi:
return str return str
return '\x1B[%d;40m%s\x1B[m' % (color, str) return '\x1B[%d;40m%s\x1B[m' % (color, str)
def writeDatafileHeader(self, filename, fwdata=[]): def writeDatafileHeader(self, filename, testdata):
fp = self.openlog(filename, 'w') fp = self.openlog(filename, 'w')
fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline)) fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
if(self.suspendmode == 'mem' or self.suspendmode == 'command'): for test in testdata:
for fw in fwdata: if 'fw' in test:
fw = test['fw']
if(fw): if(fw):
fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
if 'bat' in test:
(a1, c1), (a2, c2) = test['bat']
fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2))
if test['error'] or len(testdata) > 1:
fp.write('# enter_sleep_error %s\n' % test['error'])
return fp return fp
def sudouser(self, dir): def sudoUserchown(self, dir):
if os.path.exists(dir) and os.getuid() == 0 and \ if os.path.exists(dir) and self.sudouser:
'SUDO_USER' in os.environ:
cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
call(cmd.format(os.environ['SUDO_USER'], dir), shell=True) call(cmd.format(self.sudouser, dir), shell=True)
def outputResult(self, testdata, num=0): def outputResult(self, testdata, num=0):
if not self.result: if not self.result:
return return
...@@ -762,7 +799,7 @@ class SystemValues: ...@@ -762,7 +799,7 @@ class SystemValues:
if 'bugurl' in testdata: if 'bugurl' in testdata:
fp.write('url%s: %s\n' % (n, testdata['bugurl'])) fp.write('url%s: %s\n' % (n, testdata['bugurl']))
fp.close() fp.close()
self.sudouser(self.result) self.sudoUserchown(self.result)
def configFile(self, file): def configFile(self, file):
dir = os.path.dirname(os.path.realpath(__file__)) dir = os.path.dirname(os.path.realpath(__file__))
if os.path.exists(file): if os.path.exists(file):
...@@ -800,11 +837,12 @@ suspendmodename = { ...@@ -800,11 +837,12 @@ suspendmodename = {
# Simple class which holds property values collected # Simple class which holds property values collected
# for all the devices used in the timeline. # for all the devices used in the timeline.
class DevProps: class DevProps:
syspath = '' def __init__(self):
altname = '' self.syspath = ''
async = True self.altname = ''
xtraclass = '' self.async = True
xtrainfo = '' self.xtraclass = ''
self.xtrainfo = ''
def out(self, dev): def out(self, dev):
return '%s,%s,%d;' % (dev, self.altname, self.async) return '%s,%s,%d;' % (dev, self.altname, self.async)
def debug(self, dev): def debug(self, dev):
...@@ -831,9 +869,6 @@ class DevProps: ...@@ -831,9 +869,6 @@ class DevProps:
# A container used to create a device hierachy, with a single root node # A container used to create a device hierachy, with a single root node
# and a tree of child nodes. Used by Data.deviceTopology() # and a tree of child nodes. Used by Data.deviceTopology()
class DeviceNode: class DeviceNode:
name = ''
children = 0
depth = 0
def __init__(self, nodename, nodedepth): def __init__(self, nodename, nodedepth):
self.name = nodename self.name = nodename
self.children = [] self.children = []
...@@ -861,71 +896,78 @@ class DeviceNode: ...@@ -861,71 +896,78 @@ class DeviceNode:
# } # }
# #
class Data: class Data:
dmesg = {} # root data structure phasedef = {
phases = [] # ordered list of phases 'suspend_prepare': {'order': 0, 'color': '#CCFFCC'},
start = 0.0 # test start 'suspend': {'order': 1, 'color': '#88FF88'},
end = 0.0 # test end 'suspend_late': {'order': 2, 'color': '#00AA00'},
tSuspended = 0.0 # low-level suspend start 'suspend_noirq': {'order': 3, 'color': '#008888'},
tResumed = 0.0 # low-level resume start 'suspend_machine': {'order': 4, 'color': '#0000FF'},
tKernSus = 0.0 # kernel level suspend start 'resume_machine': {'order': 5, 'color': '#FF0000'},
tKernRes = 0.0 # kernel level resume end 'resume_noirq': {'order': 6, 'color': '#FF9900'},
tLow = 0.0 # time spent in low-level suspend (standby/freeze) 'resume_early': {'order': 7, 'color': '#FFCC00'},
fwValid = False # is firmware data available 'resume': {'order': 8, 'color': '#FFFF88'},
fwSuspend = 0 # time spent in firmware suspend 'resume_complete': {'order': 9, 'color': '#FFFFCC'},
fwResume = 0 # time spent in firmware resume }
dmesgtext = [] # dmesg text file in memory errlist = {
pstl = 0 # process timeline 'HWERROR' : '.*\[ *Hardware Error *\].*',
testnumber = 0 'FWBUG' : '.*\[ *Firmware Bug *\].*',
idstr = '' 'BUG' : '.*BUG.*',
html_device_id = 0 'ERROR' : '.*ERROR.*',
stamp = 0 'WARNING' : '.*WARNING.*',
outfile = '' 'IRQ' : '.*genirq: .*',
devpids = [] 'TASKFAIL': '.*Freezing of tasks failed.*',
kerror = False }
def __init__(self, num): def __init__(self, num):
idchar = 'abcdefghij' idchar = 'abcdefghij'
self.pstl = dict() self.start = 0.0 # test start
self.end = 0.0 # 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
self.tKernRes = 0.0 # kernel level resume end
self.fwValid = False # is firmware data available
self.fwSuspend = 0 # time spent in firmware suspend
self.fwResume = 0 # time spent in firmware resume
self.html_device_id = 0
self.stamp = 0
self.outfile = ''
self.kerror = False
self.battery = 0
self.enterfail = ''
self.currphase = ''
self.pstl = dict() # process timeline
self.testnumber = num self.testnumber = num
self.idstr = idchar[num] self.idstr = idchar[num]
self.dmesgtext = [] self.dmesgtext = [] # dmesg text file in memory
self.phases = [] self.dmesg = dict() # root data structure
self.dmesg = { # fixed list of 10 phases self.errorinfo = {'suspend':[],'resume':[]}
'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, self.tLow = [] # time spent in low-level suspends (standby/freeze)
'row': 0, 'color': '#CCFFCC', 'order': 0}, self.devpids = []
'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, self.devicegroups = 0
'row': 0, 'color': '#88FF88', 'order': 1}, def sortedPhases(self):
'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order'])
'row': 0, 'color': '#00AA00', 'order': 2}, def initDevicegroups(self):
'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, # called when phases are all finished being added
'row': 0, 'color': '#008888', 'order': 3}, for phase in self.dmesg.keys():
'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, if '*' in phase:
'row': 0, 'color': '#0000FF', 'order': 4}, p = phase.split('*')
'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, pnew = '%s%d' % (p[0], len(p))
'row': 0, 'color': '#FF0000', 'order': 5}, self.dmesg[pnew] = self.dmesg.pop(phase)
'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
'row': 0, 'color': '#FF9900', 'order': 6},
'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
'row': 0, 'color': '#FFCC00', 'order': 7},
'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
'row': 0, 'color': '#FFFF88', 'order': 8},
'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
'row': 0, 'color': '#FFFFCC', 'order': 9}
}
self.phases = self.sortedPhases()
self.devicegroups = [] self.devicegroups = []
for phase in self.phases: for phase in self.sortedPhases():
self.devicegroups.append([phase]) self.devicegroups.append([phase])
self.errorinfo = {'suspend':[],'resume':[]} def nextPhase(self, phase, offset):
order = self.dmesg[phase]['order'] + offset
for p in self.dmesg:
if self.dmesg[p]['order'] == order:
return p
return ''
def lastPhase(self):
plist = self.sortedPhases()
if len(plist) < 1:
return ''
return plist[-1]
def extractErrorInfo(self): def extractErrorInfo(self):
elist = {
'HWERROR' : '.*\[ *Hardware Error *\].*',
'FWBUG' : '.*\[ *Firmware Bug *\].*',
'BUG' : '.*BUG.*',
'ERROR' : '.*ERROR.*',
'WARNING' : '.*WARNING.*',
'IRQ' : '.*genirq: .*',
'TASKFAIL': '.*Freezing of tasks failed.*',
}
lf = sysvals.openlog(sysvals.dmesgfile, 'r') lf = sysvals.openlog(sysvals.dmesgfile, 'r')
i = 0 i = 0
list = [] list = []
...@@ -939,8 +981,8 @@ class Data: ...@@ -939,8 +981,8 @@ class Data:
continue continue
dir = 'suspend' if t < self.tSuspended else 'resume' dir = 'suspend' if t < self.tSuspended else 'resume'
msg = m.group('msg') msg = m.group('msg')
for err in elist: for err in self.errlist:
if re.match(elist[err], msg): if re.match(self.errlist[err], msg):
list.append((err, dir, t, i, i)) list.append((err, dir, t, i, i))
self.kerror = True self.kerror = True
break break
...@@ -956,7 +998,7 @@ class Data: ...@@ -956,7 +998,7 @@ class Data:
def setEnd(self, time): def setEnd(self, time):
self.end = time self.end = time
def isTraceEventOutsideDeviceCalls(self, pid, time): def isTraceEventOutsideDeviceCalls(self, pid, time):
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
for dev in list: for dev in list:
d = list[dev] d = list[dev]
...@@ -964,16 +1006,10 @@ class Data: ...@@ -964,16 +1006,10 @@ class Data:
time < d['end']): time < d['end']):
return False return False
return True return True
def phaseCollision(self, phase, isbegin, line):
key = 'end'
if isbegin:
key = 'start'
if self.dmesg[phase][key] >= 0:
sysvals.vprint('IGNORE: %s' % line.strip())
return True
return False
def sourcePhase(self, start): def sourcePhase(self, start):
for phase in self.phases: for phase in self.sortedPhases():
if 'machine' in phase:
continue
pend = self.dmesg[phase]['end'] pend = self.dmesg[phase]['end']
if start <= pend: if start <= pend:
return phase return phase
...@@ -1004,14 +1040,15 @@ class Data: ...@@ -1004,14 +1040,15 @@ class Data:
return tgtdev return tgtdev
def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata): def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
# try to place the call in a device # try to place the call in a device
tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device') phases = self.sortedPhases()
tgtdev = self.sourceDevice(phases, start, end, pid, 'device')
# calls with device pids that occur outside device bounds are dropped # calls with device pids that occur outside device bounds are dropped
# TODO: include these somehow # TODO: include these somehow
if not tgtdev and pid in self.devpids: if not tgtdev and pid in self.devpids:
return False return False
# try to place the call in a thread # try to place the call in a thread
if not tgtdev: if not tgtdev:
tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread') tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')
# create new thread blocks, expand as new calls are found # create new thread blocks, expand as new calls are found
if not tgtdev: if not tgtdev:
if proc == '<...>': if proc == '<...>':
...@@ -1053,7 +1090,7 @@ class Data: ...@@ -1053,7 +1090,7 @@ class Data:
def overflowDevices(self): def overflowDevices(self):
# get a list of devices that extend beyond the end of this test run # get a list of devices that extend beyond the end of this test run
devlist = [] devlist = []
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
for devname in list: for devname in list:
dev = list[devname] dev = list[devname]
...@@ -1064,7 +1101,7 @@ class Data: ...@@ -1064,7 +1101,7 @@ class Data:
# merge any devices that overlap devlist # merge any devices that overlap devlist
for dev in devlist: for dev in devlist:
devname = dev['name'] devname = dev['name']
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
if devname not in list: if devname not in list:
continue continue
...@@ -1079,7 +1116,7 @@ class Data: ...@@ -1079,7 +1116,7 @@ class Data:
del list[devname] del list[devname]
def usurpTouchingThread(self, name, dev): def usurpTouchingThread(self, name, dev):
# the caller test has priority of this thread, give it to him # the caller test has priority of this thread, give it to him
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
if name in list: if name in list:
tdev = list[name] tdev = list[name]
...@@ -1093,7 +1130,7 @@ class Data: ...@@ -1093,7 +1130,7 @@ class Data:
break break
def stitchTouchingThreads(self, testlist): def stitchTouchingThreads(self, testlist):
# merge any threads between tests that touch # merge any threads between tests that touch
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
for devname in list: for devname in list:
dev = list[devname] dev = list[devname]
...@@ -1103,7 +1140,7 @@ class Data: ...@@ -1103,7 +1140,7 @@ class Data:
data.usurpTouchingThread(devname, dev) data.usurpTouchingThread(devname, dev)
def optimizeDevSrc(self): def optimizeDevSrc(self):
# merge any src call loops to reduce timeline size # merge any src call loops to reduce timeline size
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
for dev in list: for dev in list:
if 'src' not in list[dev]: if 'src' not in list[dev]:
...@@ -1141,7 +1178,7 @@ class Data: ...@@ -1141,7 +1178,7 @@ class Data:
self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left) self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left) self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
self.end = self.trimTimeVal(self.end, t0, dT, left) self.end = self.trimTimeVal(self.end, t0, dT, left)
for phase in self.phases: for phase in self.sortedPhases():
p = self.dmesg[phase] p = self.dmesg[phase]
p['start'] = self.trimTimeVal(p['start'], t0, dT, left) p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
p['end'] = self.trimTimeVal(p['end'], t0, dT, left) p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
...@@ -1150,6 +1187,7 @@ class Data: ...@@ -1150,6 +1187,7 @@ class Data:
d = list[name] d = list[name]
d['start'] = self.trimTimeVal(d['start'], t0, dT, left) d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
d['end'] = self.trimTimeVal(d['end'], t0, dT, left) d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
d['length'] = d['end'] - d['start']
if('ftrace' in d): if('ftrace' in d):
cg = d['ftrace'] cg = d['ftrace']
cg.start = self.trimTimeVal(cg.start, t0, dT, left) cg.start = self.trimTimeVal(cg.start, t0, dT, left)
...@@ -1166,30 +1204,59 @@ class Data: ...@@ -1166,30 +1204,59 @@ class Data:
tm = self.trimTimeVal(tm, t0, dT, left) tm = self.trimTimeVal(tm, t0, dT, left)
list.append((type, tm, idx1, idx2)) list.append((type, tm, idx1, idx2))
self.errorinfo[dir] = list self.errorinfo[dir] = list
def normalizeTime(self, tZero): def trimFreezeTime(self, tZero):
# trim out any standby or freeze clock time # trim out any standby or freeze clock time
if(self.tSuspended != self.tResumed): lp = ''
if(self.tResumed > tZero): for phase in self.sortedPhases():
self.trimTime(self.tSuspended, \ if 'resume_machine' in phase and 'suspend_machine' in lp:
self.tResumed-self.tSuspended, True) tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start']
else: tL = tR - tS
self.trimTime(self.tSuspended, \ if tL > 0:
self.tResumed-self.tSuspended, False) left = True if tR > tZero else False
self.trimTime(tS, tL, left)
self.tLow.append('%.0f'%(tL*1000))
lp = phase
def getTimeValues(self): def getTimeValues(self):
sktime = (self.dmesg['suspend_machine']['end'] - \ if 'suspend_machine' in self.dmesg:
self.tKernSus) * 1000 sktime = (self.dmesg['suspend_machine']['end'] - \
rktime = (self.dmesg['resume_complete']['end'] - \ self.tKernSus) * 1000
self.dmesg['resume_machine']['start']) * 1000 else:
sktime = (self.tSuspended - self.tKernSus) * 1000
if 'resume_machine' in self.dmesg:
rktime = (self.tKernRes - \
self.dmesg['resume_machine']['start']) * 1000
else:
rktime = (self.tKernRes - self.tResumed) * 1000
return (sktime, rktime) return (sktime, rktime)
def setPhase(self, phase, ktime, isbegin): def setPhase(self, phase, ktime, isbegin, order=-1):
if(isbegin): if(isbegin):
# phase start over current phase
if self.currphase:
if 'resume_machine' not in self.currphase:
sysvals.vprint('WARNING: phase %s failed to end' % self.currphase)
self.dmesg[self.currphase]['end'] = ktime
phases = self.dmesg.keys()
color = self.phasedef[phase]['color']
count = len(phases) if order < 0 else order
# create unique name for every new phase
while phase in phases:
phase += '*'
self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0,
'row': 0, 'color': color, 'order': count}
self.dmesg[phase]['start'] = ktime self.dmesg[phase]['start'] = ktime
self.currphase = phase
else: else:
# phase end without a start
if phase not in self.currphase:
if self.currphase:
sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))
else:
sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)
return phase
phase = self.currphase
self.dmesg[phase]['end'] = ktime self.dmesg[phase]['end'] = ktime
def dmesgSortVal(self, phase): self.currphase = ''
return self.dmesg[phase]['order'] return phase
def sortedPhases(self):
return sorted(self.dmesg, key=self.dmesgSortVal)
def sortedDevices(self, phase): def sortedDevices(self, phase):
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
slist = [] slist = []
...@@ -1208,13 +1275,13 @@ class Data: ...@@ -1208,13 +1275,13 @@ class Data:
for devname in phaselist: for devname in phaselist:
dev = phaselist[devname] dev = phaselist[devname]
if(dev['end'] < 0): if(dev['end'] < 0):
for p in self.phases: for p in self.sortedPhases():
if self.dmesg[p]['end'] > dev['start']: if self.dmesg[p]['end'] > dev['start']:
dev['end'] = self.dmesg[p]['end'] dev['end'] = self.dmesg[p]['end']
break break
sysvals.vprint('%s (%s): callback didnt return' % (devname, phase)) sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
def deviceFilter(self, devicefilter): def deviceFilter(self, devicefilter):
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
rmlist = [] rmlist = []
for name in list: for name in list:
...@@ -1229,7 +1296,7 @@ class Data: ...@@ -1229,7 +1296,7 @@ class Data:
del list[name] del list[name]
def fixupInitcallsThatDidntReturn(self): def fixupInitcallsThatDidntReturn(self):
# if any calls never returned, clip them at system resume end # if any calls never returned, clip them at system resume end
for phase in self.phases: for phase in self.sortedPhases():
self.fixupInitcalls(phase) self.fixupInitcalls(phase)
def phaseOverlap(self, phases): def phaseOverlap(self, phases):
rmgroups = [] rmgroups = []
...@@ -1248,17 +1315,18 @@ class Data: ...@@ -1248,17 +1315,18 @@ class Data:
self.devicegroups.append(newgroup) self.devicegroups.append(newgroup)
def newActionGlobal(self, name, start, end, pid=-1, color=''): def newActionGlobal(self, name, start, end, pid=-1, color=''):
# which phase is this device callback or action in # which phase is this device callback or action in
phases = self.sortedPhases()
targetphase = 'none' targetphase = 'none'
htmlclass = '' htmlclass = ''
overlap = 0.0 overlap = 0.0
phases = [] myphases = []
for phase in self.phases: for phase in phases:
pstart = self.dmesg[phase]['start'] pstart = self.dmesg[phase]['start']
pend = self.dmesg[phase]['end'] pend = self.dmesg[phase]['end']
# see if the action overlaps this phase # see if the action overlaps this phase
o = max(0, min(end, pend) - max(start, pstart)) o = max(0, min(end, pend) - max(start, pstart))
if o > 0: if o > 0:
phases.append(phase) myphases.append(phase)
# set the target phase to the one that overlaps most # set the target phase to the one that overlaps most
if o > overlap: if o > overlap:
if overlap > 0 and phase == 'post_resume': if overlap > 0 and phase == 'post_resume':
...@@ -1267,19 +1335,19 @@ class Data: ...@@ -1267,19 +1335,19 @@ class Data:
overlap = o overlap = o
# if no target phase was found, pin it to the edge # if no target phase was found, pin it to the edge
if targetphase == 'none': if targetphase == 'none':
p0start = self.dmesg[self.phases[0]]['start'] p0start = self.dmesg[phases[0]]['start']
if start <= p0start: if start <= p0start:
targetphase = self.phases[0] targetphase = phases[0]
else: else:
targetphase = self.phases[-1] targetphase = phases[-1]
if pid == -2: if pid == -2:
htmlclass = ' bg' htmlclass = ' bg'
elif pid == -3: elif pid == -3:
htmlclass = ' ps' htmlclass = ' ps'
if len(phases) > 1: if len(myphases) > 1:
htmlclass = ' bg' htmlclass = ' bg'
self.phaseOverlap(phases) self.phaseOverlap(myphases)
if targetphase in self.phases: if targetphase in phases:
newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color) newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
return (targetphase, newname) return (targetphase, newname)
return False return False
...@@ -1315,7 +1383,7 @@ class Data: ...@@ -1315,7 +1383,7 @@ class Data:
sysvals.vprint('Timeline Details:') sysvals.vprint('Timeline Details:')
sysvals.vprint(' test start: %f' % self.start) sysvals.vprint(' test start: %f' % self.start)
sysvals.vprint('kernel suspend start: %f' % self.tKernSus) sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
for phase in self.phases: for phase in self.sortedPhases():
dc = len(self.dmesg[phase]['list']) dc = len(self.dmesg[phase]['list'])
sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \
self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
...@@ -1323,7 +1391,7 @@ class Data: ...@@ -1323,7 +1391,7 @@ class Data:
sysvals.vprint(' test end: %f' % self.end) sysvals.vprint(' test end: %f' % self.end)
def deviceChildrenAllPhases(self, devname): def deviceChildrenAllPhases(self, devname):
devlist = [] devlist = []
for phase in self.phases: for phase in self.sortedPhases():
list = self.deviceChildren(devname, phase) list = self.deviceChildren(devname, phase)
for dev in list: for dev in list:
if dev not in devlist: if dev not in devlist:
...@@ -1344,7 +1412,7 @@ class Data: ...@@ -1344,7 +1412,7 @@ class Data:
if node.name: if node.name:
info = '' info = ''
drv = '' drv = ''
for phase in self.phases: for phase in self.sortedPhases():
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
if node.name in list: if node.name in list:
s = list[node.name]['start'] s = list[node.name]['start']
...@@ -1478,8 +1546,29 @@ class Data: ...@@ -1478,8 +1546,29 @@ class Data:
c = self.addProcessUsageEvent(ps, tres) c = self.addProcessUsageEvent(ps, tres)
if c > 0: if c > 0:
sysvals.vprint('%25s (res): %d' % (ps, c)) sysvals.vprint('%25s (res): %d' % (ps, c))
def handleEndMarker(self, time):
dm = self.dmesg
self.setEnd(time)
self.initDevicegroups()
# give suspend_prepare an end if needed
if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0:
dm['suspend_prepare']['end'] = time
# assume resume machine ends at next phase start
if 'resume_machine' in dm and dm['resume_machine']['end'] < 0:
np = self.nextPhase('resume_machine', 1)
if np:
dm['resume_machine']['end'] = dm[np]['start']
# if kernel resume end not found, assume its the end marker
if self.tKernRes == 0.0:
self.tKernRes = time
# if kernel suspend start not found, assume its the end marker
if self.tKernSus == 0.0:
self.tKernSus = time
# set resume complete to end at end marker
if 'resume_complete' in dm:
dm['resume_complete']['end'] = time
def debugPrint(self): def debugPrint(self):
for p in self.phases: for p in self.sortedPhases():
list = self.dmesg[p]['list'] list = self.dmesg[p]['list']
for devname in list: for devname in list:
dev = list[devname] dev = list[devname]
...@@ -1490,9 +1579,9 @@ class Data: ...@@ -1490,9 +1579,9 @@ class Data:
# Description: # Description:
# A container for kprobe function data we want in the dev timeline # A container for kprobe function data we want in the dev timeline
class DevFunction: class DevFunction:
row = 0
count = 1
def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color): def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
self.row = 0
self.count = 1
self.name = name self.name = name
self.args = args self.args = args
self.caller = caller self.caller = caller
...@@ -1546,16 +1635,15 @@ class DevFunction: ...@@ -1546,16 +1635,15 @@ class DevFunction:
# suspend_resume: phase or custom exec block data # suspend_resume: phase or custom exec block data
# device_pm_callback: device callback info # device_pm_callback: device callback info
class FTraceLine: class FTraceLine:
time = 0.0
length = 0.0
fcall = False
freturn = False
fevent = False
fkprobe = False
depth = 0
name = ''
type = ''
def __init__(self, t, m='', d=''): def __init__(self, t, m='', d=''):
self.length = 0.0
self.fcall = False
self.freturn = False
self.fevent = False
self.fkprobe = False
self.depth = 0
self.name = ''
self.type = ''
self.time = float(t) self.time = float(t)
if not m and not d: if not m and not d:
return return
...@@ -1675,19 +1763,13 @@ class FTraceLine: ...@@ -1675,19 +1763,13 @@ class FTraceLine:
# Each instance is tied to a single device in a single phase, and is # Each instance is tied to a single device in a single phase, and is
# comprised of an ordered list of FTraceLine objects # comprised of an ordered list of FTraceLine objects
class FTraceCallGraph: class FTraceCallGraph:
id = ''
start = -1.0
end = -1.0
list = []
invalid = False
depth = 0
pid = 0
name = ''
partial = False
vfname = 'missing_function_name' vfname = 'missing_function_name'
ignore = False
sv = 0
def __init__(self, pid, sv): def __init__(self, pid, sv):
self.id = ''
self.invalid = False
self.name = ''
self.partial = False
self.ignore = False
self.start = -1.0 self.start = -1.0
self.end = -1.0 self.end = -1.0
self.list = [] self.list = []
...@@ -1943,7 +2025,7 @@ class FTraceCallGraph: ...@@ -1943,7 +2025,7 @@ class FTraceCallGraph:
dev['ftrace'] = cg dev['ftrace'] = cg
found = devname found = devname
return found return found
for p in data.phases: for p in data.sortedPhases():
if(data.dmesg[p]['start'] <= self.start and if(data.dmesg[p]['start'] <= self.start and
self.start <= data.dmesg[p]['end']): self.start <= data.dmesg[p]['end']):
list = data.dmesg[p]['list'] list = data.dmesg[p]['list']
...@@ -1966,7 +2048,7 @@ class FTraceCallGraph: ...@@ -1966,7 +2048,7 @@ class FTraceCallGraph:
if fs < data.start or fe > data.end: if fs < data.start or fe > data.end:
return return
phase = '' phase = ''
for p in data.phases: for p in data.sortedPhases():
if(data.dmesg[p]['start'] <= self.start and if(data.dmesg[p]['start'] <= self.start and
self.start < data.dmesg[p]['end']): self.start < data.dmesg[p]['end']):
phase = p phase = p
...@@ -2008,23 +2090,20 @@ class DevItem: ...@@ -2008,23 +2090,20 @@ class DevItem:
# A container for a device timeline which calculates # A container for a device timeline which calculates
# all the html properties to display it correctly # all the html properties to display it correctly
class Timeline: class Timeline:
html = ''
height = 0 # total timeline height
scaleH = 20 # timescale (top) row height
rowH = 30 # device row height
bodyH = 0 # body height
rows = 0 # total timeline rows
rowlines = dict()
rowheight = dict()
html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n' html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n' html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n' html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'
html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n' html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}">&nbsp;{2}</div>\n' html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}">&nbsp;{2}</div>\n'
def __init__(self, rowheight, scaleheight): def __init__(self, rowheight, scaleheight):
self.rowH = rowheight
self.scaleH = scaleheight
self.html = '' self.html = ''
self.height = 0 # total timeline height
self.scaleH = scaleheight # timescale (top) row height
self.rowH = rowheight # device row height
self.bodyH = 0 # body height
self.rows = 0 # total timeline rows
self.rowlines = dict()
self.rowheight = dict()
def createHeader(self, sv, stamp): def createHeader(self, sv, stamp):
if(not stamp['time']): if(not stamp['time']):
return return
...@@ -2251,18 +2330,18 @@ class Timeline: ...@@ -2251,18 +2330,18 @@ class Timeline:
# Description: # Description:
# A list of values describing the properties of these test runs # A list of values describing the properties of these test runs
class TestProps: class TestProps:
stamp = ''
sysinfo = ''
cmdline = ''
kparams = ''
S0i3 = False
fwdata = []
stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ 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<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)'
testerrfmt = '^# enter_sleep_error (?P<e>.*)'
sysinfofmt = '^# sysinfo .*' sysinfofmt = '^# sysinfo .*'
cmdlinefmt = '^# command \| (?P<cmd>.*)' cmdlinefmt = '^# command \| (?P<cmd>.*)'
kparamsfmt = '^# kparams \| (?P<kp>.*)' kparamsfmt = '^# kparams \| (?P<kp>.*)'
devpropfmt = '# Device Properties: .*'
tracertypefmt = '# tracer: (?P<t>.*)'
firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
procexecfmt = 'ps - (?P<ps>.*)$'
ftrace_line_fmt_fg = \ ftrace_line_fmt_fg = \
'^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
...@@ -2271,11 +2350,17 @@ class TestProps: ...@@ -2271,11 +2350,17 @@ class TestProps:
' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
'(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
'(?P<msg>.*)' '(?P<msg>.*)'
ftrace_line_fmt = ftrace_line_fmt_nop
cgformat = False
data = 0
ktemp = dict()
def __init__(self): def __init__(self):
self.stamp = ''
self.sysinfo = ''
self.cmdline = ''
self.kparams = ''
self.testerror = []
self.battery = []
self.fwdata = []
self.ftrace_line_fmt = self.ftrace_line_fmt_nop
self.cgformat = False
self.data = 0
self.ktemp = dict() self.ktemp = dict()
def setTracerType(self, tracer): def setTracerType(self, tracer):
if(tracer == 'function_graph'): if(tracer == 'function_graph'):
...@@ -2286,6 +2371,7 @@ class TestProps: ...@@ -2286,6 +2371,7 @@ class TestProps:
else: else:
doError('Invalid tracer format: [%s]' % tracer) doError('Invalid tracer format: [%s]' % tracer)
def parseStamp(self, data, sv): def parseStamp(self, data, sv):
# global test data
m = re.match(self.stampfmt, self.stamp) m = re.match(self.stampfmt, self.stamp)
data.stamp = {'time': '', 'host': '', 'mode': ''} data.stamp = {'time': '', 'host': '', 'mode': ''}
dt = datetime(int(m.group('y'))+2000, int(m.group('m')), dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
...@@ -2324,23 +2410,36 @@ class TestProps: ...@@ -2324,23 +2410,36 @@ class TestProps:
sv.kparams = m.group('kp') sv.kparams = m.group('kp')
if not sv.stamp: if not sv.stamp:
sv.stamp = data.stamp sv.stamp = data.stamp
# firmware data
if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber:
data.fwSuspend, data.fwResume = self.fwdata[data.testnumber]
if(data.fwSuspend > 0 or data.fwResume > 0):
data.fwValid = True
# battery data
if len(self.battery) > data.testnumber:
m = re.match(self.batteryfmt, self.battery[data.testnumber])
if m:
data.battery = m.groups()
# sleep mode enter errors
if len(self.testerror) > data.testnumber:
m = re.match(self.testerrfmt, self.testerror[data.testnumber])
if m:
data.enterfail = m.group('e')
# Class: TestRun # Class: TestRun
# Description: # Description:
# A container for a suspend/resume test run. This is necessary as # A container for a suspend/resume test run. This is necessary as
# there could be more than one, and they need to be separate. # there could be more than one, and they need to be separate.
class TestRun: class TestRun:
ftemp = dict()
ttemp = dict()
data = 0
def __init__(self, dataobj): def __init__(self, dataobj):
self.data = dataobj self.data = dataobj
self.ftemp = dict() self.ftemp = dict()
self.ttemp = dict() self.ttemp = dict()
class ProcessMonitor: class ProcessMonitor:
proclist = dict() def __init__(self):
running = False self.proclist = dict()
self.running = False
def procstat(self): def procstat(self):
c = ['cat /proc/[1-9]*/stat 2>/dev/null'] c = ['cat /proc/[1-9]*/stat 2>/dev/null']
process = Popen(c, shell=True, stdout=PIPE) process = Popen(c, shell=True, stdout=PIPE)
...@@ -2391,8 +2490,8 @@ class ProcessMonitor: ...@@ -2391,8 +2490,8 @@ class ProcessMonitor:
# markers, and/or kprobes required for primary parsing. # markers, and/or kprobes required for primary parsing.
def doesTraceLogHaveTraceEvents(): def doesTraceLogHaveTraceEvents():
kpcheck = ['_cal: (', '_cpu_down()'] kpcheck = ['_cal: (', '_cpu_down()']
techeck = ['suspend_resume'] techeck = ['suspend_resume', 'device_pm_callback']
tmcheck = ['SUSPEND START', 'RESUME COMPLETE'] tmcheck = ['tracing_mark_write']
sysvals.usekprobes = False sysvals.usekprobes = False
fp = sysvals.openlog(sysvals.ftracefile, 'r') fp = sysvals.openlog(sysvals.ftracefile, 'r')
for line in fp: for line in fp:
...@@ -2414,23 +2513,14 @@ def doesTraceLogHaveTraceEvents(): ...@@ -2414,23 +2513,14 @@ def doesTraceLogHaveTraceEvents():
check.remove(i) check.remove(i)
tmcheck = check tmcheck = check
fp.close() fp.close()
if len(techeck) == 0: sysvals.usetraceevents = True if len(techeck) < 2 else False
sysvals.usetraceevents = True sysvals.usetracemarkers = True if len(tmcheck) == 0 else False
else:
sysvals.usetraceevents = False
if len(tmcheck) == 0:
sysvals.usetracemarkers = True
else:
sysvals.usetracemarkers = False
# Function: appendIncompleteTraceLog # Function: appendIncompleteTraceLog
# Description: # Description:
# [deprecated for kernel 3.15 or newer] # [deprecated for kernel 3.15 or newer]
# Legacy support of ftrace outputs that lack the device_pm_callback # Adds callgraph data which lacks trace event data. This is only
# and/or suspend_resume trace events. The primary data should be # for timelines generated from 3.15 or older
# taken from dmesg, and this ftrace is used only for callgraph data
# or custom actions in the timeline. The data is appended to the Data
# objects provided.
# Arguments: # Arguments:
# testruns: the array of Data objects obtained from parseKernelLog # testruns: the array of Data objects obtained from parseKernelLog
def appendIncompleteTraceLog(testruns): def appendIncompleteTraceLog(testruns):
...@@ -2460,13 +2550,19 @@ def appendIncompleteTraceLog(testruns): ...@@ -2460,13 +2550,19 @@ def appendIncompleteTraceLog(testruns):
elif re.match(tp.cmdlinefmt, line): elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line tp.cmdline = line
continue continue
elif re.match(tp.batteryfmt, line):
tp.battery.append(line)
continue
elif re.match(tp.testerrfmt, line):
tp.testerror.append(line)
continue
# determine the trace data type (required for further parsing) # determine the trace data type (required for further parsing)
m = re.match(sysvals.tracertypefmt, line) m = re.match(tp.tracertypefmt, line)
if(m): if(m):
tp.setTracerType(m.group('t')) tp.setTracerType(m.group('t'))
continue continue
# device properties line # device properties line
if(re.match(sysvals.devpropfmt, line)): if(re.match(tp.devpropfmt, line)):
devProps(line) devProps(line)
continue continue
# parse only valid lines, if this is not one move on # parse only valid lines, if this is not one move on
...@@ -2506,87 +2602,7 @@ def appendIncompleteTraceLog(testruns): ...@@ -2506,87 +2602,7 @@ def appendIncompleteTraceLog(testruns):
continue continue
# trace event processing # trace event processing
if(t.fevent): if(t.fevent):
# general trace events have two types, begin and end continue
if(re.match('(?P<name>.*) begin$', t.name)):
isbegin = True
elif(re.match('(?P<name>.*) end$', t.name)):
isbegin = False
else:
continue
m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
if(m):
val = m.group('val')
if val == '0':
name = m.group('name')
else:
name = m.group('name')+'['+val+']'
else:
m = re.match('(?P<name>.*) .*', t.name)
name = m.group('name')
# special processing for trace events
if re.match('dpm_prepare\[.*', name):
continue
elif re.match('machine_suspend.*', name):
continue
elif re.match('suspend_enter\[.*', name):
if(not isbegin):
data.dmesg['suspend_prepare']['end'] = t.time
continue
elif re.match('dpm_suspend\[.*', name):
if(not isbegin):
data.dmesg['suspend']['end'] = t.time
continue
elif re.match('dpm_suspend_late\[.*', name):
if(isbegin):
data.dmesg['suspend_late']['start'] = t.time
else:
data.dmesg['suspend_late']['end'] = t.time
continue
elif re.match('dpm_suspend_noirq\[.*', name):
if(isbegin):
data.dmesg['suspend_noirq']['start'] = t.time
else:
data.dmesg['suspend_noirq']['end'] = t.time
continue
elif re.match('dpm_resume_noirq\[.*', name):
if(isbegin):
data.dmesg['resume_machine']['end'] = t.time
data.dmesg['resume_noirq']['start'] = t.time
else:
data.dmesg['resume_noirq']['end'] = t.time
continue
elif re.match('dpm_resume_early\[.*', name):
if(isbegin):
data.dmesg['resume_early']['start'] = t.time
else:
data.dmesg['resume_early']['end'] = t.time
continue
elif re.match('dpm_resume\[.*', name):
if(isbegin):
data.dmesg['resume']['start'] = t.time
else:
data.dmesg['resume']['end'] = t.time
continue
elif re.match('dpm_complete\[.*', name):
if(isbegin):
data.dmesg['resume_complete']['start'] = t.time
else:
data.dmesg['resume_complete']['end'] = t.time
continue
# skip trace events inside devices calls
if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
continue
# global events (outside device calls) are simply graphed
if(isbegin):
# store each trace event in ttemp
if(name not in testrun[testidx].ttemp):
testrun[testidx].ttemp[name] = []
testrun[testidx].ttemp[name].append(\
{'begin': t.time, 'end': t.time})
else:
# finish off matching trace event in ttemp
if(name in testrun[testidx].ttemp):
testrun[testidx].ttemp[name][-1]['end'] = t.time
# call/return processing # call/return processing
elif sysvals.usecallgraph: elif sysvals.usecallgraph:
# create a callgraph object for the data # create a callgraph object for the data
...@@ -2603,12 +2619,6 @@ def appendIncompleteTraceLog(testruns): ...@@ -2603,12 +2619,6 @@ def appendIncompleteTraceLog(testruns):
tf.close() tf.close()
for test in testrun: for test in testrun:
# add the traceevent data to the device hierarchy
if(sysvals.usetraceevents):
for name in test.ttemp:
for event in test.ttemp[name]:
test.data.newActionGlobal(name, event['begin'], event['end'])
# add the callgraph data to the device hierarchy # add the callgraph data to the device hierarchy
for pid in test.ftemp: for pid in test.ftemp:
for cg in test.ftemp[pid]: for cg in test.ftemp[pid]:
...@@ -2621,7 +2631,7 @@ def appendIncompleteTraceLog(testruns): ...@@ -2621,7 +2631,7 @@ def appendIncompleteTraceLog(testruns):
continue continue
callstart = cg.start callstart = cg.start
callend = cg.end callend = cg.end
for p in test.data.phases: for p in test.data.sortedPhases():
if(test.data.dmesg[p]['start'] <= callstart and if(test.data.dmesg[p]['start'] <= callstart and
callstart <= test.data.dmesg[p]['end']): callstart <= test.data.dmesg[p]['end']):
list = test.data.dmesg[p]['list'] list = test.data.dmesg[p]['list']
...@@ -2648,10 +2658,12 @@ def parseTraceLog(live=False): ...@@ -2648,10 +2658,12 @@ def parseTraceLog(live=False):
doError('%s does not exist' % sysvals.ftracefile) doError('%s does not exist' % sysvals.ftracefile)
if not live: if not live:
sysvals.setupAllKprobes() sysvals.setupAllKprobes()
krescalls = ['pm_notifier_call_chain', 'pm_restore_console']
tracewatch = [] tracewatch = []
if sysvals.usekprobes: if sysvals.usekprobes:
tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF'] 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON',
'CPU_OFF', 'timekeeping_freeze', 'acpi_suspend']
# extract the callgraph and traceevent data # extract the callgraph and traceevent data
tp = TestProps() tp = TestProps()
...@@ -2674,18 +2686,24 @@ def parseTraceLog(live=False): ...@@ -2674,18 +2686,24 @@ def parseTraceLog(live=False):
elif re.match(tp.cmdlinefmt, line): elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line tp.cmdline = line
continue continue
elif re.match(tp.batteryfmt, line):
tp.battery.append(line)
continue
elif re.match(tp.testerrfmt, line):
tp.testerror.append(line)
continue
# firmware line: pull out any firmware data # firmware line: pull out any firmware data
m = re.match(sysvals.firmwarefmt, line) m = re.match(tp.firmwarefmt, line)
if(m): if(m):
tp.fwdata.append((int(m.group('s')), int(m.group('r')))) tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
continue continue
# tracer type line: determine the trace data type # tracer type line: determine the trace data type
m = re.match(sysvals.tracertypefmt, line) m = re.match(tp.tracertypefmt, line)
if(m): if(m):
tp.setTracerType(m.group('t')) tp.setTracerType(m.group('t'))
continue continue
# device properties line # device properties line
if(re.match(sysvals.devpropfmt, line)): if(re.match(tp.devpropfmt, line)):
devProps(line) devProps(line)
continue continue
# ignore all other commented lines # ignore all other commented lines
...@@ -2714,20 +2732,19 @@ def parseTraceLog(live=False): ...@@ -2714,20 +2732,19 @@ def parseTraceLog(live=False):
continue continue
# find the start of suspend # find the start of suspend
if(t.startMarker()): if(t.startMarker()):
phase = 'suspend_prepare'
data = Data(len(testdata)) data = Data(len(testdata))
testdata.append(data) testdata.append(data)
testrun = TestRun(data) testrun = TestRun(data)
testruns.append(testrun) testruns.append(testrun)
tp.parseStamp(data, sysvals) tp.parseStamp(data, sysvals)
data.setStart(t.time) data.setStart(t.time)
data.tKernSus = t.time phase = data.setPhase('suspend_prepare', t.time, True)
continue continue
if(not data): if(not data):
continue continue
# process cpu exec line # process cpu exec line
if t.type == 'tracing_mark_write': if t.type == 'tracing_mark_write':
m = re.match(sysvals.procexecfmt, t.name) m = re.match(tp.procexecfmt, t.name)
if(m): if(m):
proclist = dict() proclist = dict()
for ps in m.group('ps').split(','): for ps in m.group('ps').split(','):
...@@ -2740,28 +2757,17 @@ def parseTraceLog(live=False): ...@@ -2740,28 +2757,17 @@ def parseTraceLog(live=False):
continue continue
# find the end of resume # find the end of resume
if(t.endMarker()): if(t.endMarker()):
data.setEnd(t.time) data.handleEndMarker(t.time)
if data.tKernRes == 0.0:
data.tKernRes = t.time
if data.dmesg['resume_complete']['end'] < 0:
data.dmesg['resume_complete']['end'] = t.time
if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
if(data.tSuspended != 0 and data.tResumed != 0 and \
(data.fwSuspend > 0 or data.fwResume > 0)):
data.fwValid = True
if(not sysvals.usetracemarkers): if(not sysvals.usetracemarkers):
# no trace markers? then quit and be sure to finish recording # no trace markers? then quit and be sure to finish recording
# the event we used to trigger resume end # the event we used to trigger resume end
if(len(testrun.ttemp['thaw_processes']) > 0): if('thaw_processes' in testrun.ttemp and len(testrun.ttemp['thaw_processes']) > 0):
# if an entry exists, assume this is its end # if an entry exists, assume this is its end
testrun.ttemp['thaw_processes'][-1]['end'] = t.time testrun.ttemp['thaw_processes'][-1]['end'] = t.time
break break
continue continue
# trace event processing # trace event processing
if(t.fevent): if(t.fevent):
if(phase == 'post_resume'):
data.setEnd(t.time)
if(t.type == 'suspend_resume'): if(t.type == 'suspend_resume'):
# suspend_resume trace events have two types, begin and end # suspend_resume trace events have two types, begin and end
if(re.match('(?P<name>.*) begin$', t.name)): if(re.match('(?P<name>.*) begin$', t.name)):
...@@ -2786,86 +2792,61 @@ def parseTraceLog(live=False): ...@@ -2786,86 +2792,61 @@ def parseTraceLog(live=False):
# -- phase changes -- # -- phase changes --
# start of kernel suspend # start of kernel suspend
if(re.match('suspend_enter\[.*', t.name)): if(re.match('suspend_enter\[.*', t.name)):
if(isbegin and data.start == data.tKernSus): if(isbegin):
data.dmesg[phase]['start'] = t.time
data.tKernSus = t.time data.tKernSus = t.time
continue continue
# suspend_prepare start # suspend_prepare start
elif(re.match('dpm_prepare\[.*', t.name)): elif(re.match('dpm_prepare\[.*', t.name)):
phase = 'suspend_prepare' phase = 'suspend_prepare'
if(not isbegin): if not isbegin:
data.dmesg[phase]['end'] = t.time data.setPhase(phase, t.time, isbegin)
if data.dmesg[phase]['start'] < 0: if isbegin and data.tKernSus == 0:
data.dmesg[phase]['start'] = data.start data.tKernSus = t.time
continue continue
# suspend start # suspend start
elif(re.match('dpm_suspend\[.*', t.name)): elif(re.match('dpm_suspend\[.*', t.name)):
phase = 'suspend' phase = data.setPhase('suspend', t.time, isbegin)
data.setPhase(phase, t.time, isbegin)
continue continue
# suspend_late start # suspend_late start
elif(re.match('dpm_suspend_late\[.*', t.name)): elif(re.match('dpm_suspend_late\[.*', t.name)):
phase = 'suspend_late' phase = data.setPhase('suspend_late', t.time, isbegin)
data.setPhase(phase, t.time, isbegin)
continue continue
# suspend_noirq start # suspend_noirq start
elif(re.match('dpm_suspend_noirq\[.*', t.name)): elif(re.match('dpm_suspend_noirq\[.*', t.name)):
if data.phaseCollision('suspend_noirq', isbegin, line): phase = data.setPhase('suspend_noirq', t.time, isbegin)
continue
phase = 'suspend_noirq'
data.setPhase(phase, t.time, isbegin)
if(not isbegin):
phase = 'suspend_machine'
data.dmesg[phase]['start'] = t.time
continue continue
# suspend_machine/resume_machine # suspend_machine/resume_machine
elif(re.match('machine_suspend\[.*', t.name)): elif(re.match('machine_suspend\[.*', t.name)):
if(isbegin): if(isbegin):
phase = 'suspend_machine' lp = data.lastPhase()
data.dmesg[phase]['end'] = t.time phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True)
data.tSuspended = t.time data.setPhase(phase, t.time, False)
else: if data.tSuspended == 0:
if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
data.dmesg['suspend_machine']['end'] = t.time
data.tSuspended = t.time data.tSuspended = t.time
phase = 'resume_machine' else:
data.dmesg[phase]['start'] = t.time phase = data.setPhase('resume_machine', t.time, True)
data.tResumed = t.time if(sysvals.suspendmode in ['mem', 'disk']):
data.tLow = data.tResumed - data.tSuspended if 'suspend_machine' in data.dmesg:
continue data.dmesg['suspend_machine']['end'] = t.time
# acpi_suspend
elif(re.match('acpi_suspend\[.*', t.name)):
# acpi_suspend[0] S0i3
if(re.match('acpi_suspend\[0\] begin', t.name)):
if(sysvals.suspendmode == 'mem'):
tp.S0i3 = True
data.dmesg['suspend_machine']['end'] = t.time
data.tSuspended = t.time data.tSuspended = t.time
if data.tResumed == 0:
data.tResumed = t.time
continue continue
# resume_noirq start # resume_noirq start
elif(re.match('dpm_resume_noirq\[.*', t.name)): elif(re.match('dpm_resume_noirq\[.*', t.name)):
if data.phaseCollision('resume_noirq', isbegin, line): phase = data.setPhase('resume_noirq', t.time, isbegin)
continue
phase = 'resume_noirq'
data.setPhase(phase, t.time, isbegin)
if(isbegin):
data.dmesg['resume_machine']['end'] = t.time
continue continue
# resume_early start # resume_early start
elif(re.match('dpm_resume_early\[.*', t.name)): elif(re.match('dpm_resume_early\[.*', t.name)):
phase = 'resume_early' phase = data.setPhase('resume_early', t.time, isbegin)
data.setPhase(phase, t.time, isbegin)
continue continue
# resume start # resume start
elif(re.match('dpm_resume\[.*', t.name)): elif(re.match('dpm_resume\[.*', t.name)):
phase = 'resume' phase = data.setPhase('resume', t.time, isbegin)
data.setPhase(phase, t.time, isbegin)
continue continue
# resume complete start # resume complete start
elif(re.match('dpm_complete\[.*', t.name)): elif(re.match('dpm_complete\[.*', t.name)):
phase = 'resume_complete' phase = data.setPhase('resume_complete', t.time, isbegin)
if(isbegin):
data.dmesg[phase]['start'] = t.time
continue continue
# skip trace events inside devices calls # skip trace events inside devices calls
if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)): if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
...@@ -2881,13 +2862,10 @@ def parseTraceLog(live=False): ...@@ -2881,13 +2862,10 @@ def parseTraceLog(live=False):
if(len(testrun.ttemp[name]) > 0): if(len(testrun.ttemp[name]) > 0):
# if an entry exists, assume this is its end # if an entry exists, assume this is its end
testrun.ttemp[name][-1]['end'] = t.time testrun.ttemp[name][-1]['end'] = t.time
elif(phase == 'post_resume'):
# post resume events can just have ends
testrun.ttemp[name].append({
'begin': data.dmesg[phase]['start'],
'end': t.time})
# device callback start # device callback start
elif(t.type == 'device_pm_callback_start'): elif(t.type == 'device_pm_callback_start'):
if phase not in data.dmesg:
continue
m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
t.name); t.name);
if(not m): if(not m):
...@@ -2901,6 +2879,8 @@ def parseTraceLog(live=False): ...@@ -2901,6 +2879,8 @@ def parseTraceLog(live=False):
data.devpids.append(pid) data.devpids.append(pid)
# device callback finish # device callback finish
elif(t.type == 'device_pm_callback_end'): elif(t.type == 'device_pm_callback_end'):
if phase not in data.dmesg:
continue
m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name); m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
if(not m): if(not m):
continue continue
...@@ -2941,9 +2921,9 @@ def parseTraceLog(live=False): ...@@ -2941,9 +2921,9 @@ def parseTraceLog(live=False):
e['end'] = t.time e['end'] = t.time
e['rdata'] = kprobedata e['rdata'] = kprobedata
# end of kernel resume # end of kernel resume
if(kprobename == 'pm_notifier_call_chain' or \ if(phase != 'suspend_prepare' and kprobename in krescalls):
kprobename == 'pm_restore_console'): if phase in data.dmesg:
data.dmesg[phase]['end'] = t.time data.dmesg[phase]['end'] = t.time
data.tKernRes = t.time data.tKernRes = t.time
# callgraph processing # callgraph processing
...@@ -2961,10 +2941,13 @@ def parseTraceLog(live=False): ...@@ -2961,10 +2941,13 @@ def parseTraceLog(live=False):
if(res == -1): if(res == -1):
testrun.ftemp[key][-1].addLine(t) testrun.ftemp[key][-1].addLine(t)
tf.close() tf.close()
if data and not data.devicegroups:
sysvals.vprint('WARNING: end marker is missing')
data.handleEndMarker(t.time)
if sysvals.suspendmode == 'command': if sysvals.suspendmode == 'command':
for test in testruns: for test in testruns:
for p in test.data.phases: for p in test.data.sortedPhases():
if p == 'suspend_prepare': if p == 'suspend_prepare':
test.data.dmesg[p]['start'] = test.data.start test.data.dmesg[p]['start'] = test.data.start
test.data.dmesg[p]['end'] = test.data.end test.data.dmesg[p]['end'] = test.data.end
...@@ -2973,7 +2956,6 @@ def parseTraceLog(live=False): ...@@ -2973,7 +2956,6 @@ def parseTraceLog(live=False):
test.data.dmesg[p]['end'] = test.data.end test.data.dmesg[p]['end'] = test.data.end
test.data.tSuspended = test.data.end test.data.tSuspended = test.data.end
test.data.tResumed = test.data.end test.data.tResumed = test.data.end
test.data.tLow = 0
test.data.fwValid = False test.data.fwValid = False
# dev source and procmon events can be unreadable with mixed phase height # dev source and procmon events can be unreadable with mixed phase height
...@@ -3040,8 +3022,8 @@ def parseTraceLog(live=False): ...@@ -3040,8 +3022,8 @@ def parseTraceLog(live=False):
sortkey = '%f%f%d' % (cg.start, cg.end, pid) sortkey = '%f%f%d' % (cg.start, cg.end, pid)
sortlist[sortkey] = cg sortlist[sortkey] = cg
elif len(cg.list) > 1000000: elif len(cg.list) > 1000000:
print 'WARNING: the callgraph for %s is massive (%d lines)' %\ sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\
(devname, len(cg.list)) (devname, len(cg.list)))
# create blocks for orphan cg data # create blocks for orphan cg data
for sortkey in sorted(sortlist): for sortkey in sorted(sortlist):
cg = sortlist[sortkey] cg = sortlist[sortkey]
...@@ -3057,25 +3039,34 @@ def parseTraceLog(live=False): ...@@ -3057,25 +3039,34 @@ def parseTraceLog(live=False):
for data in testdata: for data in testdata:
tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1)) tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))
terr = '' terr = ''
lp = data.phases[0] phasedef = data.phasedef
for p in data.phases: lp = 'suspend_prepare'
if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
if p not in data.dmesg:
if not terr: if not terr:
print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp) print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)
terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp) terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp)
error.append(terr) error.append(terr)
if data.tSuspended == 0:
data.tSuspended = data.dmesg[lp]['end']
if data.tResumed == 0:
data.tResumed = data.dmesg[lp]['end']
data.fwValid = False
sysvals.vprint('WARNING: phase "%s" is missing!' % p) sysvals.vprint('WARNING: phase "%s" is missing!' % p)
if(data.dmesg[p]['start'] < 0): lp = p
data.dmesg[p]['start'] = data.dmesg[lp]['end'] if not terr and data.enterfail:
if(p == 'resume_machine'): print 'test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail)
data.tSuspended = data.dmesg[lp]['end'] terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode)
data.tResumed = data.dmesg[lp]['end'] error.append(terr)
data.tLow = 0 lp = data.sortedPhases()[0]
if(data.dmesg[p]['end'] < 0): for p in data.sortedPhases():
data.dmesg[p]['end'] = data.dmesg[p]['start']
if(p != lp and not ('machine' in p and 'machine' in lp)): if(p != lp and not ('machine' in p and 'machine' in lp)):
data.dmesg[lp]['end'] = data.dmesg[p]['start'] data.dmesg[lp]['end'] = data.dmesg[p]['start']
lp = p lp = p
if data.tSuspended == 0:
data.tSuspended = data.tKernRes
if data.tResumed == 0:
data.tResumed = data.tSuspended
if(len(sysvals.devicefilter) > 0): if(len(sysvals.devicefilter) > 0):
data.deviceFilter(sysvals.devicefilter) data.deviceFilter(sysvals.devicefilter)
...@@ -3127,7 +3118,13 @@ def loadKernelLog(): ...@@ -3127,7 +3118,13 @@ def loadKernelLog():
elif re.match(tp.cmdlinefmt, line): elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line tp.cmdline = line
continue continue
m = re.match(sysvals.firmwarefmt, line) elif re.match(tp.batteryfmt, line):
tp.battery.append(line)
continue
elif re.match(tp.testerrfmt, line):
tp.testerror.append(line)
continue
m = re.match(tp.firmwarefmt, line)
if(m): if(m):
tp.fwdata.append((int(m.group('s')), int(m.group('r')))) tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
continue continue
...@@ -3140,10 +3137,6 @@ def loadKernelLog(): ...@@ -3140,10 +3137,6 @@ def loadKernelLog():
testruns.append(data) testruns.append(data)
data = Data(len(testruns)) data = Data(len(testruns))
tp.parseStamp(data, sysvals) tp.parseStamp(data, sysvals)
if len(tp.fwdata) > data.testnumber:
data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
if(data.fwSuspend > 0 or data.fwResume > 0):
data.fwValid = True
if(not data): if(not data):
continue continue
m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
...@@ -3199,30 +3192,30 @@ def parseKernelLog(data): ...@@ -3199,30 +3192,30 @@ def parseKernelLog(data):
# dmesg phase match table # dmesg phase match table
dm = { dm = {
'suspend_prepare': 'PM: Syncing filesystems.*', 'suspend_prepare': ['PM: Syncing filesystems.*'],
'suspend': 'PM: Entering [a-z]* sleep.*', 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*'],
'suspend_late': 'PM: suspend of devices complete after.*', 'suspend_late': ['PM: suspend of devices complete after.*'],
'suspend_noirq': 'PM: late suspend of devices complete after.*', 'suspend_noirq': ['PM: late suspend of devices complete after.*'],
'suspend_machine': 'PM: noirq suspend of devices complete after.*', 'suspend_machine': ['PM: noirq suspend of devices complete after.*'],
'resume_machine': 'ACPI: Low-level resume complete.*', 'resume_machine': ['ACPI: Low-level resume complete.*'],
'resume_noirq': 'ACPI: Waking up from system sleep state.*', 'resume_noirq': ['ACPI: Waking up from system sleep state.*'],
'resume_early': 'PM: noirq resume of devices complete after.*', 'resume_early': ['PM: noirq resume of devices complete after.*'],
'resume': 'PM: early resume of devices complete after.*', 'resume': ['PM: early resume of devices complete after.*'],
'resume_complete': 'PM: resume of devices complete after.*', 'resume_complete': ['PM: resume of devices complete after.*'],
'post_resume': '.*Restarting tasks \.\.\..*', 'post_resume': ['.*Restarting tasks \.\.\..*'],
} }
if(sysvals.suspendmode == 'standby'): if(sysvals.suspendmode == 'standby'):
dm['resume_machine'] = 'PM: Restoring platform NVS memory' dm['resume_machine'] = ['PM: Restoring platform NVS memory']
elif(sysvals.suspendmode == 'disk'): elif(sysvals.suspendmode == 'disk'):
dm['suspend_late'] = 'PM: freeze of devices complete after.*' dm['suspend_late'] = ['PM: freeze of devices complete after.*']
dm['suspend_noirq'] = 'PM: late 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['suspend_machine'] = ['PM: noirq freeze of devices complete after.*']
dm['resume_machine'] = 'PM: Restoring platform NVS memory' dm['resume_machine'] = ['PM: Restoring platform NVS memory']
dm['resume_early'] = 'PM: noirq restore of devices complete after.*' dm['resume_early'] = ['PM: noirq restore of devices complete after.*']
dm['resume'] = 'PM: early restore of devices complete after.*' dm['resume'] = ['PM: early restore of devices complete after.*']
dm['resume_complete'] = 'PM: restore of devices complete after.*' dm['resume_complete'] = ['PM: restore of devices complete after.*']
elif(sysvals.suspendmode == 'freeze'): elif(sysvals.suspendmode == 'freeze'):
dm['resume_machine'] = 'ACPI: resume from mwait' dm['resume_machine'] = ['ACPI: resume from mwait']
# action table (expected events that occur and show up in dmesg) # action table (expected events that occur and show up in dmesg)
at = { at = {
...@@ -3264,81 +3257,89 @@ def parseKernelLog(data): ...@@ -3264,81 +3257,89 @@ def parseKernelLog(data):
else: else:
continue continue
# check for a phase change line
phasechange = False
for p in dm:
for s in dm[p]:
if(re.match(s, msg)):
phasechange, phase = True, p
break
# hack for determining resume_machine end for freeze # hack for determining resume_machine end for freeze
if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
and phase == 'resume_machine' and \ and phase == 'resume_machine' and \
re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
data.dmesg['resume_machine']['end'] = ktime data.setPhase(phase, ktime, False)
phase = 'resume_noirq' phase = 'resume_noirq'
data.dmesg[phase]['start'] = ktime data.setPhase(phase, ktime, True)
# suspend start if phasechange:
if(re.match(dm['suspend_prepare'], msg)): if phase == 'suspend_prepare':
phase = 'suspend_prepare' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime data.setStart(ktime)
data.setStart(ktime) data.tKernSus = ktime
data.tKernSus = ktime elif phase == 'suspend':
# suspend start lp = data.lastPhase()
elif(re.match(dm['suspend'], msg)): if lp:
data.dmesg['suspend_prepare']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'suspend' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'suspend_late':
# suspend_late start lp = data.lastPhase()
elif(re.match(dm['suspend_late'], msg)): if lp:
data.dmesg['suspend']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'suspend_late' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'suspend_noirq':
# suspend_noirq start lp = data.lastPhase()
elif(re.match(dm['suspend_noirq'], msg)): if lp:
data.dmesg['suspend_late']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'suspend_noirq' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'suspend_machine':
# suspend_machine start lp = data.lastPhase()
elif(re.match(dm['suspend_machine'], msg)): if lp:
data.dmesg['suspend_noirq']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'suspend_machine' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'resume_machine':
# resume_machine start lp = data.lastPhase()
elif(re.match(dm['resume_machine'], msg)): if(sysvals.suspendmode in ['freeze', 'standby']):
if(sysvals.suspendmode in ['freeze', 'standby']): data.tSuspended = prevktime
data.tSuspended = prevktime if lp:
data.dmesg['suspend_machine']['end'] = prevktime data.setPhase(lp, prevktime, False)
else: else:
data.tSuspended = ktime data.tSuspended = ktime
data.dmesg['suspend_machine']['end'] = ktime if lp:
phase = 'resume_machine' data.setPhase(lp, prevktime, False)
data.tResumed = ktime data.tResumed = ktime
data.tLow = data.tResumed - data.tSuspended data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'resume_noirq':
# resume_noirq start lp = data.lastPhase()
elif(re.match(dm['resume_noirq'], msg)): if lp:
data.dmesg['resume_machine']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'resume_noirq' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'resume_early':
# resume_early start lp = data.lastPhase()
elif(re.match(dm['resume_early'], msg)): if lp:
data.dmesg['resume_noirq']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'resume_early' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'resume':
# resume start lp = data.lastPhase()
elif(re.match(dm['resume'], msg)): if lp:
data.dmesg['resume_early']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'resume' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'resume_complete':
# resume complete start lp = data.lastPhase()
elif(re.match(dm['resume_complete'], msg)): if lp:
data.dmesg['resume']['end'] = ktime data.setPhase(lp, ktime, False)
phase = 'resume_complete' data.setPhase(phase, ktime, True)
data.dmesg[phase]['start'] = ktime elif phase == 'post_resume':
# post resume start lp = data.lastPhase()
elif(re.match(dm['post_resume'], msg)): if lp:
data.dmesg['resume_complete']['end'] = ktime data.setPhase(lp, ktime, False)
data.setEnd(ktime) data.setEnd(ktime)
data.tKernRes = ktime data.tKernRes = ktime
break break
# -- device callbacks -- # -- device callbacks --
if(phase in data.phases): if(phase in data.sortedPhases()):
# device init call # device init call
if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
sm = re.match('calling (?P<f>.*)\+ @ '+\ sm = re.match('calling (?P<f>.*)\+ @ '+\
...@@ -3396,24 +3397,31 @@ def parseKernelLog(data): ...@@ -3396,24 +3397,31 @@ def parseKernelLog(data):
actions[cpu].append({'begin': cpu_start, 'end': ktime}) actions[cpu].append({'begin': cpu_start, 'end': ktime})
cpu_start = ktime cpu_start = ktime
prevktime = ktime prevktime = ktime
data.initDevicegroups()
# fill in any missing phases # fill in any missing phases
lp = data.phases[0] phasedef = data.phasedef
for p in data.phases: terr, lp = '', 'suspend_prepare'
if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
print('WARNING: phase "%s" is missing, something went wrong!' % p) if p not in data.dmesg:
print(' In %s, this dmesg line denotes the start of %s:' % \ if not terr:
(sysvals.suspendmode, p)) print 'TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp)
print(' "%s"' % dm[p]) terr = '%s failed in %s phase' % (sysvals.suspendmode, lp)
if(data.dmesg[p]['start'] < 0): if data.tSuspended == 0:
data.dmesg[p]['start'] = data.dmesg[lp]['end'] data.tSuspended = data.dmesg[lp]['end']
if(p == 'resume_machine'): if data.tResumed == 0:
data.tSuspended = data.dmesg[lp]['end'] data.tResumed = data.dmesg[lp]['end']
data.tResumed = data.dmesg[lp]['end'] sysvals.vprint('WARNING: phase "%s" is missing!' % p)
data.tLow = 0 lp = p
if(data.dmesg[p]['end'] < 0): lp = data.sortedPhases()[0]
data.dmesg[p]['end'] = data.dmesg[p]['start'] for p in data.sortedPhases():
if(p != lp and not ('machine' in p and 'machine' in lp)):
data.dmesg[lp]['end'] = data.dmesg[p]['start']
lp = p lp = p
if data.tSuspended == 0:
data.tSuspended = data.tKernRes
if data.tResumed == 0:
data.tResumed = data.tSuspended
# fill in any actions we've found # fill in any actions we've found
for name in actions: for name in actions:
...@@ -3462,7 +3470,7 @@ def addCallgraphs(sv, hf, data): ...@@ -3462,7 +3470,7 @@ def addCallgraphs(sv, hf, data):
hf.write('<section id="callgraphs" class="callgraph">\n') hf.write('<section id="callgraphs" class="callgraph">\n')
# write out the ftrace data converted to html # write out the ftrace data converted to html
num = 0 num = 0
for p in data.phases: for p in data.sortedPhases():
if sv.cgphase and p != sv.cgphase: if sv.cgphase and p != sv.cgphase:
continue continue
list = data.dmesg[p]['list'] list = data.dmesg[p]['list']
...@@ -3505,7 +3513,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3505,7 +3513,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
table {width:100%;border-collapse: collapse;}\n\ table {width:100%;border-collapse: collapse;}\n\
.summary {border:1px solid;}\n\ .summary {border:1px solid;}\n\
th {border: 1px solid black;background:#222;color:white;}\n\ th {border: 1px solid black;background:#222;color:white;}\n\
td {font: 16px "Times New Roman";text-align: center;}\n\ td {font: 14px "Times New Roman";text-align: center;}\n\
tr.head td {border: 1px solid black;background:#aaa;}\n\ tr.head td {border: 1px solid black;background:#aaa;}\n\
tr.alt {background-color:#ddd;}\n\ tr.alt {background-color:#ddd;}\n\
tr.notice {color:red;}\n\ tr.notice {color:red;}\n\
...@@ -3521,7 +3529,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3521,7 +3529,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
iMin, iMed, iMax = [0, 0], [0, 0], [0, 0] iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
num = 0 num = 0
lastmode = '' lastmode = ''
cnt = {'pass':0, 'fail':0, 'hang':0} cnt = dict()
for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])): for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
mode = data['mode'] mode = data['mode']
if mode not in list: if mode not in list:
...@@ -3541,10 +3549,14 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3541,10 +3549,14 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
tVal = [float(data['suspend']), float(data['resume'])] tVal = [float(data['suspend']), float(data['resume'])]
list[mode]['data'].append([data['host'], data['kernel'], list[mode]['data'].append([data['host'], data['kernel'],
data['time'], tVal[0], tVal[1], data['url'], data['result'], data['time'], tVal[0], tVal[1], data['url'], data['result'],
data['issues']]) data['issues'], data['sus_worst'], data['sus_worsttime'],
data['res_worst'], data['res_worsttime']])
idx = len(list[mode]['data']) - 1 idx = len(list[mode]['data']) - 1
if data['result'] not in cnt:
cnt[data['result']] = 1
else:
cnt[data['result']] += 1
if data['result'] == 'pass': if data['result'] == 'pass':
cnt['pass'] += 1
for i in range(2): for i in range(2):
tMed[i].append(tVal[i]) tMed[i].append(tVal[i])
tAvg[i] += tVal[i] tAvg[i] += tVal[i]
...@@ -3555,10 +3567,6 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3555,10 +3567,6 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
iMax[i] = idx iMax[i] = idx
tMax[i] = tVal[i] tMax[i] = tVal[i]
num += 1 num += 1
elif data['result'] == 'hang':
cnt['hang'] += 1
elif data['result'] == 'fail':
cnt['fail'] += 1
lastmode = mode lastmode = mode
if lastmode and num > 0: if lastmode and num > 0:
for i in range(2): for i in range(2):
...@@ -3585,11 +3593,14 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3585,11 +3593,14 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
html += '<table class="summary">\n<tr>\n' + th.format('#') +\ html += '<table class="summary">\n<tr>\n' + th.format('#') +\
th.format('Mode') + th.format('Host') + th.format('Kernel') +\ th.format('Mode') + th.format('Host') + th.format('Kernel') +\
th.format('Test Time') + th.format('Result') + th.format('Issues') +\ th.format('Test Time') + th.format('Result') + th.format('Issues') +\
th.format('Suspend') + th.format('Resume') + th.format('Detail') + '</tr>\n' th.format('Suspend') + th.format('Resume') +\
th.format('Worst Suspend Device') + th.format('SD Time') +\
th.format('Worst Resume Device') + th.format('RD Time') +\
th.format('Detail') + '</tr>\n'
# export list into html # export list into html
head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\ head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\
'<td colspan=8 class="sus">Suspend Avg={2} '+\ '<td colspan=12 class="sus">Suspend Avg={2} '+\
'<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\ '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\
'<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\ '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\
'<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\ '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\
...@@ -3598,7 +3609,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3598,7 +3609,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
'<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\ '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\
'<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\ '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\
'</tr>\n' '</tr>\n'
headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=8></td></tr>\n' headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=12></td></tr>\n'
for mode in list: for mode in list:
# header line for each suspend mode # header line for each suspend mode
num = 0 num = 0
...@@ -3641,6 +3652,10 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3641,6 +3652,10 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
html += td.format(d[7]) # issues html += td.format(d[7]) # issues
html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend
html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume
html += td.format(d[8]) # sus_worst
html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time
html += td.format(d[10]) # res_worst
html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time
html += tdlink.format(d[5]) if d[5] else td.format('') # url html += tdlink.format(d[5]) if d[5] else td.format('') # url
html += '</tr>\n' html += '</tr>\n'
num += 1 num += 1
...@@ -3677,7 +3692,8 @@ def createHTML(testruns, testfail): ...@@ -3677,7 +3692,8 @@ def createHTML(testruns, testfail):
for data in testruns: for data in testruns:
if data.kerror: if data.kerror:
kerror = True kerror = True
data.normalizeTime(testruns[-1].tSuspended) if(sysvals.suspendmode in ['freeze', 'standby']):
data.trimFreezeTime(testruns[-1].tSuspended)
# html function templates # html function templates
html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}&rarr;</div>\n' html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}&rarr;</div>\n'
...@@ -3721,8 +3737,8 @@ def createHTML(testruns, testfail): ...@@ -3721,8 +3737,8 @@ def createHTML(testruns, testfail):
sktime, rktime = data.getTimeValues() sktime, rktime = data.getTimeValues()
if(tTotal == 0): if(tTotal == 0):
doError('No timeline data') doError('No timeline data')
if(data.tLow > 0): if(len(data.tLow) > 0):
low_time = '%.0f'%(data.tLow*1000) low_time = '|'.join(data.tLow)
if sysvals.suspendmode == 'command': if sysvals.suspendmode == 'command':
run_time = '%.0f'%((data.end-data.start)*1000) run_time = '%.0f'%((data.end-data.start)*1000)
if sysvals.testcommand: if sysvals.testcommand:
...@@ -3743,7 +3759,7 @@ def createHTML(testruns, testfail): ...@@ -3743,7 +3759,7 @@ def createHTML(testruns, testfail):
if(len(testruns) > 1): if(len(testruns) > 1):
testdesc1 = testdesc2 = ordinal(data.testnumber+1) testdesc1 = testdesc2 = ordinal(data.testnumber+1)
testdesc2 += ' ' testdesc2 += ' '
if(data.tLow == 0): if(len(data.tLow) == 0):
thtml = html_timetotal.format(suspend_time, \ thtml = html_timetotal.format(suspend_time, \
resume_time, testdesc1, stitle, rtitle) resume_time, testdesc1, stitle, rtitle)
else: else:
...@@ -3762,7 +3778,7 @@ def createHTML(testruns, testfail): ...@@ -3762,7 +3778,7 @@ def createHTML(testruns, testfail):
rtitle = 'time from firmware mode to return from kernel enter_state(%s) [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): if(len(testruns) > 1):
testdesc = ordinal(data.testnumber+1)+' '+testdesc testdesc = ordinal(data.testnumber+1)+' '+testdesc
if(data.tLow == 0): if(len(data.tLow) == 0):
thtml = html_timetotal.format(suspend_time, \ thtml = html_timetotal.format(suspend_time, \
resume_time, testdesc, stitle, rtitle) resume_time, testdesc, stitle, rtitle)
else: else:
...@@ -3820,15 +3836,14 @@ def createHTML(testruns, testfail): ...@@ -3820,15 +3836,14 @@ def createHTML(testruns, testfail):
# draw the full timeline # draw the full timeline
devtl.createZoomBox(sysvals.suspendmode, len(testruns)) devtl.createZoomBox(sysvals.suspendmode, len(testruns))
phases = {'suspend':[],'resume':[]}
for phase in data.dmesg:
if 'resume' in phase:
phases['resume'].append(phase)
else:
phases['suspend'].append(phase)
# draw each test run chronologically
for data in testruns: for data in testruns:
# draw each test run and block chronologically
phases = {'suspend':[],'resume':[]}
for phase in data.sortedPhases():
if data.dmesg[phase]['start'] >= data.tSuspended:
phases['resume'].append(phase)
else:
phases['suspend'].append(phase)
# now draw the actual timeline blocks # now draw the actual timeline blocks
for dir in phases: for dir in phases:
# draw suspend and resume blocks separately # draw suspend and resume blocks separately
...@@ -3850,7 +3865,7 @@ def createHTML(testruns, testfail): ...@@ -3850,7 +3865,7 @@ def createHTML(testruns, testfail):
continue continue
width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal) width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH) devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)
for b in sorted(phases[dir]): for b in phases[dir]:
# draw the phase color background # draw the phase color background
phase = data.dmesg[b] phase = data.dmesg[b]
length = phase['end']-phase['start'] length = phase['end']-phase['start']
...@@ -3865,7 +3880,7 @@ def createHTML(testruns, testfail): ...@@ -3865,7 +3880,7 @@ def createHTML(testruns, testfail):
id = '%d_%d' % (idx1, idx2) id = '%d_%d' % (idx1, idx2)
right = '%f' % (((mMax-t)*100.0)/mTotal) right = '%f' % (((mMax-t)*100.0)/mTotal)
devtl.html += html_error.format(right, id, type) devtl.html += html_error.format(right, id, type)
for b in sorted(phases[dir]): for b in phases[dir]:
# draw the devices for this phase # draw the devices for this phase
phaselist = data.dmesg[b]['list'] phaselist = data.dmesg[b]['list']
for d in data.tdevlist[b]: for d in data.tdevlist[b]:
...@@ -3942,19 +3957,17 @@ def createHTML(testruns, testfail): ...@@ -3942,19 +3957,17 @@ def createHTML(testruns, testfail):
# draw a legend which describes the phases by color # draw a legend which describes the phases by color
if sysvals.suspendmode != 'command': if sysvals.suspendmode != 'command':
data = testruns[-1] phasedef = testruns[-1].phasedef
devtl.html += '<div class="legend">\n' devtl.html += '<div class="legend">\n'
pdelta = 100.0/len(data.phases) pdelta = 100.0/len(phasedef.keys())
pmargin = pdelta / 4.0 pmargin = pdelta / 4.0
for phase in data.phases: for phase in sorted(phasedef, key=lambda k:phasedef[k]['order']):
tmp = phase.split('_') id, p = '', phasedef[phase]
id = tmp[0][0] for word in phase.split('_'):
if(len(tmp) > 1): id += word[0]
id += tmp[1][0] order = '%.2f' % ((p['order'] * pdelta) + pmargin)
order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
name = string.replace(phase, '_', ' &nbsp;') name = string.replace(phase, '_', ' &nbsp;')
devtl.html += devtl.html_legend.format(order, \ devtl.html += devtl.html_legend.format(order, p['color'], name, id)
data.dmesg[phase]['color'], name, id)
devtl.html += '</div>\n' devtl.html += '</div>\n'
hf = open(sysvals.htmlfile, 'w') hf = open(sysvals.htmlfile, 'w')
...@@ -3970,7 +3983,7 @@ def createHTML(testruns, testfail): ...@@ -3970,7 +3983,7 @@ def createHTML(testruns, testfail):
pscolor = 'linear-gradient(to top left, #ccc, #eee)' pscolor = 'linear-gradient(to top left, #ccc, #eee)'
hf.write(devtl.html_phaselet.format('pre_suspend_process', \ hf.write(devtl.html_phaselet.format('pre_suspend_process', \
'0', '0', pscolor)) '0', '0', pscolor))
for b in data.phases: for b in data.sortedPhases():
phase = data.dmesg[b] phase = data.dmesg[b]
length = phase['end']-phase['start'] length = phase['end']-phase['start']
left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
...@@ -4542,16 +4555,12 @@ def setRuntimeSuspend(before=True): ...@@ -4542,16 +4555,12 @@ def setRuntimeSuspend(before=True):
def executeSuspend(): def executeSuspend():
pm = ProcessMonitor() pm = ProcessMonitor()
tp = sysvals.tpath tp = sysvals.tpath
fwdata = [] testdata = []
battery = True if getBattery() else False
# run these commands to prepare the system for suspend # run these commands to prepare the system for suspend
if sysvals.display: if sysvals.display:
if sysvals.display > 0: print('SET DISPLAY TO %s' % sysvals.display.upper())
print('TURN DISPLAY ON') displayControl(sysvals.display)
call('xset -d :0.0 dpms force suspend', shell=True)
call('xset -d :0.0 dpms force on', shell=True)
else:
print('TURN DISPLAY OFF')
call('xset -d :0.0 dpms force suspend', shell=True)
time.sleep(1) time.sleep(1)
if sysvals.sync: if sysvals.sync:
print('SYNCING FILESYSTEMS') print('SYNCING FILESYSTEMS')
...@@ -4579,6 +4588,7 @@ def executeSuspend(): ...@@ -4579,6 +4588,7 @@ def executeSuspend():
print('SUSPEND START') print('SUSPEND START')
else: else:
print('SUSPEND START (press a key to resume)') print('SUSPEND START (press a key to resume)')
bat1 = getBattery() if battery else False
# set rtcwake # set rtcwake
if(sysvals.rtcwake): if(sysvals.rtcwake):
print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
...@@ -4592,8 +4602,11 @@ def executeSuspend(): ...@@ -4592,8 +4602,11 @@ def executeSuspend():
time.sleep(sysvals.predelay/1000.0) time.sleep(sysvals.predelay/1000.0)
sysvals.fsetVal('WAIT END', 'trace_marker') sysvals.fsetVal('WAIT END', 'trace_marker')
# initiate suspend or command # initiate suspend or command
tdata = {'error': ''}
if sysvals.testcommand != '': if sysvals.testcommand != '':
call(sysvals.testcommand+' 2>&1', shell=True); res = call(sysvals.testcommand+' 2>&1', shell=True);
if res != 0:
tdata['error'] = 'cmd returned %d' % res
else: else:
mode = sysvals.suspendmode mode = sysvals.suspendmode
if sysvals.memmode and os.path.exists(sysvals.mempowerfile): if sysvals.memmode and os.path.exists(sysvals.mempowerfile):
...@@ -4606,8 +4619,8 @@ def executeSuspend(): ...@@ -4606,8 +4619,8 @@ def executeSuspend():
# execution will pause here # execution will pause here
try: try:
pf.close() pf.close()
except: except Exception as e:
pass tdata['error'] = str(e)
if(sysvals.rtcwake): if(sysvals.rtcwake):
sysvals.rtcWakeAlarmOff() sysvals.rtcWakeAlarmOff()
# postdelay delay # postdelay delay
...@@ -4620,23 +4633,29 @@ def executeSuspend(): ...@@ -4620,23 +4633,29 @@ def executeSuspend():
if(sysvals.usecallgraph or sysvals.usetraceevents): if(sysvals.usecallgraph or sysvals.usetraceevents):
sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
fwdata.append(getFPDT(False)) tdata['fw'] = getFPDT(False)
bat2 = getBattery() if battery else False
if battery and bat1 and bat2:
tdata['bat'] = (bat1, bat2)
testdata.append(tdata)
# stop ftrace # stop ftrace
if(sysvals.usecallgraph or sysvals.usetraceevents): if(sysvals.usecallgraph or sysvals.usetraceevents):
if sysvals.useprocmon: if sysvals.useprocmon:
pm.stop() pm.stop()
sysvals.fsetVal('0', 'tracing_on') sysvals.fsetVal('0', 'tracing_on')
# grab a copy of the dmesg output
print('CAPTURING DMESG')
sysvals.getdmesg(testdata)
# grab a copy of the ftrace output
if(sysvals.usecallgraph or sysvals.usetraceevents):
print('CAPTURING TRACE') print('CAPTURING TRACE')
op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata) op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata)
fp = open(tp+'trace', 'r') fp = open(tp+'trace', 'r')
for line in fp: for line in fp:
op.write(line) op.write(line)
op.close() op.close()
sysvals.fsetVal('', 'trace') sysvals.fsetVal('', 'trace')
devProps() devProps()
# grab a copy of the dmesg output
print('CAPTURING DMESG')
sysvals.getdmesg(fwdata)
def readFile(file): def readFile(file):
if os.path.islink(file): if os.path.islink(file):
...@@ -4766,7 +4785,7 @@ def devProps(data=0): ...@@ -4766,7 +4785,7 @@ def devProps(data=0):
alreadystamped = True alreadystamped = True
continue continue
# determine the trace data type (required for further parsing) # determine the trace data type (required for further parsing)
m = re.match(sysvals.tracertypefmt, line) m = re.match(tp.tracertypefmt, line)
if(m): if(m):
tp.setTracerType(m.group('t')) tp.setTracerType(m.group('t'))
continue continue
...@@ -4994,8 +5013,9 @@ def dmidecode(mempath, fatal=False): ...@@ -4994,8 +5013,9 @@ def dmidecode(mempath, fatal=False):
return out return out
def getBattery(): def getBattery():
p = '/sys/class/power_supply' p, charge, bat = '/sys/class/power_supply', 0, {}
bat = dict() if not os.path.exists(p):
return False
for d in os.listdir(p): for d in os.listdir(p):
type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower() type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower()
if type != 'battery': if type != 'battery':
...@@ -5003,15 +5023,42 @@ def getBattery(): ...@@ -5003,15 +5023,42 @@ def getBattery():
for v in ['status', 'energy_now', 'capacity_now']: for v in ['status', 'energy_now', 'capacity_now']:
bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower() bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower()
break break
ac = True if 'status' not in bat:
if 'status' in bat and 'discharging' in bat['status']: return False
ac = False ac = False if 'discharging' in bat['status'] else True
charge = 0
for v in ['energy_now', 'capacity_now']: for v in ['energy_now', 'capacity_now']:
if v in bat and bat[v]: if v in bat and bat[v]:
charge = int(bat[v]) charge = int(bat[v])
return (ac, charge) return (ac, charge)
def displayControl(cmd):
xset, ret = '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)
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)
curr = displayControl('stat')
sysvals.vprint('Display Switched: %s -> %s' % (b4, curr))
if curr != cmd:
sysvals.vprint('WARNING: Display failed to change to %s' % cmd)
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>.*)', 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 # Function: getFPDT
# Description: # Description:
# Read the acpi bios tables and pull out FPDT, the firmware data # Read the acpi bios tables and pull out FPDT, the firmware data
...@@ -5149,7 +5196,7 @@ def getFPDT(output): ...@@ -5149,7 +5196,7 @@ def getFPDT(output):
# Output: # Output:
# True if the test will work, False if not # True if the test will work, False if not
def statusCheck(probecheck=False): def statusCheck(probecheck=False):
status = True status = ''
print('Checking this system (%s)...' % platform.node()) print('Checking this system (%s)...' % platform.node())
...@@ -5160,7 +5207,7 @@ def statusCheck(probecheck=False): ...@@ -5160,7 +5207,7 @@ def statusCheck(probecheck=False):
print(' have root access: %s' % res) print(' have root access: %s' % res)
if(res != 'YES'): if(res != 'YES'):
print(' Try running this script with sudo') print(' Try running this script with sudo')
return False return 'missing root access'
# check sysfs is mounted # check sysfs is mounted
res = sysvals.colorText('NO (No features of this tool will work!)') res = sysvals.colorText('NO (No features of this tool will work!)')
...@@ -5168,7 +5215,7 @@ def statusCheck(probecheck=False): ...@@ -5168,7 +5215,7 @@ def statusCheck(probecheck=False):
res = 'YES' res = 'YES'
print(' is sysfs mounted: %s' % res) print(' is sysfs mounted: %s' % res)
if(res != 'YES'): if(res != 'YES'):
return False return 'sysfs is missing'
# check target mode is a valid mode # check target mode is a valid mode
if sysvals.suspendmode != 'command': if sysvals.suspendmode != 'command':
...@@ -5177,7 +5224,7 @@ def statusCheck(probecheck=False): ...@@ -5177,7 +5224,7 @@ def statusCheck(probecheck=False):
if(sysvals.suspendmode in modes): if(sysvals.suspendmode in modes):
res = 'YES' res = 'YES'
else: else:
status = False status = '%s mode is not supported' % sysvals.suspendmode
print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
if(res == 'NO'): if(res == 'NO'):
print(' valid power modes are: %s' % modes) print(' valid power modes are: %s' % modes)
...@@ -5189,7 +5236,7 @@ def statusCheck(probecheck=False): ...@@ -5189,7 +5236,7 @@ def statusCheck(probecheck=False):
if(ftgood): if(ftgood):
res = 'YES' res = 'YES'
elif(sysvals.usecallgraph): elif(sysvals.usecallgraph):
status = False status = 'ftrace is not properly supported'
print(' is ftrace supported: %s' % res) print(' is ftrace supported: %s' % res)
# check if kprobes are available # check if kprobes are available
...@@ -5217,7 +5264,7 @@ def statusCheck(probecheck=False): ...@@ -5217,7 +5264,7 @@ def statusCheck(probecheck=False):
if(sysvals.rtcpath != ''): if(sysvals.rtcpath != ''):
res = 'YES' res = 'YES'
elif(sysvals.rtcwake): elif(sysvals.rtcwake):
status = False status = 'rtcwake is not properly supported'
print(' is rtcwake supported: %s' % res) print(' is rtcwake supported: %s' % res)
if not probecheck: if not probecheck:
...@@ -5245,7 +5292,7 @@ def doError(msg, help=False): ...@@ -5245,7 +5292,7 @@ def doError(msg, help=False):
printHelp() printHelp()
print('ERROR: %s\n') % msg print('ERROR: %s\n') % msg
sysvals.outputResult({'error':msg}) sysvals.outputResult({'error':msg})
sys.exit() sys.exit(1)
# Function: getArgInt # Function: getArgInt
# Description: # Description:
...@@ -5301,11 +5348,16 @@ def processData(live=False): ...@@ -5301,11 +5348,16 @@ def processData(live=False):
appendIncompleteTraceLog(testruns) appendIncompleteTraceLog(testruns)
sysvals.vprint('Command:\n %s' % sysvals.cmdline) sysvals.vprint('Command:\n %s' % sysvals.cmdline)
for data in testruns: for data in testruns:
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)
data.printDetails() data.printDetails()
if sysvals.cgdump: if sysvals.cgdump:
for data in testruns: for data in testruns:
data.debugPrint() data.debugPrint()
sys.exit() sys.exit(0)
if len(testruns) < 1: if len(testruns) < 1:
return (testruns, {'error': 'timeline generation failed'}) return (testruns, {'error': 'timeline generation failed'})
sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
...@@ -5335,6 +5387,7 @@ def rerunTest(): ...@@ -5335,6 +5387,7 @@ def rerunTest():
elif not os.access(sysvals.htmlfile, os.W_OK): elif not os.access(sysvals.htmlfile, os.W_OK):
doError('missing permission to write to %s' % sysvals.htmlfile) doError('missing permission to write to %s' % sysvals.htmlfile)
testruns, stamp = processData(False) testruns, stamp = processData(False)
sysvals.logmsg = ''
return stamp return stamp
# Function: runTest # Function: runTest
...@@ -5349,13 +5402,16 @@ def runTest(n=0): ...@@ -5349,13 +5402,16 @@ def runTest(n=0):
executeSuspend() executeSuspend()
sysvals.cleanupFtrace() sysvals.cleanupFtrace()
if sysvals.skiphtml: if sysvals.skiphtml:
sysvals.sudouser(sysvals.testdir) sysvals.sudoUserchown(sysvals.testdir)
return return
testruns, stamp = processData(True) testruns, stamp = processData(True)
for data in testruns: for data in testruns:
del data del data
sysvals.sudouser(sysvals.testdir) sysvals.sudoUserchown(sysvals.testdir)
sysvals.outputResult(stamp, n) sysvals.outputResult(stamp, n)
if 'error' in stamp:
return 2
return 0
def find_in_html(html, start, end, firstonly=True): def find_in_html(html, start, end, firstonly=True):
n, out = 0, [] n, out = 0, []
...@@ -5380,14 +5436,86 @@ def find_in_html(html, start, end, firstonly=True): ...@@ -5380,14 +5436,86 @@ def find_in_html(html, start, end, firstonly=True):
return '' return ''
return out return out
def data_from_html(file, outpath, devlist=False):
html = open(file, 'r').read()
suspend = find_in_html(html, 'Kernel Suspend', 'ms')
resume = find_in_html(html, 'Kernel Resume', 'ms')
line = find_in_html(html, '<div class="stamp">', '</div>')
stmp = line.split()
if not suspend or not resume or len(stmp) != 8:
return False
try:
dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
except:
return 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)
if m:
result = 'fail in %s' % m.group('p')
else:
result = 'fail'
else:
result = 'pass'
ilist = []
e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '&rarr;</div>', False)
for i in list(set(e)):
ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
low = find_in_html(html, 'freeze time: <b>', ' ms</b>')
if low and '|' in low:
ilist.append('FREEZEx%d' % len(low.split('|')))
devices = dict()
for line in html.split('\n'):
m = re.match(' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line)
if not m or 'thread kth' in line or 'thread sec' in line:
continue
m = re.match('(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title'))
if not m:
continue
name, time, phase = m.group('n'), m.group('t'), m.group('p')
if ' async' in name or ' sync' in name:
name = ' '.join(name.split(' ')[:-1])
d = phase.split('_')[0]
if d not in devices:
devices[d] = dict()
if name not in devices[d]:
devices[d][name] = 0.0
devices[d][name] += float(time)
worst = {'suspend': {'name':'', 'time': 0.0},
'resume': {'name':'', 'time': 0.0}}
for d in devices:
if d not in worst:
worst[d] = dict()
dev = devices[d]
if len(dev.keys()) > 0:
n = sorted(dev, key=dev.get, reverse=True)[0]
worst[d]['name'], worst[d]['time'] = n, dev[n]
data = {
'mode': stmp[2],
'host': stmp[0],
'kernel': stmp[1],
'time': tstr,
'result': result,
'issues': ' '.join(ilist),
'suspend': suspend,
'resume': resume,
'sus_worst': worst['suspend']['name'],
'sus_worsttime': worst['suspend']['time'],
'res_worst': worst['resume']['name'],
'res_worsttime': worst['resume']['time'],
'url': os.path.relpath(file, outpath),
}
if devlist:
data['devlist'] = devices
return data
# Function: runSummary # Function: runSummary
# Description: # Description:
# create a summary of tests in a sub-directory # create a summary of tests in a sub-directory
def runSummary(subdir, local=True, genhtml=False): def runSummary(subdir, local=True, genhtml=False):
inpath = os.path.abspath(subdir) inpath = os.path.abspath(subdir)
outpath = inpath outpath = os.path.abspath('.') if local else inpath
if local:
outpath = os.path.abspath('.')
print('Generating a summary of folder "%s"' % inpath) print('Generating a summary of folder "%s"' % inpath)
if genhtml: if genhtml:
for dirname, dirnames, filenames in os.walk(subdir): for dirname, dirnames, filenames in os.walk(subdir):
...@@ -5409,36 +5537,9 @@ def runSummary(subdir, local=True, genhtml=False): ...@@ -5409,36 +5537,9 @@ def runSummary(subdir, local=True, genhtml=False):
for filename in filenames: for filename in filenames:
if(not re.match('.*.html', filename)): if(not re.match('.*.html', filename)):
continue continue
file = os.path.join(dirname, filename) data = data_from_html(os.path.join(dirname, filename), outpath)
html = open(file, 'r').read() if(not data):
suspend = find_in_html(html, 'Kernel Suspend', 'ms')
resume = find_in_html(html, 'Kernel Resume', 'ms')
line = find_in_html(html, '<div class="stamp">', '</div>')
stmp = line.split()
if not suspend or not resume or len(stmp) != 8:
continue continue
try:
dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
except:
continue
tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
result = 'fail' if error else 'pass'
ilist = []
e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '&rarr;</div>', False)
for i in list(set(e)):
ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
data = {
'mode': stmp[2],
'host': stmp[0],
'kernel': stmp[1],
'time': tstr,
'result': result,
'issues': ','.join(ilist),
'suspend': suspend,
'resume': resume,
'url': os.path.relpath(file, outpath),
}
testruns.append(data) testruns.append(data)
outfile = os.path.join(outpath, 'summary.html') outfile = os.path.join(outpath, 'summary.html')
print('Summary file: %s' % outfile) print('Summary file: %s' % outfile)
...@@ -5499,13 +5600,10 @@ def configFromFile(file): ...@@ -5499,13 +5600,10 @@ def configFromFile(file):
else: else:
doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True) doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)
elif(option == 'display'): elif(option == 'display'):
if value in switchvalues: disopt = ['on', 'off', 'standby', 'suspend']
if value in switchoff: if value not in disopt:
sysvals.display = -1 doError('invalid value --> (%s: %s), use %s' % (option, value, disopt), True)
else: sysvals.display = value
sysvals.display = 1
else:
doError('invalid value --> (%s: %s), use "on/off"' % (option, value), True)
elif(option == 'gzip'): elif(option == 'gzip'):
sysvals.gzip = checkArgBool(option, value) sysvals.gzip = checkArgBool(option, value)
elif(option == 'cgfilter'): elif(option == 'cgfilter'):
...@@ -5521,9 +5619,9 @@ def configFromFile(file): ...@@ -5521,9 +5619,9 @@ def configFromFile(file):
sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False) sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)
elif(option == 'cgphase'): elif(option == 'cgphase'):
d = Data(0) d = Data(0)
if value not in d.phases: if value not in d.sortedPhases():
doError('invalid phase --> (%s: %s), valid phases are %s'\ doError('invalid phase --> (%s: %s), valid phases are %s'\
% (option, value, d.phases), True) % (option, value, d.sortedPhases()), True)
sysvals.cgphase = value sysvals.cgphase = value
elif(option == 'fadd'): elif(option == 'fadd'):
file = sysvals.configFile(value) file = sysvals.configFile(value)
...@@ -5697,7 +5795,7 @@ def printHelp(): ...@@ -5697,7 +5795,7 @@ def printHelp():
print(' [testprep]') print(' [testprep]')
print(' -sync Sync the filesystems before starting the test') print(' -sync Sync the filesystems before starting the test')
print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test') print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test')
print(' -display on/off Turn the display on or off for the test') print(' -display m Change the display mode to m for the test (on/off/standby/suspend)')
print(' [advanced]') print(' [advanced]')
print(' -gzip Gzip the trace and dmesg logs to save space') print(' -gzip Gzip the trace and dmesg logs to save space')
print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"') print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"')
...@@ -5729,6 +5827,7 @@ def printHelp(): ...@@ -5729,6 +5827,7 @@ def printHelp():
print(' -status Test to see if the system is enabled to run this tool') print(' -status Test to see if the system is enabled to run this tool')
print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
print(' -battery Print out battery info (if available)') print(' -battery Print out battery info (if available)')
print(' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)')
print(' -sysinfo Print out system info extracted from BIOS') print(' -sysinfo Print out system info extracted from BIOS')
print(' -devinfo Print out the pm settings of all devices which support runtime suspend') print(' -devinfo Print out the pm settings of all devices which support runtime suspend')
print(' -flist Print the list of functions currently being captured in ftrace') print(' -flist Print the list of functions currently being captured in ftrace')
...@@ -5745,7 +5844,9 @@ def printHelp(): ...@@ -5745,7 +5844,9 @@ def printHelp():
if __name__ == '__main__': if __name__ == '__main__':
genhtml = False genhtml = False
cmd = '' cmd = ''
simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status', '-battery'] simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall',
'-devinfo', '-status', '-battery', '-xon', '-xoff', '-xstandby',
'-xsuspend', '-xinit', '-xreset', '-xstat']
if '-f' in sys.argv: if '-f' in sys.argv:
sysvals.cgskip = sysvals.configFile('cgskip.txt') sysvals.cgskip = sysvals.configFile('cgskip.txt')
# loop through the command line arguments # loop through the command line arguments
...@@ -5763,10 +5864,10 @@ if __name__ == '__main__': ...@@ -5763,10 +5864,10 @@ if __name__ == '__main__':
cmd = arg[1:] cmd = arg[1:]
elif(arg == '-h'): elif(arg == '-h'):
printHelp() printHelp()
sys.exit() sys.exit(0)
elif(arg == '-v'): elif(arg == '-v'):
print("Version %s" % sysvals.version) print("Version %s" % sysvals.version)
sys.exit() sys.exit(0)
elif(arg == '-x2'): elif(arg == '-x2'):
sysvals.execcount = 2 sysvals.execcount = 2
elif(arg == '-x2delay'): elif(arg == '-x2delay'):
...@@ -5785,6 +5886,10 @@ if __name__ == '__main__': ...@@ -5785,6 +5886,10 @@ if __name__ == '__main__':
genhtml = True genhtml = True
elif(arg == '-addlogs'): elif(arg == '-addlogs'):
sysvals.dmesglog = sysvals.ftracelog = True sysvals.dmesglog = sysvals.ftracelog = True
elif(arg == '-addlogdmesg'):
sysvals.dmesglog = True
elif(arg == '-addlogftrace'):
sysvals.ftracelog = True
elif(arg == '-verbose'): elif(arg == '-verbose'):
sysvals.verbose = True sysvals.verbose = True
elif(arg == '-proc'): elif(arg == '-proc'):
...@@ -5811,14 +5916,11 @@ if __name__ == '__main__': ...@@ -5811,14 +5916,11 @@ if __name__ == '__main__':
try: try:
val = args.next() val = args.next()
except: except:
doError('-display requires "on" or "off"', True) doError('-display requires an mode value', True)
if val.lower() in switchvalues: disopt = ['on', 'off', 'standby', 'suspend']
if val.lower() in switchoff: if val.lower() not in disopt:
sysvals.display = -1 doError('valid display mode values are %s' % disopt, True)
else: sysvals.display = val.lower()
sysvals.display = 1
else:
doError('invalid option: %s, use "on/off"' % val, True)
elif(arg == '-maxdepth'): elif(arg == '-maxdepth'):
sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000) sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
elif(arg == '-rtcwake'): elif(arg == '-rtcwake'):
...@@ -5847,9 +5949,9 @@ if __name__ == '__main__': ...@@ -5847,9 +5949,9 @@ if __name__ == '__main__':
except: except:
doError('No phase name supplied', True) doError('No phase name supplied', True)
d = Data(0) d = Data(0)
if val not in d.phases: if val not in d.phasedef:
doError('invalid phase --> (%s: %s), valid phases are %s'\ doError('invalid phase --> (%s: %s), valid phases are %s'\
% (arg, val, d.phases), True) % (arg, val, d.phasedef.keys()), True)
sysvals.cgphase = val sysvals.cgphase = val
elif(arg == '-cgfilter'): elif(arg == '-cgfilter'):
try: try:
...@@ -5951,6 +6053,7 @@ if __name__ == '__main__': ...@@ -5951,6 +6053,7 @@ if __name__ == '__main__':
except: except:
doError('No result file supplied', True) doError('No result file supplied', True)
sysvals.result = val sysvals.result = val
sysvals.signalHandlerInit()
else: else:
doError('Invalid argument: '+arg, True) doError('Invalid argument: '+arg, True)
...@@ -5975,12 +6078,20 @@ if __name__ == '__main__': ...@@ -5975,12 +6078,20 @@ if __name__ == '__main__':
# just run a utility command and exit # just run a utility command and exit
if(cmd != ''): if(cmd != ''):
ret = 0
if(cmd == 'status'): if(cmd == 'status'):
statusCheck(True) if not statusCheck(True):
ret = 1
elif(cmd == 'fpdt'): elif(cmd == 'fpdt'):
getFPDT(True) if not getFPDT(True):
ret = 1
elif(cmd == 'battery'): elif(cmd == 'battery'):
print 'AC Connect: %s\nCharge: %d' % getBattery() out = getBattery()
if out:
print 'AC Connect : %s\nBattery Charge: %d' % out
else:
print 'no battery found'
ret = 1
elif(cmd == 'sysinfo'): elif(cmd == 'sysinfo'):
sysvals.printSystemInfo(True) sysvals.printSystemInfo(True)
elif(cmd == 'devinfo'): elif(cmd == 'devinfo'):
...@@ -5993,17 +6104,23 @@ if __name__ == '__main__': ...@@ -5993,17 +6104,23 @@ if __name__ == '__main__':
sysvals.getFtraceFilterFunctions(False) sysvals.getFtraceFilterFunctions(False)
elif(cmd == 'summary'): elif(cmd == 'summary'):
runSummary(sysvals.outdir, True, genhtml) runSummary(sysvals.outdir, True, genhtml)
sys.exit() elif(cmd in ['xon', 'xoff', 'xstandby', 'xsuspend', 'xinit', 'xreset']):
sysvals.verbose = True
ret = displayControl(cmd[1:])
elif(cmd == 'xstat'):
print 'Display Status: %s' % displayControl('stat').upper()
sys.exit(ret)
# if instructed, re-analyze existing data files # if instructed, re-analyze existing data files
if(sysvals.notestrun): if(sysvals.notestrun):
stamp = rerunTest() stamp = rerunTest()
sysvals.outputResult(stamp) sysvals.outputResult(stamp)
sys.exit() sys.exit(0)
# verify that we can run a test # verify that we can run a test
if(not statusCheck()): error = statusCheck()
doError('Check FAILED, aborting the test run!') if(error):
doError(error)
# extract mem modes and convert # extract mem modes and convert
mode = sysvals.suspendmode mode = sysvals.suspendmode
...@@ -6025,8 +6142,8 @@ if __name__ == '__main__': ...@@ -6025,8 +6142,8 @@ if __name__ == '__main__':
setRuntimeSuspend(True) setRuntimeSuspend(True)
if sysvals.display: if sysvals.display:
call('xset -d :0.0 dpms 0 0 0', shell=True) displayControl('init')
call('xset -d :0.0 s off', shell=True) ret = 0
if sysvals.multitest['run']: if sysvals.multitest['run']:
# run multiple tests in a separate subdirectory # run multiple tests in a separate subdirectory
if not sysvals.outdir: if not sysvals.outdir:
...@@ -6041,17 +6158,18 @@ if __name__ == '__main__': ...@@ -6041,17 +6158,18 @@ if __name__ == '__main__':
print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count'])) print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count']))
fmt = 'suspend-%y%m%d-%H%M%S' fmt = 'suspend-%y%m%d-%H%M%S'
sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
runTest(i+1) ret = runTest(i+1)
print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count'])) print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
sysvals.logmsg = '' sysvals.logmsg = ''
if not sysvals.skiphtml: if not sysvals.skiphtml:
runSummary(sysvals.outdir, False, False) runSummary(sysvals.outdir, False, False)
sysvals.sudouser(sysvals.outdir) sysvals.sudoUserchown(sysvals.outdir)
else: else:
if sysvals.outdir: if sysvals.outdir:
sysvals.testdir = sysvals.outdir sysvals.testdir = sysvals.outdir
# run the test in the current directory # run the test in the current directory
runTest() ret = runTest()
if sysvals.display: if sysvals.display:
call('xset -d :0.0 s reset', shell=True) displayControl('reset')
setRuntimeSuspend(False) setRuntimeSuspend(False)
sys.exit(ret)
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment