Commit 700abc90 authored by Todd E Brandt's avatar Todd E Brandt Committed by Rafael J. Wysocki

pm-graph: AnalyzeSuspend v5.0

- add -cgskip option to reduce callgraph output size
- add -cgfilter option to focus on a list of devices
- add -result option for exporting batch test results
- removed all phoronix hooks, use -result to enable batch testing
- change -usbtopo to -devinfo, now prints all devices
- add -gzip option to read/write logs in gz format
- add -bufsize option to manually control ftrace buffer size
- add -sync option to run filesystem sync prior to test
- add -display option to enable/disable the display prior to test
- add -rs option to enable/disable runtime suspend on all devices for test
- add installed config files to search path
- add kernel error/warning links into the timeline
- fix callgraph trace to better handle interrupts
- include command string and kernel params in timeline output header
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 d83a76a8
...@@ -52,9 +52,32 @@ disable rtcwake and require a user keypress to resume. ...@@ -52,9 +52,32 @@ disable rtcwake and require a user keypress to resume.
\fB-addlogs\fR \fB-addlogs\fR
Add the dmesg and ftrace logs to the html output. They will be viewable by Add the dmesg and ftrace logs to the html output. They will be viewable by
clicking buttons in the timeline. clicking buttons in the timeline.
.TP
\fB-result \fIfile\fR
Export a results table to a text file for parsing.
.TP
\fB-sync\fR
Sync the filesystems before starting the test. This reduces the size of
the sys_sync call which happens in the suspend_prepare phase.
.TP
\fB-rs \fIenable/disable\fR
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
after the test is complete.
.TP
\fB-display \fIon/off\fR
Turn the display on or off for the test using the xset command. This helps
maintain the consistecy of test data for better comparison.
.TP
\fB-skiphtml\fR
Run the test and capture the trace logs, but skip the timeline generation.
.SS "advanced" .SS "advanced"
.TP .TP
\fB-gzip\fR
Gzip the trace and dmesg logs to save space. The tool can also read in gzipped
logs for processing.
.TP
\fB-cmd \fIstr\fR \fB-cmd \fIstr\fR
Run the timeline over a custom suspend command, e.g. pm-suspend. By default Run the timeline over a custom suspend command, e.g. pm-suspend. By default
the tool forces suspend via /sys/power/state so this allows testing over the tool forces suspend via /sys/power/state so this allows testing over
...@@ -114,6 +137,18 @@ This reduces the html file size as there can be many tiny callgraphs ...@@ -114,6 +137,18 @@ This reduces the html file size as there can be many tiny callgraphs
which are barely visible in the timeline. which are barely visible in the timeline.
The value is a float: e.g. 0.001 represents 1 us. The value is a float: e.g. 0.001 represents 1 us.
.TP .TP
\fB-cgfilter \fI"func1,func2,..."\fR
Reduce callgraph output in the timeline by limiting it to a list of calls. The
argument can be a single function name or a comma delimited list.
(default: none)
.TP
\fB-cgskip \fIfile\fR
Reduce callgraph timeline size by skipping over uninteresting functions
in the trace, e.g. printk or console_unlock. The functions listed
in this file will show up as empty leaves in the callgraph with only the start/end
times displayed. cgskip.txt is used automatically if found in the path, so
use "off" to disable completely (default: cgskip.txt)
.TP
\fB-cgphase \fIp\fR \fB-cgphase \fIp\fR
Only show callgraph data for phase \fIp\fR (e.g. suspend_late). Only show callgraph data for phase \fIp\fR (e.g. suspend_late).
.TP .TP
...@@ -122,6 +157,9 @@ In an x2 run, only show callgraph data for test \fIn\fR (e.g. 0 or 1). ...@@ -122,6 +157,9 @@ In an x2 run, only show callgraph data for test \fIn\fR (e.g. 0 or 1).
.TP .TP
\fB-timeprec \fIn\fR \fB-timeprec \fIn\fR
Number of significant digits in timestamps (0:S, [3:ms], 6:us). Number of significant digits in timestamps (0:S, [3:ms], 6:us).
.TP
\fB-bufsize \fIN\fR
Set trace buffer size to N kilo-bytes (default: all of free memory up to 3GB)
.SH COMMANDS .SH COMMANDS
.TP .TP
...@@ -144,11 +182,8 @@ Print out the contents of the ACPI Firmware Performance Data Table. ...@@ -144,11 +182,8 @@ Print out the contents of the ACPI Firmware Performance Data Table.
\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
\fB-usbtopo\fR \fB-devinfo\fR
Print out the current USB topology with power info. Print out the pm settings of all devices which support runtime suspend.
.TP
\fB-usbauto\fR
Enable autosuspend for all connected USB devices.
.TP .TP
\fB-flist\fR \fB-flist\fR
Print the list of ftrace functions currently being captured. Functions Print the list of ftrace functions currently being captured. Functions
...@@ -198,7 +233,7 @@ Execute a mem suspend with a 15 second wakeup. Include the logs in the html. ...@@ -198,7 +233,7 @@ Execute a mem suspend with a 15 second wakeup. Include the logs in the html.
.PP .PP
Execute a standby with a 15 second wakeup. Change the output folder name. Execute a standby with a 15 second wakeup. Change the output folder name.
.IP .IP
\f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{hostname}-{date}-{time}"\fR \f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{host}-{date}-{time}"\fR
.PP .PP
Execute a freeze with no wakeup (require keypress). Change output folder name. Execute a freeze with no wakeup (require keypress). Change output folder name.
.IP .IP
......
...@@ -19,7 +19,7 @@ ...@@ -19,7 +19,7 @@
# Home Page # Home Page
# https://01.org/suspendresume # https://01.org/suspendresume
# Source repo # Source repo
# https://github.com/01org/pm-graph # git@github.com:01org/pm-graph
# #
# Description: # Description:
# This tool is designed to assist kernel and OS developers in optimizing # This tool is designed to assist kernel and OS developers in optimizing
...@@ -57,6 +57,7 @@ import platform ...@@ -57,6 +57,7 @@ import platform
from datetime import datetime from datetime import datetime
import struct import struct
import ConfigParser import ConfigParser
import gzip
from threading import Thread from threading import Thread
from subprocess import call, Popen, PIPE from subprocess import call, Popen, PIPE
...@@ -68,8 +69,12 @@ from subprocess import call, Popen, PIPE ...@@ -68,8 +69,12 @@ from subprocess import call, Popen, PIPE
# store system values and test parameters # store system values and test parameters
class SystemValues: class SystemValues:
title = 'SleepGraph' title = 'SleepGraph'
version = '4.7' version = '5.0'
ansi = False ansi = False
rs = 0
display = 0
gzip = False
sync = False
verbose = False verbose = False
testlog = True testlog = True
dmesglog = False dmesglog = False
...@@ -78,14 +83,19 @@ class SystemValues: ...@@ -78,14 +83,19 @@ class SystemValues:
mincglen = 0.0 mincglen = 0.0
cgphase = '' cgphase = ''
cgtest = -1 cgtest = -1
cgskip = ''
multitest = {'run': False, 'count': 0, 'delay': 0}
max_graph_depth = 0 max_graph_depth = 0
callloopmaxgap = 0.0001 callloopmaxgap = 0.0001
callloopmaxlen = 0.005 callloopmaxlen = 0.005
bufsize = 0
cpucount = 0 cpucount = 0
memtotal = 204800 memtotal = 204800
memfree = 204800
srgap = 0 srgap = 0
cgexp = False cgexp = False
testdir = '' testdir = ''
outdir = ''
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/'
...@@ -109,22 +119,24 @@ class SystemValues: ...@@ -109,22 +119,24 @@ class SystemValues:
dmesgfile = '' dmesgfile = ''
ftracefile = '' ftracefile = ''
htmlfile = 'output.html' htmlfile = 'output.html'
embedded = False result = ''
rtcwake = True rtcwake = True
rtcwaketime = 15 rtcwaketime = 15
rtcpath = '' rtcpath = ''
devicefilter = [] devicefilter = []
cgfilter = []
stamp = 0 stamp = 0
execcount = 1 execcount = 1
x2delay = 0 x2delay = 0
skiphtml = False
usecallgraph = False usecallgraph = False
usetraceevents = False usetraceevents = False
usetraceeventsonly = False
usetracemarkers = True usetracemarkers = True
usekprobes = True usekprobes = True
usedevsrc = False usedevsrc = False
useprocmon = False useprocmon = False
notestrun = False notestrun = False
cgdump = False
mixedphaseheight = True mixedphaseheight = True
devprops = dict() devprops = dict()
predelay = 0 predelay = 0
...@@ -134,24 +146,33 @@ class SystemValues: ...@@ -134,24 +146,33 @@ class SystemValues:
tracertypefmt = '# tracer: (?P<t>.*)' tracertypefmt = '# tracer: (?P<t>.*)'
firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
tracefuncs = { tracefuncs = {
'sys_sync': dict(), 'sys_sync': {},
'pm_prepare_console': dict(), '__pm_notifier_call_chain': {},
'pm_notifier_call_chain': dict(), 'pm_prepare_console': {},
'freeze_processes': dict(), 'pm_notifier_call_chain': {},
'freeze_kernel_threads': dict(), 'freeze_processes': {},
'pm_restrict_gfp_mask': dict(), 'freeze_kernel_threads': {},
'acpi_suspend_begin': dict(), 'pm_restrict_gfp_mask': {},
'suspend_console': dict(), 'acpi_suspend_begin': {},
'acpi_pm_prepare': dict(), 'acpi_hibernation_begin': {},
'syscore_suspend': dict(), 'acpi_hibernation_enter': {},
'arch_enable_nonboot_cpus_end': dict(), 'acpi_hibernation_leave': {},
'syscore_resume': dict(), 'acpi_pm_freeze': {},
'acpi_pm_finish': dict(), 'acpi_pm_thaw': {},
'resume_console': dict(), 'hibernate_preallocate_memory': {},
'acpi_pm_end': dict(), 'create_basic_memory_bitmaps': {},
'pm_restore_gfp_mask': dict(), 'swsusp_write': {},
'thaw_processes': dict(), 'suspend_console': {},
'pm_restore_console': dict(), 'acpi_pm_prepare': {},
'syscore_suspend': {},
'arch_enable_nonboot_cpus_end': {},
'syscore_resume': {},
'acpi_pm_finish': {},
'resume_console': {},
'acpi_pm_end': {},
'pm_restore_gfp_mask': {},
'thaw_processes': {},
'pm_restore_console': {},
'CPU_OFF': { 'CPU_OFF': {
'func':'_cpu_down', 'func':'_cpu_down',
'args_x86_64': {'cpu':'%di:s32'}, 'args_x86_64': {'cpu':'%di:s32'},
...@@ -173,56 +194,54 @@ class SystemValues: ...@@ -173,56 +194,54 @@ class SystemValues:
'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
'acpi_os_stall': {'ub': 1}, 'acpi_os_stall': {'ub': 1},
# ACPI # ACPI
'acpi_resume_power_resources': dict(), 'acpi_resume_power_resources': {},
'acpi_ps_parse_aml': dict(), 'acpi_ps_parse_aml': {},
# filesystem # filesystem
'ext4_sync_fs': dict(), 'ext4_sync_fs': {},
# 80211 # 80211
'iwlagn_mac_start': dict(), 'iwlagn_mac_start': {},
'iwlagn_alloc_bcast_station': dict(), 'iwlagn_alloc_bcast_station': {},
'iwl_trans_pcie_start_hw': dict(), 'iwl_trans_pcie_start_hw': {},
'iwl_trans_pcie_start_fw': dict(), 'iwl_trans_pcie_start_fw': {},
'iwl_run_init_ucode': dict(), 'iwl_run_init_ucode': {},
'iwl_load_ucode_wait_alive': dict(), 'iwl_load_ucode_wait_alive': {},
'iwl_alive_start': dict(), 'iwl_alive_start': {},
'iwlagn_mac_stop': dict(), 'iwlagn_mac_stop': {},
'iwlagn_mac_suspend': dict(), 'iwlagn_mac_suspend': {},
'iwlagn_mac_resume': dict(), 'iwlagn_mac_resume': {},
'iwlagn_mac_add_interface': dict(), 'iwlagn_mac_add_interface': {},
'iwlagn_mac_remove_interface': dict(), 'iwlagn_mac_remove_interface': {},
'iwlagn_mac_change_interface': dict(), 'iwlagn_mac_change_interface': {},
'iwlagn_mac_config': dict(), 'iwlagn_mac_config': {},
'iwlagn_configure_filter': dict(), 'iwlagn_configure_filter': {},
'iwlagn_mac_hw_scan': dict(), 'iwlagn_mac_hw_scan': {},
'iwlagn_bss_info_changed': dict(), 'iwlagn_bss_info_changed': {},
'iwlagn_mac_channel_switch': dict(), 'iwlagn_mac_channel_switch': {},
'iwlagn_mac_flush': dict(), 'iwlagn_mac_flush': {},
# ATA # ATA
'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} }, 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
# i915 # i915
'i915_gem_resume': dict(), 'i915_gem_resume': {},
'i915_restore_state': dict(), 'i915_restore_state': {},
'intel_opregion_setup': dict(), 'intel_opregion_setup': {},
'g4x_pre_enable_dp': dict(), 'g4x_pre_enable_dp': {},
'vlv_pre_enable_dp': dict(), 'vlv_pre_enable_dp': {},
'chv_pre_enable_dp': dict(), 'chv_pre_enable_dp': {},
'g4x_enable_dp': dict(), 'g4x_enable_dp': {},
'vlv_enable_dp': dict(), 'vlv_enable_dp': {},
'intel_hpd_init': dict(), 'intel_hpd_init': {},
'intel_opregion_register': dict(), 'intel_opregion_register': {},
'intel_dp_detect': dict(), 'intel_dp_detect': {},
'intel_hdmi_detect': dict(), 'intel_hdmi_detect': {},
'intel_opregion_init': dict(), 'intel_opregion_init': {},
'intel_fbdev_set_suspend': dict(), 'intel_fbdev_set_suspend': {},
} }
cgblacklist = []
kprobes = dict() kprobes = dict()
timeformat = '%.3f' timeformat = '%.3f'
cmdline = '%s %s' % \
(os.path.basename(sys.argv[0]), string.join(sys.argv[1:], ' '))
def __init__(self): def __init__(self):
# if this is a phoronix test run, set some default options
if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
self.embedded = True
self.dmesglog = self.ftracelog = True
self.htmlfile = os.environ['LOG_FILE']
self.archargs = 'args_'+platform.machine() self.archargs = 'args_'+platform.machine()
self.hostname = platform.node() self.hostname = platform.node()
if(self.hostname == ''): if(self.hostname == ''):
...@@ -237,18 +256,36 @@ class SystemValues: ...@@ -237,18 +256,36 @@ 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')
def vprint(self, msg):
self.logmsg += msg+'\n'
if(self.verbose):
print(msg)
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
if fatal: if fatal:
doError('This command requires sysfs mount and root access') msg = 'This command requires sysfs mount and root access'
print('ERROR: %s\n') % msg
self.outputResult({'error':msg})
sys.exit()
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':
return True return True
if fatal: if fatal:
doError('This command must be run as root') msg = 'This command must be run as root'
print('ERROR: %s\n') % msg
self.outputResult({'error':msg})
sys.exit()
return False return False
def getExec(self, cmd):
dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
'/usr/local/sbin', '/usr/local/bin']
for path in dirlist:
cmdfull = os.path.join(path, cmd)
if os.path.exists(cmdfull):
return cmdfull
return ''
def setPrecision(self, num): def setPrecision(self, num):
if num < 0 or num > 6: if num < 0 or num > 6:
return return
...@@ -258,15 +295,15 @@ class SystemValues: ...@@ -258,15 +295,15 @@ class SystemValues:
n = datetime.now() n = datetime.now()
args['date'] = n.strftime('%y%m%d') args['date'] = n.strftime('%y%m%d')
args['time'] = n.strftime('%H%M%S') args['time'] = n.strftime('%H%M%S')
args['hostname'] = self.hostname args['hostname'] = args['host'] = self.hostname
return value.format(**args) return value.format(**args)
def setOutputFile(self): def setOutputFile(self):
if self.dmesgfile != '': if self.dmesgfile != '':
m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)
if(m): if(m):
self.htmlfile = m.group('name')+'.html' self.htmlfile = m.group('name')+'.html'
if self.ftracefile != '': if self.ftracefile != '':
m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile) m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
if(m): if(m):
self.htmlfile = m.group('name')+'.html' self.htmlfile = m.group('name')+'.html'
def systemInfo(self, info): def systemInfo(self, info):
...@@ -283,16 +320,19 @@ class SystemValues: ...@@ -283,16 +320,19 @@ class SystemValues:
c = info['processor-version'] c = info['processor-version']
if 'bios-version' in info: if 'bios-version' in info:
b = info['bios-version'] b = info['bios-version']
self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d' % \ self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \
(m, p, c, b, self.cpucount, self.memtotal) (m, p, c, b, self.cpucount, self.memtotal, self.memfree)
def printSystemInfo(self): def printSystemInfo(self, fatal=False):
self.rootCheck(True) self.rootCheck(True)
out = dmidecode(self.mempath, True) out = dmidecode(self.mempath, fatal)
if len(out) < 1:
return
fmt = '%-24s: %s' fmt = '%-24s: %s'
for name in sorted(out): for name in sorted(out):
print fmt % (name, out[name]) print fmt % (name, out[name])
print fmt % ('cpucount', ('%d' % self.cpucount)) print fmt % ('cpucount', ('%d' % self.cpucount))
print fmt % ('memtotal', ('%d kB' % self.memtotal)) print fmt % ('memtotal', ('%d kB' % self.memtotal))
print fmt % ('memfree', ('%d kB' % self.memfree))
def cpuInfo(self): def cpuInfo(self):
self.cpucount = 0 self.cpucount = 0
fp = open('/proc/cpuinfo', 'r') fp = open('/proc/cpuinfo', 'r')
...@@ -305,7 +345,9 @@ class SystemValues: ...@@ -305,7 +345,9 @@ class SystemValues:
m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line) m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
if m: if m:
self.memtotal = int(m.group('sz')) self.memtotal = int(m.group('sz'))
break m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)
if m:
self.memfree = int(m.group('sz'))
fp.close() fp.close()
def initTestOutput(self, name): def initTestOutput(self, name):
self.prefix = self.hostname self.prefix = self.hostname
...@@ -315,39 +357,34 @@ class SystemValues: ...@@ -315,39 +357,34 @@ class SystemValues:
testtime = datetime.now().strftime(fmt) testtime = datetime.now().strftime(fmt)
self.teststamp = \ self.teststamp = \
'# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
if(self.embedded): ext = ''
self.dmesgfile = \ if self.gzip:
'/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt' ext = '.gz'
self.ftracefile = \
'/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
return
self.dmesgfile = \ self.dmesgfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
self.ftracefile = \ self.ftracefile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
self.htmlfile = \ self.htmlfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
if not os.path.isdir(self.testdir): if not os.path.isdir(self.testdir):
os.mkdir(self.testdir) os.mkdir(self.testdir)
def getValueList(self, value):
out = []
for i in value.split(','):
if i.strip():
out.append(i.strip())
return out
def setDeviceFilter(self, value): def setDeviceFilter(self, value):
self.devicefilter = [] self.devicefilter = self.getValueList(value)
if value: def setCallgraphFilter(self, value):
value = value.split(',') self.cgfilter = self.getValueList(value)
for i in value: def setCallgraphBlacklist(self, file):
self.devicefilter.append(i.strip()) self.cgblacklist = self.listFromFile(file)
def rtcWakeAlarmOn(self): def rtcWakeAlarmOn(self):
call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True) call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
outD = open(self.rtcpath+'/date', 'r').read().strip() nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()
outT = open(self.rtcpath+'/time', 'r').read().strip() if nowtime:
mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD) nowtime = int(nowtime)
mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
if(mD and mT):
# get the current time from hardware
utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
dt = datetime(\
int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
nowtime = int(dt.strftime('%s')) + utcoffset
else: else:
# if hardware time fails, use the software time # if hardware time fails, use the software time
nowtime = int(datetime.now().strftime('%s')) nowtime = int(datetime.now().strftime('%s'))
...@@ -369,10 +406,10 @@ class SystemValues: ...@@ -369,10 +406,10 @@ 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): def getdmesg(self, fwdata=[]):
op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata)
# 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
op = open(self.dmesgfile, 'a')
for line in fp: for line in fp:
line = line.replace('\r\n', '') line = line.replace('\r\n', '')
idx = line.find('[') idx = line.find('[')
...@@ -386,11 +423,17 @@ class SystemValues: ...@@ -386,11 +423,17 @@ class SystemValues:
op.write(line) op.write(line)
fp.close() fp.close()
op.close() op.close()
def addFtraceFilterFunctions(self, file): def listFromFile(self, file):
list = []
fp = open(file) fp = open(file)
list = fp.read().split('\n') for i in fp.read().split('\n'):
i = i.strip()
if i and i[0] != '#':
list.append(i)
fp.close() fp.close()
for i in list: return list
def addFtraceFilterFunctions(self, file):
for i in self.listFromFile(file):
if len(i) < 2: if len(i) < 2:
continue continue
self.tracefuncs[i] = dict() self.tracefuncs[i] = dict()
...@@ -399,9 +442,7 @@ class SystemValues: ...@@ -399,9 +442,7 @@ class SystemValues:
if not current: if not current:
call('cat '+self.tpath+'available_filter_functions', shell=True) call('cat '+self.tpath+'available_filter_functions', shell=True)
return return
fp = open(self.tpath+'available_filter_functions') master = self.listFromFile(self.tpath+'available_filter_functions')
master = fp.read().split('\n')
fp.close()
for i in self.tracefuncs: for i in self.tracefuncs:
if 'func' in self.tracefuncs[i]: if 'func' in self.tracefuncs[i]:
i = self.tracefuncs[i]['func'] i = self.tracefuncs[i]['func']
...@@ -410,9 +451,7 @@ class SystemValues: ...@@ -410,9 +451,7 @@ class SystemValues:
else: else:
print self.colorText(i) print self.colorText(i)
def setFtraceFilterFunctions(self, list): def setFtraceFilterFunctions(self, list):
fp = open(self.tpath+'available_filter_functions') master = self.listFromFile(self.tpath+'available_filter_functions')
master = fp.read().split('\n')
fp.close()
flist = '' flist = ''
for i in list: for i in list:
if i not in master: if i not in master:
...@@ -501,6 +540,7 @@ class SystemValues: ...@@ -501,6 +540,7 @@ class SystemValues:
rejects = [] rejects = []
# sort kprobes: trace, ub-dev, custom, dev # sort kprobes: trace, ub-dev, custom, dev
kpl = [[], [], [], []] kpl = [[], [], [], []]
linesout = len(self.kprobes)
for name in sorted(self.kprobes): for name in sorted(self.kprobes):
res = self.colorText('YES', 32) res = self.colorText('YES', 32)
if not self.testKprobe(name, self.kprobes[name]): if not self.testKprobe(name, self.kprobes[name]):
...@@ -528,17 +568,10 @@ class SystemValues: ...@@ -528,17 +568,10 @@ class SystemValues:
for kp in kplist: for kp in kplist:
kprobeevents += self.kprobeText(kp, self.kprobes[kp]) kprobeevents += self.kprobeText(kp, self.kprobes[kp])
self.fsetVal(kprobeevents, 'kprobe_events') self.fsetVal(kprobeevents, 'kprobe_events')
# verify that the kprobes were set as ordered
check = self.fgetVal('kprobe_events')
linesout = len(kprobeevents.split('\n')) - 1
linesack = len(check.split('\n')) - 1
if output: if output:
res = '%d/%d' % (linesack, linesout) check = self.fgetVal('kprobe_events')
if linesack < linesout: linesack = (len(check.split('\n')) - 1) / 2
res = self.colorText(res, 31) print(' kprobe functions enabled: %d/%d' % (linesack, linesout))
else:
res = self.colorText(res, 32)
print(' working kprobe functions enabled: %s' % res)
self.fsetVal('1', 'events/kprobes/enable') self.fsetVal('1', 'events/kprobes/enable')
def testKprobe(self, kname, kprobe): def testKprobe(self, kname, kprobe):
self.fsetVal('0', 'events/kprobes/enable') self.fsetVal('0', 'events/kprobes/enable')
...@@ -555,8 +588,7 @@ class SystemValues: ...@@ -555,8 +588,7 @@ class SystemValues:
if linesack < linesout: if linesack < linesout:
return False return False
return True return True
def fsetVal(self, val, path, mode='w'): def setVal(self, val, file, mode='w'):
file = self.tpath+path
if not os.path.exists(file): if not os.path.exists(file):
return False return False
try: try:
...@@ -567,8 +599,9 @@ class SystemValues: ...@@ -567,8 +599,9 @@ class SystemValues:
except: except:
return False return False
return True return True
def fgetVal(self, path): def fsetVal(self, val, path, mode='w'):
file = self.tpath+path return self.setVal(val, self.tpath+path, mode)
def getVal(self, file):
res = '' res = ''
if not os.path.exists(file): if not os.path.exists(file):
return res return res
...@@ -579,10 +612,13 @@ class SystemValues: ...@@ -579,10 +612,13 @@ class SystemValues:
except: except:
pass pass
return res return res
def fgetVal(self, path):
return self.getVal(self.tpath+path)
def cleanupFtrace(self): def cleanupFtrace(self):
if(self.usecallgraph or self.usetraceevents): if(self.usecallgraph or self.usetraceevents or self.usedevsrc):
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')
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])
...@@ -599,7 +635,8 @@ class SystemValues: ...@@ -599,7 +635,8 @@ class SystemValues:
if name == f: if name == f:
return True return True
return False return False
def initFtrace(self, testing=False): def initFtrace(self):
self.printSystemInfo(False)
print('INITIALIZING FTRACE...') print('INITIALIZING FTRACE...')
# turn trace off # turn trace off
self.fsetVal('0', 'tracing_on') self.fsetVal('0', 'tracing_on')
...@@ -607,17 +644,21 @@ class SystemValues: ...@@ -607,17 +644,21 @@ class SystemValues:
# 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')
# set trace buffer to a huge value # set trace buffer to an appropriate value
if self.usecallgraph or self.usedevsrc: cpus = max(1, self.cpucount)
tgtsize = min(self.memtotal / 2, 2*1024*1024) if self.bufsize > 0:
maxbuf = '%d' % (tgtsize / max(1, self.cpucount)) tgtsize = self.bufsize
if self.cpucount < 1 or not self.fsetVal(maxbuf, 'buffer_size_kb'): elif self.usecallgraph or self.usedevsrc:
self.fsetVal('131072', 'buffer_size_kb') tgtsize = min(self.memfree, 3*1024*1024)
else: else:
self.fsetVal('16384', 'buffer_size_kb') tgtsize = 65536
# go no further if this is just a status check while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
if testing: # if the size failed to set, lower it and keep trying
return tgtsize -= 65536
if tgtsize < 65536:
tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
break
print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)
# initialize the callgraph trace # initialize the callgraph trace
if(self.usecallgraph): if(self.usecallgraph):
# set trace type # set trace type
...@@ -635,7 +676,7 @@ class SystemValues: ...@@ -635,7 +676,7 @@ class SystemValues:
self.fsetVal('graph-time', 'trace_options') self.fsetVal('graph-time', 'trace_options')
self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth') self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
cf = ['dpm_run_callback'] cf = ['dpm_run_callback']
if(self.usetraceeventsonly): if(self.usetraceevents):
cf += ['dpm_prepare', 'dpm_complete'] cf += ['dpm_prepare', 'dpm_complete']
for fn in self.tracefuncs: for fn in self.tracefuncs:
if 'func' in self.tracefuncs[fn]: if 'func' in self.tracefuncs[fn]:
...@@ -688,16 +729,65 @@ class SystemValues: ...@@ -688,16 +729,65 @@ class SystemValues:
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, fwdata=[]):
fp = open(filename, 'w') fp = self.openlog(filename, 'w')
fp.write(self.teststamp+'\n') fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
fp.write(self.sysstamp+'\n')
if(self.suspendmode == 'mem' or self.suspendmode == 'command'): if(self.suspendmode == 'mem' or self.suspendmode == 'command'):
for fw in fwdata: for fw in fwdata:
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]))
return fp
def sudouser(self, dir):
if os.path.exists(dir) and os.getuid() == 0 and \
'SUDO_USER' in os.environ:
cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
call(cmd.format(os.environ['SUDO_USER'], dir), shell=True)
def outputResult(self, testdata, num=0):
if not self.result:
return
n = ''
if num > 0:
n = '%d' % num
fp = open(self.result, 'a')
if 'error' in testdata:
fp.write('result%s: fail\n' % n)
fp.write('error%s: %s\n' % (n, testdata['error']))
else:
fp.write('result%s: pass\n' % n)
for v in ['suspend', 'resume', 'boot', 'lastinit']:
if v in testdata:
fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))
for v in ['fwsuspend', 'fwresume']:
if v in testdata:
fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0))
if 'bugurl' in testdata:
fp.write('url%s: %s\n' % (n, testdata['bugurl']))
fp.close() fp.close()
self.sudouser(self.result)
def configFile(self, file):
dir = os.path.dirname(os.path.realpath(__file__))
if os.path.exists(file):
return file
elif os.path.exists(dir+'/'+file):
return dir+'/'+file
elif os.path.exists(dir+'/config/'+file):
return dir+'/config/'+file
return ''
def openlog(self, filename, mode):
isgz = self.gzip
if mode == 'r':
try:
with gzip.open(filename, mode+'b') as fp:
test = fp.read(64)
isgz = True
except:
isgz = False
if isgz:
return gzip.open(filename, mode+'b')
return open(filename, mode)
sysvals = SystemValues() sysvals = SystemValues()
switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
switchoff = ['disable', 'off', 'false', '0']
suspendmodename = { suspendmodename = {
'freeze': 'Freeze (S0)', 'freeze': 'Freeze (S0)',
'standby': 'Standby (S1)', 'standby': 'Standby (S1)',
...@@ -826,34 +916,65 @@ class Data: ...@@ -826,34 +916,65 @@ class Data:
for phase in self.phases: for phase in self.phases:
self.devicegroups.append([phase]) self.devicegroups.append([phase])
self.errorinfo = {'suspend':[],'resume':[]} self.errorinfo = {'suspend':[],'resume':[]}
def extractErrorInfo(self, dmesg): def extractErrorInfo(self):
error = '' lf = sysvals.openlog(sysvals.dmesgfile, 'r')
tm = 0.0 i = 0
for i in range(len(dmesg)): list = []
if 'Call Trace:' in dmesg[i]: # sl = start line, et = error time, el = error line
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i]) type = 'ERROR'
sl = et = el = -1
for line in lf:
i += 1
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
if not m: if not m:
continue continue
tm = float(m.group('ktime')) t = float(m.group('ktime'))
if tm < self.start or tm > self.end: if t < self.start or t > self.end:
continue
for j in range(i-10, i+1):
error += dmesg[j]
continue continue
if error: if t < self.tSuspended:
m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
if m:
error += dmesg[i]
else:
if tm < self.tSuspended:
dir = 'suspend' dir = 'suspend'
else: else:
dir = 'resume' dir = 'resume'
error = error.replace('<', '&lt').replace('>', '&gt') msg = m.group('msg')
vprint('kernel error found in %s at %f' % (dir, tm)) if re.match('-*\[ *cut here *\]-*', msg):
self.errorinfo[dir].append((tm, error)) type = 'WARNING'
sl = i
elif re.match('genirq: .*', msg):
type = 'IRQ'
sl = i
elif re.match('BUG: .*', msg) or re.match('kernel BUG .*', msg):
type = 'BUG'
sl = i
elif re.match('-*\[ *end trace .*\]-*', msg) or \
re.match('R13: .*', msg):
if et >= 0 and sl >= 0:
list.append((type, dir, et, sl, i))
self.kerror = True
sl = et = el = -1
type = 'ERROR'
elif 'Call Trace:' in msg:
if el >= 0 and et >= 0:
list.append((type, dir, et, el, el))
self.kerror = True
et, el = t, i
if sl < 0 or type == 'BUG':
slval = i
if sl >= 0:
slval = sl
list.append((type, dir, et, slval, i))
self.kerror = True
sl = et = el = -1
type = 'ERROR'
if el >= 0 and et >= 0:
list.append((type, dir, et, el, el))
self.kerror = True self.kerror = True
error = '' for e in list:
type, dir, t, idx1, idx2 = e
sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t))
self.errorinfo[dir].append((type, t, idx1, idx2))
if self.kerror:
sysvals.dmesglog = True
lf.close()
def setStart(self, time): def setStart(self, time):
self.start = time self.start = time
def setEnd(self, time): def setEnd(self, time):
...@@ -867,6 +988,14 @@ class Data: ...@@ -867,6 +988,14 @@ 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.phases:
pend = self.dmesg[phase]['end'] pend = self.dmesg[phase]['end']
...@@ -918,7 +1047,7 @@ class Data: ...@@ -918,7 +1047,7 @@ class Data:
return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
# this should not happen # this should not happen
if not tgtdev: if not tgtdev:
vprint('[%f - %f] %s-%d %s %s %s' % \ sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \
(start, end, proc, pid, kprobename, cdata, rdata)) (start, end, proc, pid, kprobename, cdata, rdata))
return False return False
# place the call data inside the src element of the tgtdev # place the call data inside the src element of the tgtdev
...@@ -1054,6 +1183,13 @@ class Data: ...@@ -1054,6 +1183,13 @@ class Data:
if('src' in d): if('src' in d):
for e in d['src']: for e in d['src']:
e.time = self.trimTimeVal(e.time, t0, dT, left) e.time = self.trimTimeVal(e.time, t0, dT, left)
for dir in ['suspend', 'resume']:
list = []
for e in self.errorinfo[dir]:
type, tm, idx1, idx2 = e
tm = self.trimTimeVal(tm, t0, dT, left)
list.append((type, tm, idx1, idx2))
self.errorinfo[dir] = list
def normalizeTime(self, tZero): def normalizeTime(self, tZero):
# trim out any standby or freeze clock time # trim out any standby or freeze clock time
if(self.tSuspended != self.tResumed): if(self.tSuspended != self.tResumed):
...@@ -1100,7 +1236,7 @@ class Data: ...@@ -1100,7 +1236,7 @@ class Data:
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
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.phases:
list = self.dmesg[phase]['list'] list = self.dmesg[phase]['list']
...@@ -1200,15 +1336,15 @@ class Data: ...@@ -1200,15 +1336,15 @@ class Data:
devlist.append(child) devlist.append(child)
return devlist return devlist
def printDetails(self): def printDetails(self):
vprint('Timeline Details:') sysvals.vprint('Timeline Details:')
vprint(' test start: %f' % self.start) sysvals.vprint(' test start: %f' % self.start)
vprint('kernel suspend start: %f' % self.tKernSus) sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
for phase in self.phases: for phase in self.phases:
dc = len(self.dmesg[phase]['list']) dc = len(self.dmesg[phase]['list'])
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))
vprint(' kernel resume end: %f' % self.tKernRes) sysvals.vprint(' kernel resume end: %f' % self.tKernRes)
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.phases:
...@@ -1358,14 +1494,21 @@ class Data: ...@@ -1358,14 +1494,21 @@ class Data:
tres.append(t) tres.append(t)
# process the events for suspend and resume # process the events for suspend and resume
if len(proclist) > 0: if len(proclist) > 0:
vprint('Process Execution:') sysvals.vprint('Process Execution:')
for ps in proclist: for ps in proclist:
c = self.addProcessUsageEvent(ps, tsus) c = self.addProcessUsageEvent(ps, tsus)
if c > 0: if c > 0:
vprint('%25s (sus): %d' % (ps, c)) sysvals.vprint('%25s (sus): %d' % (ps, c))
c = self.addProcessUsageEvent(ps, tres) c = self.addProcessUsageEvent(ps, tres)
if c > 0: if c > 0:
vprint('%25s (res): %d' % (ps, c)) sysvals.vprint('%25s (res): %d' % (ps, c))
def debugPrint(self):
for p in self.phases:
list = self.dmesg[p]['list']
for devname in list:
dev = list[devname]
if 'ftrace' in dev:
dev['ftrace'].debugPrint(' [%s]' % devname)
# Class: DevFunction # Class: DevFunction
# Description: # Description:
...@@ -1504,18 +1647,24 @@ class FTraceLine: ...@@ -1504,18 +1647,24 @@ class FTraceLine:
# something else (possibly a trace marker) # something else (possibly a trace marker)
else: else:
self.name = m self.name = m
def isCall(self):
return self.fcall and not self.freturn
def isReturn(self):
return self.freturn and not self.fcall
def isLeaf(self):
return self.fcall and self.freturn
def getDepth(self, str): def getDepth(self, str):
return len(str)/2 return len(str)/2
def debugPrint(self, dev=''): def debugPrint(self, info=''):
if(self.freturn and self.fcall): if self.isLeaf():
print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000)) self.depth, self.name, self.length*1000000, info))
elif(self.freturn): elif self.freturn:
print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000)) self.depth, self.name, self.length*1000000, info))
else: else:
print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000)) self.depth, self.name, self.length*1000000, info))
def startMarker(self): def startMarker(self):
# Is this the starting line of a suspend? # Is this the starting line of a suspend?
if not self.fevent: if not self.fevent:
...@@ -1558,96 +1707,147 @@ class FTraceCallGraph: ...@@ -1558,96 +1707,147 @@ class FTraceCallGraph:
depth = 0 depth = 0
pid = 0 pid = 0
name = '' name = ''
def __init__(self, pid): partial = False
vfname = 'missing_function_name'
ignore = False
sv = 0
def __init__(self, pid, sv):
self.start = -1.0 self.start = -1.0
self.end = -1.0 self.end = -1.0
self.list = [] self.list = []
self.depth = 0 self.depth = 0
self.pid = pid self.pid = pid
def addLine(self, line, debug=False): self.sv = sv
def addLine(self, line):
# if this is already invalid, just leave # if this is already invalid, just leave
if(self.invalid): if(self.invalid):
return False if(line.depth == 0 and line.freturn):
# invalidate on too much data or bad depth return 1
if(len(self.list) >= 1000000 or self.depth < 0): return 0
# invalidate on bad depth
if(self.depth < 0):
self.invalidate(line) self.invalidate(line)
return False return 0
# ignore data til we return to the current depth
if self.ignore:
if line.depth > self.depth:
return 0
else:
self.list[-1].freturn = True
self.list[-1].length = line.time - self.list[-1].time
self.ignore = False
# if this is a return at self.depth, no more work is needed
if line.depth == self.depth and line.isReturn():
if line.depth == 0:
self.end = line.time
return 1
return 0
# compare current depth with this lines pre-call depth # compare current depth with this lines pre-call depth
prelinedep = line.depth prelinedep = line.depth
if(line.freturn and not line.fcall): if line.isReturn():
prelinedep += 1 prelinedep += 1
last = 0 last = 0
lasttime = line.time lasttime = line.time
virtualfname = 'missing_function_name'
if len(self.list) > 0: if len(self.list) > 0:
last = self.list[-1] last = self.list[-1]
lasttime = last.time lasttime = last.time
if last.isLeaf():
lasttime += last.length
# handle low misalignments by inserting returns # handle low misalignments by inserting returns
if prelinedep < self.depth: mismatch = prelinedep - self.depth
if debug and last: warning = self.sv.verbose and abs(mismatch) > 1
print '-------- task %d --------' % self.pid info = []
last.debugPrint() if mismatch < 0:
idx = 0 idx = 0
# add return calls to get the depth down # add return calls to get the depth down
while prelinedep < self.depth: while prelinedep < self.depth:
if debug:
print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
self.depth -= 1 self.depth -= 1
if idx == 0 and last and last.fcall and not last.freturn: if idx == 0 and last and last.isCall():
# special case, turn last call into a leaf # special case, turn last call into a leaf
last.depth = self.depth last.depth = self.depth
last.freturn = True last.freturn = True
last.length = line.time - last.time last.length = line.time - last.time
if debug: if warning:
last.debugPrint() info.append(('[make leaf]', last))
else: else:
vline = FTraceLine(lasttime) vline = FTraceLine(lasttime)
vline.depth = self.depth vline.depth = self.depth
vline.name = virtualfname vline.name = self.vfname
vline.freturn = True vline.freturn = True
self.list.append(vline) self.list.append(vline)
if debug: if warning:
vline.debugPrint() if idx == 0:
info.append(('', last))
info.append(('[add return]', vline))
idx += 1 idx += 1
if debug: if warning:
line.debugPrint() info.append(('', line))
print ''
# handle high misalignments by inserting calls # handle high misalignments by inserting calls
elif prelinedep > self.depth: elif mismatch > 0:
if debug and last:
print '-------- task %d --------' % self.pid
last.debugPrint()
idx = 0 idx = 0
if warning:
info.append(('', last))
# add calls to get the depth up # add calls to get the depth up
while prelinedep > self.depth: while prelinedep > self.depth:
if debug: if idx == 0 and line.isReturn():
print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
if idx == 0 and line.freturn and not line.fcall:
# special case, turn this return into a leaf # special case, turn this return into a leaf
line.fcall = True line.fcall = True
prelinedep -= 1 prelinedep -= 1
if warning:
info.append(('[make leaf]', line))
else: else:
vline = FTraceLine(lasttime) vline = FTraceLine(lasttime)
vline.depth = self.depth vline.depth = self.depth
vline.name = virtualfname vline.name = self.vfname
vline.fcall = True vline.fcall = True
if debug:
vline.debugPrint()
self.list.append(vline) self.list.append(vline)
self.depth += 1 self.depth += 1
if not last: if not last:
self.start = vline.time self.start = vline.time
if warning:
info.append(('[add call]', vline))
idx += 1 idx += 1
if debug: if warning and ('[make leaf]', line) not in info:
line.debugPrint() info.append(('', line))
print '' if warning:
print 'WARNING: ftrace data missing, corrections made:'
for i in info:
t, obj = i
if obj:
obj.debugPrint(t)
# process the call and set the new depth # process the call and set the new depth
if(line.fcall and not line.freturn): skipadd = False
md = self.sv.max_graph_depth
if line.isCall():
# ignore blacklisted/overdepth funcs
if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):
self.ignore = True
else:
self.depth += 1 self.depth += 1
elif(line.freturn and not line.fcall): elif line.isReturn():
self.depth -= 1 self.depth -= 1
# remove blacklisted/overdepth/empty funcs that slipped through
if (last and last.isCall() and last.depth == line.depth) or \
(md and last and last.depth >= md) or \
(line.name in self.sv.cgblacklist):
while len(self.list) > 0 and self.list[-1].depth > line.depth:
self.list.pop(-1)
if len(self.list) == 0:
self.invalid = True
return 1
self.list[-1].freturn = True
self.list[-1].length = line.time - self.list[-1].time
self.list[-1].name = line.name
skipadd = True
if len(self.list) < 1: if len(self.list) < 1:
self.start = line.time self.start = line.time
# check for a mismatch that returned all the way to callgraph end
res = 1
if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn:
line = self.list[-1]
skipadd = True
res = -1
if not skipadd:
self.list.append(line) self.list.append(line)
if(line.depth == 0 and line.freturn): if(line.depth == 0 and line.freturn):
if(self.start < 0): if(self.start < 0):
...@@ -1655,10 +1855,12 @@ class FTraceCallGraph: ...@@ -1655,10 +1855,12 @@ class FTraceCallGraph:
self.end = line.time self.end = line.time
if line.fcall: if line.fcall:
self.end += line.length self.end += line.length
if self.list[0].name == virtualfname: if self.list[0].name == self.vfname:
self.invalid = True self.invalid = True
return True if res == -1:
return False self.partial = True
return res
return 0
def invalidate(self, line): def invalidate(self, line):
if(len(self.list) > 0): if(len(self.list) > 0):
first = self.list[0] first = self.list[0]
...@@ -1668,29 +1870,30 @@ class FTraceCallGraph: ...@@ -1668,29 +1870,30 @@ class FTraceCallGraph:
id = 'task %s' % (self.pid) id = 'task %s' % (self.pid)
window = '(%f - %f)' % (self.start, line.time) window = '(%f - %f)' % (self.start, line.time)
if(self.depth < 0): if(self.depth < 0):
vprint('Too much data for '+id+\ print('Data misalignment for '+id+\
' (buffer overflow), ignoring this callback') ' (buffer overflow), ignoring this callback')
else: else:
vprint('Too much data for '+id+\ print('Too much data for '+id+\
' '+window+', ignoring this callback') ' '+window+', ignoring this callback')
def slice(self, t0, tN): def slice(self, dev):
minicg = FTraceCallGraph(0) minicg = FTraceCallGraph(dev['pid'], self.sv)
count = -1 minicg.name = self.name
firstdepth = 0 mydepth = -1
good = False
for l in self.list: for l in self.list:
if(l.time < t0 or l.time > tN): if(l.time < dev['start'] or l.time > dev['end']):
continue continue
if(count < 0): if mydepth < 0:
if(not l.fcall or l.name == 'dev_driver_string'): if l.name == 'mutex_lock' and l.freturn:
mydepth = l.depth
continue continue
firstdepth = l.depth elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall:
count = 0 good = True
l.depth -= firstdepth
minicg.addLine(l)
if((count == 0 and l.freturn and l.fcall) or
(count > 0 and l.depth <= 0)):
break break
count += 1 l.depth -= mydepth
minicg.addLine(l)
if not good or len(minicg.list) < 1:
return 0
return minicg return minicg
def repair(self, enddepth): def repair(self, enddepth):
# bring the depth back to 0 with additional returns # bring the depth back to 0 with additional returns
...@@ -1701,11 +1904,11 @@ class FTraceCallGraph: ...@@ -1701,11 +1904,11 @@ class FTraceCallGraph:
t.depth = i t.depth = i
t.freturn = True t.freturn = True
fixed = self.addLine(t) fixed = self.addLine(t)
if fixed: if fixed != 0:
self.end = last.time self.end = last.time
return True return True
return False return False
def postProcess(self, debug=False): def postProcess(self):
if len(self.list) > 0: if len(self.list) > 0:
self.name = self.list[0].name self.name = self.list[0].name
stack = dict() stack = dict()
...@@ -1714,20 +1917,23 @@ class FTraceCallGraph: ...@@ -1714,20 +1917,23 @@ class FTraceCallGraph:
for l in self.list: for l in self.list:
# ftrace bug: reported duration is not reliable # ftrace bug: reported duration is not reliable
# check each leaf and clip it at max possible length # check each leaf and clip it at max possible length
if(last and last.freturn and last.fcall): if last and last.isLeaf():
if last.length > l.time - last.time: if last.length > l.time - last.time:
last.length = l.time - last.time last.length = l.time - last.time
if(l.fcall and not l.freturn): if l.isCall():
stack[l.depth] = l stack[l.depth] = l
cnt += 1 cnt += 1
elif(l.freturn and not l.fcall): elif l.isReturn():
if(l.depth not in stack): if(l.depth not in stack):
if debug: if self.sv.verbose:
print 'Post Process Error: Depth missing' print 'Post Process Error: Depth missing'
l.debugPrint() l.debugPrint()
return False return False
# calculate call length from call/return lines # calculate call length from call/return lines
stack[l.depth].length = l.time - stack[l.depth].time cl = stack[l.depth]
cl.length = l.time - cl.time
if cl.name == self.vfname:
cl.name = l.name
stack.pop(l.depth) stack.pop(l.depth)
l.length = 0 l.length = 0
cnt -= 1 cnt -= 1
...@@ -1736,13 +1942,13 @@ class FTraceCallGraph: ...@@ -1736,13 +1942,13 @@ class FTraceCallGraph:
# trace caught the whole call tree # trace caught the whole call tree
return True return True
elif(cnt < 0): elif(cnt < 0):
if debug: if self.sv.verbose:
print 'Post Process Error: Depth is less than 0' print 'Post Process Error: Depth is less than 0'
return False return False
# trace ended before call tree finished # trace ended before call tree finished
return self.repair(cnt) return self.repair(cnt)
def deviceMatch(self, pid, data): def deviceMatch(self, pid, data):
found = False found = ''
# add the callgraph data to the device hierarchy # add the callgraph data to the device hierarchy
borderphase = { borderphase = {
'dpm_prepare': 'suspend_prepare', 'dpm_prepare': 'suspend_prepare',
...@@ -1756,8 +1962,10 @@ class FTraceCallGraph: ...@@ -1756,8 +1962,10 @@ class FTraceCallGraph:
if(pid == dev['pid'] and if(pid == dev['pid'] and
self.start <= dev['start'] and self.start <= dev['start'] and
self.end >= dev['end']): self.end >= dev['end']):
dev['ftrace'] = self.slice(dev['start'], dev['end']) cg = self.slice(dev)
found = True if cg:
dev['ftrace'] = cg
found = devname
return found return found
for p in data.phases: for p in data.phases:
if(data.dmesg[p]['start'] <= self.start and if(data.dmesg[p]['start'] <= self.start and
...@@ -1769,7 +1977,7 @@ class FTraceCallGraph: ...@@ -1769,7 +1977,7 @@ class FTraceCallGraph:
self.start <= dev['start'] and self.start <= dev['start'] and
self.end >= dev['end']): self.end >= dev['end']):
dev['ftrace'] = self dev['ftrace'] = self
found = True found = devname
break break
break break
return found return found
...@@ -1793,18 +2001,20 @@ class FTraceCallGraph: ...@@ -1793,18 +2001,20 @@ class FTraceCallGraph:
if out: if out:
phase, myname = out phase, myname = out
data.dmesg[phase]['list'][myname]['ftrace'] = self data.dmesg[phase]['list'][myname]['ftrace'] = self
def debugPrint(self): def debugPrint(self, info=''):
print('[%f - %f] %s (%d)') % (self.start, self.end, self.name, self.pid) print('%s pid=%d [%f - %f] %.3f us') % \
(self.name, self.pid, self.start, self.end,
(self.end - self.start)*1000000)
for l in self.list: for l in self.list:
if(l.freturn and l.fcall): if l.isLeaf():
print('%f (%02d): %s(); (%.3f us)' % (l.time, \ print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
l.depth, l.name, l.length*1000000)) l.depth, l.name, l.length*1000000, info))
elif(l.freturn): elif l.freturn:
print('%f (%02d): %s} (%.3f us)' % (l.time, \ print('%f (%02d): %s} (%.3f us)%s' % (l.time, \
l.depth, l.name, l.length*1000000)) l.depth, l.name, l.length*1000000, info))
else: else:
print('%f (%02d): %s() { (%.3f us)' % (l.time, \ print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
l.depth, l.name, l.length*1000000)) l.depth, l.name, l.length*1000000, info))
print(' ') print(' ')
class DevItem: class DevItem:
...@@ -1839,8 +2049,8 @@ class Timeline: ...@@ -1839,8 +2049,8 @@ class Timeline:
self.rowH = rowheight self.rowH = rowheight
self.scaleH = scaleheight self.scaleH = scaleheight
self.html = '' self.html = ''
def createHeader(self, sv): def createHeader(self, sv, stamp):
if(not sv.stamp['time']): if(not stamp['time']):
return return
self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \ self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \
% (sv.title, sv.version) % (sv.title, sv.version)
...@@ -1851,12 +2061,12 @@ class Timeline: ...@@ -1851,12 +2061,12 @@ class Timeline:
if sv.ftracelog: if sv.ftracelog:
self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>' self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>'
headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
self.html += headline_stamp.format(sv.stamp['host'], sv.stamp['kernel'], self.html += headline_stamp.format(stamp['host'], stamp['kernel'],
sv.stamp['mode'], sv.stamp['time']) stamp['mode'], stamp['time'])
if 'man' in sv.stamp and 'plat' in sv.stamp and 'cpu' in sv.stamp: if 'man' in stamp and 'plat' in stamp and 'cpu' in stamp and \
stamp['man'] and stamp['plat'] and stamp['cpu']:
headline_sysinfo = '<div class="stamp sysinfo">{0} {1} <i>with</i> {2}</div>\n' headline_sysinfo = '<div class="stamp sysinfo">{0} {1} <i>with</i> {2}</div>\n'
self.html += headline_sysinfo.format(sv.stamp['man'], self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu'])
sv.stamp['plat'], sv.stamp['cpu'])
# Function: getDeviceRows # Function: getDeviceRows
# Description: # Description:
...@@ -2067,12 +2277,16 @@ class Timeline: ...@@ -2067,12 +2277,16 @@ class Timeline:
class TestProps: class TestProps:
stamp = '' stamp = ''
sysinfo = '' sysinfo = ''
cmdline = ''
kparams = ''
S0i3 = False S0i3 = False
fwdata = [] 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>.*)$'
sysinfofmt = '^# sysinfo .*' sysinfofmt = '^# sysinfo .*'
cmdlinefmt = '^# command \| (?P<cmd>.*)'
kparamsfmt = '^# kparams \| (?P<kp>.*)'
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]*) *\|'+\
...@@ -2116,13 +2330,20 @@ class TestProps: ...@@ -2116,13 +2330,20 @@ class TestProps:
sv.hostname = data.stamp['host'] sv.hostname = data.stamp['host']
sv.suspendmode = data.stamp['mode'] sv.suspendmode = data.stamp['mode']
if sv.suspendmode == 'command' and sv.ftracefile != '': if sv.suspendmode == 'command' and sv.ftracefile != '':
modes = ['on', 'freeze', 'standby', 'mem'] modes = ['on', 'freeze', 'standby', 'mem', 'disk']
out = Popen(['grep', 'suspend_enter', sv.ftracefile], out = Popen(['grep', 'machine_suspend', sv.ftracefile],
stderr=PIPE, stdout=PIPE).stdout.read() stderr=PIPE, stdout=PIPE).stdout.read()
m = re.match('.* suspend_enter\[(?P<mode>.*)\]', out) m = re.match('.* machine_suspend\[(?P<mode>.*)\]', out)
if m and m.group('mode') in ['1', '2', '3']: if m and m.group('mode') in ['1', '2', '3', '4']:
sv.suspendmode = modes[int(m.group('mode'))] sv.suspendmode = modes[int(m.group('mode'))]
data.stamp['mode'] = sv.suspendmode data.stamp['mode'] = sv.suspendmode
m = re.match(self.cmdlinefmt, self.cmdline)
if m:
sv.cmdline = m.group('cmd')
if self.kparams:
m = re.match(self.kparamsfmt, self.kparams)
if m:
sv.kparams = m.group('kp')
if not sv.stamp: if not sv.stamp:
sv.stamp = data.stamp sv.stamp = data.stamp
...@@ -2186,46 +2407,42 @@ class ProcessMonitor: ...@@ -2186,46 +2407,42 @@ class ProcessMonitor:
# ----------------- FUNCTIONS -------------------- # ----------------- FUNCTIONS --------------------
# Function: vprint
# Description:
# verbose print (prints only with -verbose option)
# Arguments:
# msg: the debug/log message to print
def vprint(msg):
sysvals.logmsg += msg+'\n'
if(sysvals.verbose):
print(msg)
# Function: doesTraceLogHaveTraceEvents # Function: doesTraceLogHaveTraceEvents
# Description: # Description:
# Quickly determine if the ftrace log has some or all of the trace events # Quickly determine if the ftrace log has all of the trace events,
# required for primary parsing. Set the usetraceevents and/or # markers, and/or kprobes required for primary parsing.
# usetraceeventsonly flags in the global sysvals object
def doesTraceLogHaveTraceEvents(): def doesTraceLogHaveTraceEvents():
# check for kprobes kpcheck = ['_cal: (', '_cpu_down()']
techeck = sysvals.traceevents[:]
tmcheck = ['SUSPEND START', 'RESUME COMPLETE']
sysvals.usekprobes = False sysvals.usekprobes = False
out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True) fp = sysvals.openlog(sysvals.ftracefile, 'r')
if(out == 0): for line in fp:
sysvals.usekprobes = True # check for kprobes
# check for callgraph data on trace event blocks if not sysvals.usekprobes:
out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True) for i in kpcheck:
if(out == 0): if i in line:
sysvals.usekprobes = True sysvals.usekprobes = True
out = Popen(['head', '-1', sysvals.ftracefile], # check for all necessary trace events
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') check = techeck[:]
# figure out what level of trace events are supported for i in techeck:
sysvals.usetraceeventsonly = True if i in line:
sysvals.usetraceevents = False check.remove(i)
for e in sysvals.traceevents: techeck = check
out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True) # check for all necessary trace markers
if(out != 0): check = tmcheck[:]
sysvals.usetraceeventsonly = False for i in tmcheck:
if(e == 'suspend_resume' and out == 0): if i in line:
check.remove(i)
tmcheck = check
fp.close()
if len(techeck) == 0:
sysvals.usetraceevents = True sysvals.usetraceevents = True
# determine is this log is properly formatted else:
for e in ['SUSPEND START', 'RESUME COMPLETE']: sysvals.usetraceevents = False
out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True) if len(tmcheck) == 0:
if(out != 0): sysvals.usetracemarkers = True
else:
sysvals.usetracemarkers = False sysvals.usetracemarkers = False
# Function: appendIncompleteTraceLog # Function: appendIncompleteTraceLog
...@@ -2247,9 +2464,10 @@ def appendIncompleteTraceLog(testruns): ...@@ -2247,9 +2464,10 @@ def appendIncompleteTraceLog(testruns):
testrun.append(TestRun(data)) testrun.append(TestRun(data))
# extract the callgraph and traceevent data # extract the callgraph and traceevent data
vprint('Analyzing the ftrace data...') sysvals.vprint('Analyzing the ftrace data (%s)...' % \
os.path.basename(sysvals.ftracefile))
tp = TestProps() tp = TestProps()
tf = open(sysvals.ftracefile, 'r') tf = sysvals.openlog(sysvals.ftracefile, 'r')
data = 0 data = 0
for line in tf: for line in tf:
# remove any latent carriage returns # remove any latent carriage returns
...@@ -2261,6 +2479,9 @@ def appendIncompleteTraceLog(testruns): ...@@ -2261,6 +2479,9 @@ def appendIncompleteTraceLog(testruns):
elif re.match(tp.sysinfofmt, line): elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line tp.sysinfo = line
continue continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = 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(sysvals.tracertypefmt, line)
if(m): if(m):
...@@ -2393,11 +2614,14 @@ def appendIncompleteTraceLog(testruns): ...@@ -2393,11 +2614,14 @@ def appendIncompleteTraceLog(testruns):
# create a callgraph object for the data # create a callgraph object for the data
if(pid not in testrun[testidx].ftemp): if(pid not in testrun[testidx].ftemp):
testrun[testidx].ftemp[pid] = [] testrun[testidx].ftemp[pid] = []
testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid)) testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
# when the call is finished, see which device matches it # when the call is finished, see which device matches it
cg = testrun[testidx].ftemp[pid][-1] cg = testrun[testidx].ftemp[pid][-1]
if(cg.addLine(t)): res = cg.addLine(t)
testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid)) if(res != 0):
testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
if(res == -1):
testrun[testidx].ftemp[pid][-1].addLine(t)
tf.close() tf.close()
for test in testrun: for test in testrun:
...@@ -2410,11 +2634,11 @@ def appendIncompleteTraceLog(testruns): ...@@ -2410,11 +2634,11 @@ def appendIncompleteTraceLog(testruns):
# 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]:
if len(cg.list) < 1 or cg.invalid: if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
continue continue
if(not cg.postProcess()): if(not cg.postProcess()):
id = 'task %s cpu %s' % (pid, m.group('cpu')) id = 'task %s cpu %s' % (pid, m.group('cpu'))
vprint('Sanity check failed for '+\ sysvals.vprint('Sanity check failed for '+\
id+', ignoring this callback') id+', ignoring this callback')
continue continue
callstart = cg.start callstart = cg.start
...@@ -2431,8 +2655,6 @@ def appendIncompleteTraceLog(testruns): ...@@ -2431,8 +2655,6 @@ def appendIncompleteTraceLog(testruns):
dev['ftrace'] = cg dev['ftrace'] = cg
break break
test.data.printDetails()
# Function: parseTraceLog # Function: parseTraceLog
# Description: # Description:
# Analyze an ftrace log output file generated from this app during # Analyze an ftrace log output file generated from this app during
...@@ -2441,11 +2663,12 @@ def appendIncompleteTraceLog(testruns): ...@@ -2441,11 +2663,12 @@ def appendIncompleteTraceLog(testruns):
# The ftrace filename is taken from sysvals # The ftrace filename is taken from sysvals
# Output: # Output:
# An array of Data objects # An array of Data objects
def parseTraceLog(): def parseTraceLog(live=False):
vprint('Analyzing the ftrace data...') sysvals.vprint('Analyzing the ftrace data (%s)...' % \
os.path.basename(sysvals.ftracefile))
if(os.path.exists(sysvals.ftracefile) == False): if(os.path.exists(sysvals.ftracefile) == False):
doError('%s does not exist' % sysvals.ftracefile) doError('%s does not exist' % sysvals.ftracefile)
if not live:
sysvals.setupAllKprobes() sysvals.setupAllKprobes()
tracewatch = [] tracewatch = []
if sysvals.usekprobes: if sysvals.usekprobes:
...@@ -2458,7 +2681,7 @@ def parseTraceLog(): ...@@ -2458,7 +2681,7 @@ def parseTraceLog():
testdata = [] testdata = []
testrun = 0 testrun = 0
data = 0 data = 0
tf = open(sysvals.ftracefile, 'r') tf = sysvals.openlog(sysvals.ftracefile, 'r')
phase = 'suspend_prepare' phase = 'suspend_prepare'
for line in tf: for line in tf:
# remove any latent carriage returns # remove any latent carriage returns
...@@ -2470,6 +2693,9 @@ def parseTraceLog(): ...@@ -2470,6 +2693,9 @@ def parseTraceLog():
elif re.match(tp.sysinfofmt, line): elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line tp.sysinfo = line
continue continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = 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(sysvals.firmwarefmt, line)
if(m): if(m):
...@@ -2591,6 +2817,8 @@ def parseTraceLog(): ...@@ -2591,6 +2817,8 @@ def parseTraceLog():
phase = 'suspend_prepare' phase = 'suspend_prepare'
if(not isbegin): if(not isbegin):
data.dmesg[phase]['end'] = t.time data.dmesg[phase]['end'] = t.time
if data.dmesg[phase]['start'] < 0:
data.dmesg[phase]['start'] = data.start
continue continue
# suspend start # suspend start
elif(re.match('dpm_suspend\[.*', t.name)): elif(re.match('dpm_suspend\[.*', t.name)):
...@@ -2604,6 +2832,8 @@ def parseTraceLog(): ...@@ -2604,6 +2832,8 @@ def parseTraceLog():
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):
continue
phase = 'suspend_noirq' phase = 'suspend_noirq'
data.setPhase(phase, t.time, isbegin) data.setPhase(phase, t.time, isbegin)
if(not isbegin): if(not isbegin):
...@@ -2636,6 +2866,8 @@ def parseTraceLog(): ...@@ -2636,6 +2866,8 @@ def parseTraceLog():
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):
continue
phase = 'resume_noirq' phase = 'resume_noirq'
data.setPhase(phase, t.time, isbegin) data.setPhase(phase, t.time, isbegin)
if(isbegin): if(isbegin):
...@@ -2742,11 +2974,14 @@ def parseTraceLog(): ...@@ -2742,11 +2974,14 @@ def parseTraceLog():
key = (m_proc, pid) key = (m_proc, pid)
if(key not in testrun.ftemp): if(key not in testrun.ftemp):
testrun.ftemp[key] = [] testrun.ftemp[key] = []
testrun.ftemp[key].append(FTraceCallGraph(pid)) testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
# when the call is finished, see which device matches it # when the call is finished, see which device matches it
cg = testrun.ftemp[key][-1] cg = testrun.ftemp[key][-1]
if(cg.addLine(t)): res = cg.addLine(t)
testrun.ftemp[key].append(FTraceCallGraph(pid)) if(res != 0):
testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
if(res == -1):
testrun.ftemp[key][-1].addLine(t)
tf.close() tf.close()
if sysvals.suspendmode == 'command': if sysvals.suspendmode == 'command':
...@@ -2812,28 +3047,31 @@ def parseTraceLog(): ...@@ -2812,28 +3047,31 @@ def parseTraceLog():
for key in test.ftemp: for key in test.ftemp:
proc, pid = key proc, pid = key
for cg in test.ftemp[key]: for cg in test.ftemp[key]:
if len(cg.list) < 1 or cg.invalid: if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
continue continue
if(not cg.postProcess()): if(not cg.postProcess()):
id = 'task %s' % (pid) id = 'task %s' % (pid)
vprint('Sanity check failed for '+\ sysvals.vprint('Sanity check failed for '+\
id+', ignoring this callback') id+', ignoring this callback')
continue continue
# match cg data to devices # match cg data to devices
if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, data): devname = ''
if sysvals.suspendmode != 'command':
devname = cg.deviceMatch(pid, data)
if not devname:
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:
print 'WARNING: the callgraph for %s is massive (%d lines)' %\
(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]
name = cg.name name = cg.name
if sysvals.isCallgraphFunc(name): if sysvals.isCallgraphFunc(name):
vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name)) sysvals.vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
cg.newActionFromFunction(data) cg.newActionFromFunction(data)
if sysvals.suspendmode == 'command': if sysvals.suspendmode == 'command':
for data in testdata:
data.printDetails()
return testdata return testdata
# fill in any missing phases # fill in any missing phases
...@@ -2841,7 +3079,7 @@ def parseTraceLog(): ...@@ -2841,7 +3079,7 @@ def parseTraceLog():
lp = data.phases[0] lp = data.phases[0]
for p in data.phases: for p in data.phases:
if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
vprint('WARNING: phase "%s" is missing!' % p) sysvals.vprint('WARNING: phase "%s" is missing!' % p)
if(data.dmesg[p]['start'] < 0): if(data.dmesg[p]['start'] < 0):
data.dmesg[p]['start'] = data.dmesg[lp]['end'] data.dmesg[p]['start'] = data.dmesg[lp]['end']
if(p == 'resume_machine'): if(p == 'resume_machine'):
...@@ -2859,7 +3097,6 @@ def parseTraceLog(): ...@@ -2859,7 +3097,6 @@ def parseTraceLog():
data.fixupInitcallsThatDidntReturn() data.fixupInitcallsThatDidntReturn()
if sysvals.usedevsrc: if sysvals.usedevsrc:
data.optimizeDevSrc() data.optimizeDevSrc()
data.printDetails()
# x2: merge any overlapping devices between test runs # x2: merge any overlapping devices between test runs
if sysvals.usedevsrc and len(testdata) > 1: if sysvals.usedevsrc and len(testdata) > 1:
...@@ -2878,19 +3115,18 @@ def parseTraceLog(): ...@@ -2878,19 +3115,18 @@ def parseTraceLog():
# The dmesg filename is taken from sysvals # The dmesg filename is taken from sysvals
# Output: # Output:
# An array of empty Data objects with only their dmesgtext attributes set # An array of empty Data objects with only their dmesgtext attributes set
def loadKernelLog(justtext=False): def loadKernelLog():
vprint('Analyzing the dmesg data...') sysvals.vprint('Analyzing the dmesg data (%s)...' % \
os.path.basename(sysvals.dmesgfile))
if(os.path.exists(sysvals.dmesgfile) == False): if(os.path.exists(sysvals.dmesgfile) == False):
doError('%s does not exist' % sysvals.dmesgfile) doError('%s does not exist' % sysvals.dmesgfile)
if justtext:
dmesgtext = []
# there can be multiple test runs in a single file # there can be multiple test runs in a single file
tp = TestProps() tp = TestProps()
tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown') tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
testruns = [] testruns = []
data = 0 data = 0
lf = open(sysvals.dmesgfile, 'r') lf = sysvals.openlog(sysvals.dmesgfile, 'r')
for line in lf: for line in lf:
line = line.replace('\r\n', '') line = line.replace('\r\n', '')
idx = line.find('[') idx = line.find('[')
...@@ -2903,6 +3139,9 @@ def loadKernelLog(justtext=False): ...@@ -2903,6 +3139,9 @@ def loadKernelLog(justtext=False):
elif re.match(tp.sysinfofmt, line): elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line tp.sysinfo = line
continue continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line
continue
m = re.match(sysvals.firmwarefmt, line) m = re.match(sysvals.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'))))
...@@ -2911,9 +3150,6 @@ def loadKernelLog(justtext=False): ...@@ -2911,9 +3150,6 @@ def loadKernelLog(justtext=False):
if(not m): if(not m):
continue continue
msg = m.group("msg") msg = m.group("msg")
if justtext:
dmesgtext.append(line)
continue
if(re.match('PM: Syncing filesystems.*', msg)): if(re.match('PM: Syncing filesystems.*', msg)):
if(data): if(data):
testruns.append(data) testruns.append(data)
...@@ -2934,8 +3170,6 @@ def loadKernelLog(justtext=False): ...@@ -2934,8 +3170,6 @@ def loadKernelLog(justtext=False):
data.dmesgtext.append(line) data.dmesgtext.append(line)
lf.close() lf.close()
if justtext:
return dmesgtext
if data: if data:
testruns.append(data) testruns.append(data)
if len(testruns) < 1: if len(testruns) < 1:
...@@ -2975,7 +3209,7 @@ def parseKernelLog(data): ...@@ -2975,7 +3209,7 @@ def parseKernelLog(data):
phase = 'suspend_runtime' phase = 'suspend_runtime'
if(data.fwValid): if(data.fwValid):
vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \ sysvals.vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
(data.fwSuspend, data.fwResume)) (data.fwSuspend, data.fwResume))
# dmesg phase match table # dmesg phase match table
...@@ -3201,7 +3435,6 @@ def parseKernelLog(data): ...@@ -3201,7 +3435,6 @@ def parseKernelLog(data):
for event in actions[name]: for event in actions[name]:
data.newActionGlobal(name, event['begin'], event['end']) data.newActionGlobal(name, event['begin'], event['end'])
data.printDetails()
if(len(sysvals.devicefilter) > 0): if(len(sysvals.devicefilter) > 0):
data.deviceFilter(sysvals.devicefilter) data.deviceFilter(sysvals.devicefilter)
data.fixupInitcallsThatDidntReturn() data.fixupInitcallsThatDidntReturn()
...@@ -3230,9 +3463,9 @@ def callgraphHTML(sv, hf, num, cg, title, color, devid): ...@@ -3230,9 +3463,9 @@ def callgraphHTML(sv, hf, num, cg, title, color, devid):
else: else:
fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>' fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'
flen = fmt % (line.length*1000, line.time) flen = fmt % (line.length*1000, line.time)
if(line.freturn and line.fcall): if line.isLeaf():
hf.write(html_func_leaf.format(line.name, flen)) hf.write(html_func_leaf.format(line.name, flen))
elif(line.freturn): elif line.freturn:
hf.write(html_func_end) hf.write(html_func_end)
else: else:
hf.write(html_func_start.format(num, line.name, flen)) hf.write(html_func_start.format(num, line.name, flen))
...@@ -3249,7 +3482,7 @@ def addCallgraphs(sv, hf, data): ...@@ -3249,7 +3482,7 @@ def addCallgraphs(sv, hf, data):
continue continue
list = data.dmesg[p]['list'] list = data.dmesg[p]['list']
for devname in data.sortedDevices(p): for devname in data.sortedDevices(p):
if len(sv.devicefilter) > 0 and devname not in sv.devicefilter: if len(sv.cgfilter) > 0 and devname not in sv.cgfilter:
continue continue
dev = list[devname] dev = list[devname]
color = 'white' color = 'white'
...@@ -3270,7 +3503,6 @@ def addCallgraphs(sv, hf, data): ...@@ -3270,7 +3503,6 @@ def addCallgraphs(sv, hf, data):
for cg in dev['ftraces']: for cg in dev['ftraces']:
num = callgraphHTML(sv, hf, num, cg, num = callgraphHTML(sv, hf, num, cg,
name+' &rarr; '+cg.name, color, dev['id']) name+' &rarr; '+cg.name, color, dev['id'])
hf.write('\n\n </section>\n') hf.write('\n\n </section>\n')
# Function: createHTMLSummarySimple # Function: createHTMLSummarySimple
...@@ -3311,7 +3543,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): ...@@ -3311,7 +3543,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
sTimeAvg = rTimeAvg = 0.0 sTimeAvg = rTimeAvg = 0.0
mode = '' mode = ''
num = 0 num = 0
for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'])): for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
if mode != data['mode']: if mode != data['mode']:
# test average line # test average line
if(num > 0): if(num > 0):
...@@ -3387,7 +3619,7 @@ def createHTML(testruns): ...@@ -3387,7 +3619,7 @@ def createHTML(testruns):
data.normalizeTime(testruns[-1].tSuspended) data.normalizeTime(testruns[-1].tSuspended)
# html function templates # html function templates
html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR&rarr;</div>\n' html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}&rarr;</div>\n'
html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n' html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n'
html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n' html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
html_timetotal = '<table class="time1">\n<tr>'\ html_timetotal = '<table class="time1">\n<tr>'\
...@@ -3416,20 +3648,17 @@ def createHTML(testruns): ...@@ -3416,20 +3648,17 @@ def createHTML(testruns):
scaleH = 40 scaleH = 40
# device timeline # device timeline
vprint('Creating Device Timeline...')
devtl = Timeline(30, scaleH) devtl = Timeline(30, scaleH)
# write the test title and general info header # write the test title and general info header
devtl.createHeader(sysvals) devtl.createHeader(sysvals, testruns[0].stamp)
# Generate the header for this timeline # Generate the header for this timeline
for data in testruns: for data in testruns:
tTotal = data.end - data.start tTotal = data.end - data.start
sktime, rktime = data.getTimeValues() sktime, rktime = data.getTimeValues()
if(tTotal == 0): if(tTotal == 0):
print('ERROR: No timeline data') doError('No timeline data')
sys.exit()
if(data.tLow > 0): if(data.tLow > 0):
low_time = '%.0f'%(data.tLow*1000) low_time = '%.0f'%(data.tLow*1000)
if sysvals.suspendmode == 'command': if sysvals.suspendmode == 'command':
...@@ -3567,9 +3796,10 @@ def createHTML(testruns): ...@@ -3567,9 +3796,10 @@ def createHTML(testruns):
data.dmesg[b]['color'], '') data.dmesg[b]['color'], '')
for e in data.errorinfo[dir]: for e in data.errorinfo[dir]:
# draw red lines for any kernel errors found # draw red lines for any kernel errors found
t, err = e type, t, idx1, idx2 = e
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, err) devtl.html += html_error.format(right, id, type)
for b in sorted(phases[dir]): for b in sorted(phases[dir]):
# draw the devices for this phase # draw the devices for this phase
phaselist = data.dmesg[b]['list'] phaselist = data.dmesg[b]['list']
...@@ -3663,13 +3893,6 @@ def createHTML(testruns): ...@@ -3663,13 +3893,6 @@ def createHTML(testruns):
devtl.html += '</div>\n' devtl.html += '</div>\n'
hf = open(sysvals.htmlfile, 'w') hf = open(sysvals.htmlfile, 'w')
# no header or css if its embedded
if(sysvals.embedded):
hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
(data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \
data.fwSuspend/1000000, data.fwResume/1000000))
else:
addCSS(hf, sysvals, len(testruns), kerror) addCSS(hf, sysvals, len(testruns), kerror)
# write the device timeline # write the device timeline
...@@ -3701,7 +3924,7 @@ def createHTML(testruns): ...@@ -3701,7 +3924,7 @@ def createHTML(testruns):
data = testruns[sysvals.cgtest] data = testruns[sysvals.cgtest]
else: else:
data = testruns[-1] data = testruns[-1]
if(sysvals.usecallgraph and not sysvals.embedded): if sysvals.usecallgraph:
addCallgraphs(sysvals, hf, data) addCallgraphs(sysvals, hf, data)
# add the test log as a hidden div # add the test log as a hidden div
...@@ -3710,7 +3933,7 @@ def createHTML(testruns): ...@@ -3710,7 +3933,7 @@ def createHTML(testruns):
# add the dmesg log as a hidden div # add the dmesg log as a hidden div
if sysvals.dmesglog and sysvals.dmesgfile: if sysvals.dmesglog and sysvals.dmesgfile:
hf.write('<div id="dmesglog" style="display:none;">\n') hf.write('<div id="dmesglog" style="display:none;">\n')
lf = open(sysvals.dmesgfile, 'r') lf = sysvals.openlog(sysvals.dmesgfile, 'r')
for line in lf: for line in lf:
line = line.replace('<', '&lt').replace('>', '&gt') line = line.replace('<', '&lt').replace('>', '&gt')
hf.write(line) hf.write(line)
...@@ -3719,28 +3942,15 @@ def createHTML(testruns): ...@@ -3719,28 +3942,15 @@ def createHTML(testruns):
# add the ftrace log as a hidden div # add the ftrace log as a hidden div
if sysvals.ftracelog and sysvals.ftracefile: if sysvals.ftracelog and sysvals.ftracefile:
hf.write('<div id="ftracelog" style="display:none;">\n') hf.write('<div id="ftracelog" style="display:none;">\n')
lf = open(sysvals.ftracefile, 'r') lf = sysvals.openlog(sysvals.ftracefile, 'r')
for line in lf: for line in lf:
hf.write(line) hf.write(line)
lf.close() lf.close()
hf.write('</div>\n') hf.write('</div>\n')
if(not sysvals.embedded):
# write the footer and close # write the footer and close
addScriptCode(hf, testruns) addScriptCode(hf, testruns)
hf.write('</body>\n</html>\n') hf.write('</body>\n</html>\n')
else:
# embedded out will be loaded in a page, skip the js
t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
# add js code in a div entry for later evaluation
detail = 'var bounds = [%f,%f];\n' % (t0, tMax)
detail += 'var devtable = [\n'
for data in testruns:
topo = data.deviceTopology()
detail += '\t"%s",\n' % (topo)
detail += '];\n'
hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n')
hf.close() hf.close()
return True return True
...@@ -4149,9 +4359,25 @@ def addScriptCode(hf, testruns): ...@@ -4149,9 +4359,25 @@ def addScriptCode(hf, testruns):
' win.document.write(html+dt);\n'\ ' win.document.write(html+dt);\n'\
' }\n'\ ' }\n'\
' function errWindow() {\n'\ ' function errWindow() {\n'\
' var text = this.id;\n'\ ' var range = this.id.split("_");\n'\
' var idx1 = parseInt(range[0]);\n'\
' var idx2 = parseInt(range[1]);\n'\
' var win = window.open();\n'\ ' var win = window.open();\n'\
' win.document.write("<pre>"+text+"</pre>");\n'\ ' var log = document.getElementById("dmesglog");\n'\
' var title = "<title>dmesg log</title>";\n'\
' var text = log.innerHTML.split("\\n");\n'\
' var html = "";\n'\
' for(var i = 0; i < text.length; i++) {\n'\
' if(i == idx1) {\n'\
' html += "<e id=target>"+text[i]+"</e>\\n";\n'\
' } else if(i > idx1 && i <= idx2) {\n'\
' html += "<e>"+text[i]+"</e>\\n";\n'\
' } else {\n'\
' html += text[i]+"\\n";\n'\
' }\n'\
' }\n'\
' win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>");\n'\
' win.location.hash = "#target";\n'\
' win.document.close();\n'\ ' win.document.close();\n'\
' }\n'\ ' }\n'\
' function logWindow(e) {\n'\ ' function logWindow(e) {\n'\
...@@ -4219,6 +4445,30 @@ def addScriptCode(hf, testruns): ...@@ -4219,6 +4445,30 @@ def addScriptCode(hf, testruns):
'</script>\n' '</script>\n'
hf.write(script_code); hf.write(script_code);
def setRuntimeSuspend(before=True):
global sysvals
sv = sysvals
if sv.rs == 0:
return
if before:
# runtime suspend disable or enable
if sv.rs > 0:
sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled'
else:
sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled'
print('CONFIGURING RUNTIME SUSPEND...')
sv.rslist = deviceInfo(sv.rstgt)
for i in sv.rslist:
sv.setVal(sv.rsval, i)
print('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist)))
print('waiting 5 seconds...')
time.sleep(5)
else:
# runtime suspend re-enable or re-disable
for i in sv.rslist:
sv.setVal(sv.rstgt, i)
print('runtime suspend settings restored on %d devices' % len(sv.rslist))
# Function: executeSuspend # Function: executeSuspend
# Description: # Description:
# Execute system suspend through the sysfs interface, then copy the output # Execute system suspend through the sysfs interface, then copy the output
...@@ -4227,6 +4477,19 @@ def executeSuspend(): ...@@ -4227,6 +4477,19 @@ def executeSuspend():
pm = ProcessMonitor() pm = ProcessMonitor()
tp = sysvals.tpath tp = sysvals.tpath
fwdata = [] fwdata = []
# run these commands to prepare the system for suspend
if sysvals.display:
if sysvals.display > 0:
print('TURN DISPLAY ON')
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)
if sysvals.sync:
print('SYNCING FILESYSTEMS')
call('sync', shell=True)
# mark the start point in the kernel ring buffer just as we start # mark the start point in the kernel ring buffer just as we start
sysvals.initdmesg() sysvals.initdmesg()
# start ftrace # start ftrace
...@@ -4298,47 +4561,22 @@ def executeSuspend(): ...@@ -4298,47 +4561,22 @@ def executeSuspend():
pm.stop() pm.stop()
sysvals.fsetVal('0', 'tracing_on') sysvals.fsetVal('0', 'tracing_on')
print('CAPTURING TRACE') print('CAPTURING TRACE')
sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata) op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata)
call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True) fp = open(tp+'trace', 'r')
for line in fp:
op.write(line)
op.close()
sysvals.fsetVal('', 'trace') sysvals.fsetVal('', 'trace')
devProps() devProps()
# grab a copy of the dmesg output # grab a copy of the dmesg output
print('CAPTURING DMESG') print('CAPTURING DMESG')
sysvals.writeDatafileHeader(sysvals.dmesgfile, fwdata) sysvals.getdmesg(fwdata)
sysvals.getdmesg()
# Function: setUSBDevicesAuto def readFile(file):
# Description: if os.path.islink(file):
# Set the autosuspend control parameter of all USB devices to auto return os.readlink(file).split('/')[-1]
# This can be dangerous, so use at your own risk, most devices are set else:
# to always-on since the kernel cant determine if the device can return sysvals.getVal(file).strip()
# properly autosuspend
def setUSBDevicesAuto():
sysvals.rootCheck(True)
for dirname, dirnames, filenames in os.walk('/sys/devices'):
if(re.match('.*/usb[0-9]*.*', dirname) and
'idVendor' in filenames and 'idProduct' in filenames):
call('echo auto > %s/power/control' % dirname, shell=True)
name = dirname.split('/')[-1]
desc = Popen(['cat', '%s/product' % dirname],
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
ctrl = Popen(['cat', '%s/power/control' % dirname],
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
print('control is %s for %6s: %s' % (ctrl, name, desc))
# Function: yesno
# Description:
# Print out an equivalent Y or N for a set of known parameter values
# Output:
# 'Y', 'N', or ' ' if the value is unknown
def yesno(val):
yesvals = ['auto', 'enabled', 'active', '1']
novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
if val in yesvals:
return 'Y'
elif val in novals:
return 'N'
return ' '
# Function: ms2nice # Function: ms2nice
# Description: # Description:
...@@ -4346,69 +4584,81 @@ def yesno(val): ...@@ -4346,69 +4584,81 @@ def yesno(val):
# Output: # Output:
# The time string, e.g. "1901m16s" # The time string, e.g. "1901m16s"
def ms2nice(val): def ms2nice(val):
ms = 0 val = int(val)
try: h = val / 3600000
ms = int(val) m = (val / 60000) % 60
except: s = (val / 1000) % 60
return 0.0 if h > 0:
m = ms / 60000 return '%d:%02d:%02d' % (h, m, s)
s = (ms / 1000) - (m * 60) if m > 0:
return '%3dm%2ds' % (m, s) return '%02d:%02d' % (m, s)
return '%ds' % s
# Function: detectUSB def yesno(val):
list = {'enabled':'A', 'disabled':'S', 'auto':'E', 'on':'D',
'active':'A', 'suspended':'S', 'suspending':'S'}
if val not in list:
return ' '
return list[val]
# Function: deviceInfo
# Description: # Description:
# Detect all the USB hosts and devices currently connected and add # Detect all the USB hosts and devices currently connected and add
# a list of USB device names to sysvals for better timeline readability # a list of USB device names to sysvals for better timeline readability
def detectUSB(): def deviceInfo(output=''):
field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} if not output:
power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
'control':'', 'persist':'', 'runtime_enabled':'',
'runtime_status':'', 'runtime_usage':'',
'runtime_active_time':'',
'runtime_suspended_time':'',
'active_duration':'',
'connected_duration':''}
print('LEGEND') print('LEGEND')
print('---------------------------------------------------------------------------------------------') print('---------------------------------------------------------------------------------------------')
print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)') print(' A = async/sync PM queue (A/S) C = runtime active children')
print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)') print(' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)')
print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)') print(' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)')
print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
print(' U = runtime usage count') print(' U = runtime usage count')
print('---------------------------------------------------------------------------------------------') print('---------------------------------------------------------------------------------------------')
print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT') print('DEVICE NAME A R S U C rACTIVE rSUSPEND')
print('---------------------------------------------------------------------------------------------') print('---------------------------------------------------------------------------------------------')
res = []
tgtval = 'runtime_status'
lines = dict()
for dirname, dirnames, filenames in os.walk('/sys/devices'): for dirname, dirnames, filenames in os.walk('/sys/devices'):
if(re.match('.*/usb[0-9]*.*', dirname) and if(not re.match('.*/power', dirname) or
'idVendor' in filenames and 'idProduct' in filenames): 'control' not in filenames or
for i in field: tgtval not in filenames):
field[i] = Popen(['cat', '%s/%s' % (dirname, i)], continue
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') name = ''
name = dirname.split('/')[-1] dirname = dirname[:-6]
for i in power: device = dirname.split('/')[-1]
power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)], power = dict()
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') power[tgtval] = readFile('%s/power/%s' % (dirname, tgtval))
if(re.match('usb[0-9]*', name)): # only list devices which support runtime suspend
first = '%-8s' % name if power[tgtval] not in ['active', 'suspended', 'suspending']:
else: continue
first = '%8s' % name for i in ['product', 'driver', 'subsystem']:
print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \ file = '%s/%s' % (dirname, i)
(first, field['idVendor'], field['idProduct'], \ if os.path.exists(file):
field['product'][0:20], field['speed'], \ name = readFile(file)
break
for i in ['async', 'control', 'runtime_status', 'runtime_usage',
'runtime_active_kids', 'runtime_active_time',
'runtime_suspended_time']:
if i in filenames:
power[i] = readFile('%s/power/%s' % (dirname, i))
if output:
if power['control'] == output:
res.append('%s/power/control' % dirname)
continue
lines[dirname] = '%-26s %-26s %1s %1s %1s %1s %1s %10s %10s' % \
(device[:26], name[:26],
yesno(power['async']), \ yesno(power['async']), \
yesno(power['control']), \ yesno(power['control']), \
yesno(power['persist']), \
yesno(power['runtime_enabled']), \
yesno(power['runtime_status']), \ yesno(power['runtime_status']), \
power['runtime_usage'], \ power['runtime_usage'], \
power['autosuspend'], \ power['runtime_active_kids'], \
ms2nice(power['runtime_active_time']), \ ms2nice(power['runtime_active_time']), \
ms2nice(power['runtime_suspended_time']), \ ms2nice(power['runtime_suspended_time']))
ms2nice(power['active_duration']), \ for i in sorted(lines):
ms2nice(power['connected_duration']))) print lines[i]
return res
# Function: devProps # Function: devProps
# Description: # Description:
...@@ -4444,7 +4694,7 @@ def devProps(data=0): ...@@ -4444,7 +4694,7 @@ def devProps(data=0):
msghead = 'Additional data added by AnalyzeSuspend' msghead = 'Additional data added by AnalyzeSuspend'
alreadystamped = False alreadystamped = False
tp = TestProps() tp = TestProps()
tf = open(sysvals.ftracefile, 'r') tf = sysvals.openlog(sysvals.ftracefile, 'r')
for line in tf: for line in tf:
if msghead in line: if msghead in line:
alreadystamped = True alreadystamped = True
...@@ -4469,7 +4719,7 @@ def devProps(data=0): ...@@ -4469,7 +4719,7 @@ def devProps(data=0):
if not alreadystamped and sysvals.suspendmode == 'command': if not alreadystamped and sysvals.suspendmode == 'command':
out = '#\n# '+msghead+'\n# Device Properties: ' out = '#\n# '+msghead+'\n# Device Properties: '
out += 'testcommandstring,%s,0;' % (sysvals.testcommand) out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
with open(sysvals.ftracefile, 'a') as fp: with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
fp.write(out+'\n') fp.write(out+'\n')
sysvals.devprops = props sysvals.devprops = props
return return
...@@ -4526,7 +4776,7 @@ def devProps(data=0): ...@@ -4526,7 +4776,7 @@ def devProps(data=0):
out = '#\n# '+msghead+'\n# Device Properties: ' out = '#\n# '+msghead+'\n# Device Properties: '
for dev in sorted(props): for dev in sorted(props):
out += props[dev].out(dev) out += props[dev].out(dev)
with open(sysvals.ftracefile, 'a') as fp: with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
fp.write(out+'\n') fp.write(out+'\n')
sysvals.devprops = props sysvals.devprops = props
...@@ -4869,20 +5119,12 @@ def statusCheck(probecheck=False): ...@@ -4869,20 +5119,12 @@ def statusCheck(probecheck=False):
# what data source are we using # what data source are we using
res = 'DMESG' res = 'DMESG'
if(ftgood): if(ftgood):
sysvals.usetraceeventsonly = True
sysvals.usetraceevents = False
for e in sysvals.traceevents:
check = False
if(os.path.exists(sysvals.epath+e)):
check = True
if(not check):
sysvals.usetraceeventsonly = False
if(e == 'suspend_resume' and check):
sysvals.usetraceevents = True sysvals.usetraceevents = True
if(sysvals.usetraceevents and sysvals.usetraceeventsonly): for e in sysvals.traceevents:
if not os.path.exists(sysvals.epath+e):
sysvals.usetraceevents = False
if(sysvals.usetraceevents):
res = 'FTRACE (all trace events found)' res = 'FTRACE (all trace events found)'
elif(sysvals.usetraceevents):
res = 'DMESG and FTRACE (suspend_resume trace event found)'
print(' timeline data source: %s' % res) print(' timeline data source: %s' % res)
# check if rtcwake # check if rtcwake
...@@ -4917,6 +5159,7 @@ def doError(msg, help=False): ...@@ -4917,6 +5159,7 @@ def doError(msg, help=False):
if(help == True): if(help == True):
printHelp() printHelp()
print('ERROR: %s\n') % msg print('ERROR: %s\n') % msg
sysvals.outputResult({'error':msg})
sys.exit() sys.exit()
# Function: getArgInt # Function: getArgInt
...@@ -4957,22 +5200,36 @@ def getArgFloat(name, args, min, max, main=True): ...@@ -4957,22 +5200,36 @@ def getArgFloat(name, args, min, max, main=True):
doError(name+': value should be between %f and %f' % (min, max), True) doError(name+': value should be between %f and %f' % (min, max), True)
return val return val
def processData(): def processData(live=False):
print('PROCESSING DATA') print('PROCESSING DATA')
if(sysvals.usetraceeventsonly): if(sysvals.usetraceevents):
testruns = parseTraceLog() testruns = parseTraceLog(live)
if sysvals.dmesgfile: if sysvals.dmesgfile:
dmesgtext = loadKernelLog(True)
for data in testruns: for data in testruns:
data.extractErrorInfo(dmesgtext) data.extractErrorInfo()
else: else:
testruns = loadKernelLog() testruns = loadKernelLog()
for data in testruns: for data in testruns:
parseKernelLog(data) parseKernelLog(data)
if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)): if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
appendIncompleteTraceLog(testruns) appendIncompleteTraceLog(testruns)
sysvals.vprint('Command:\n %s' % sysvals.cmdline)
for data in testruns:
data.printDetails()
if sysvals.cgdump:
for data in testruns:
data.debugPrint()
sys.exit()
sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
createHTML(testruns) createHTML(testruns)
return testruns print('DONE')
data = testruns[0]
stamp = data.stamp
stamp['suspend'], stamp['resume'] = data.getTimeValues()
if data.fwValid:
stamp['fwsuspend'], stamp['fwresume'] = data.fwSuspend, data.fwResume
return (testruns, stamp)
# Function: rerunTest # Function: rerunTest
# Description: # Description:
...@@ -4980,37 +5237,36 @@ def processData(): ...@@ -4980,37 +5237,36 @@ def processData():
def rerunTest(): def rerunTest():
if sysvals.ftracefile: if sysvals.ftracefile:
doesTraceLogHaveTraceEvents() doesTraceLogHaveTraceEvents()
if not sysvals.dmesgfile and not sysvals.usetraceeventsonly: if not sysvals.dmesgfile and not sysvals.usetraceevents:
doError('recreating this html output requires a dmesg file') doError('recreating this html output requires a dmesg file')
sysvals.setOutputFile() sysvals.setOutputFile()
vprint('Output file: %s' % sysvals.htmlfile)
if os.path.exists(sysvals.htmlfile): if os.path.exists(sysvals.htmlfile):
if not os.path.isfile(sysvals.htmlfile): if not os.path.isfile(sysvals.htmlfile):
doError('a directory already exists with this name: %s' % sysvals.htmlfile) doError('a directory already exists with this name: %s' % sysvals.htmlfile)
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)
return processData() testruns, stamp = processData(False)
return stamp
# Function: runTest # Function: runTest
# Description: # Description:
# execute a suspend/resume, gather the logs, and generate the output # execute a suspend/resume, gather the logs, and generate the output
def runTest(): def runTest(n=0):
# prepare for the test # prepare for the test
sysvals.initFtrace() sysvals.initFtrace()
sysvals.initTestOutput('suspend') sysvals.initTestOutput('suspend')
vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
(sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
# execute the test # execute the test
executeSuspend() executeSuspend()
sysvals.cleanupFtrace() sysvals.cleanupFtrace()
processData() if sysvals.skiphtml:
sysvals.sudouser(sysvals.testdir)
# if running as root, change output dir owner to sudo_user return
if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \ testruns, stamp = processData(True)
'SUDO_USER' in os.environ: for data in testruns:
cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' del data
call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True) sysvals.sudouser(sysvals.testdir)
sysvals.outputResult(stamp, n)
def find_in_html(html, strs, div=False): def find_in_html(html, strs, div=False):
for str in strs: for str in strs:
...@@ -5072,10 +5328,12 @@ def runSummary(subdir, local=True): ...@@ -5072,10 +5328,12 @@ def runSummary(subdir, local=True):
# Function: checkArgBool # Function: checkArgBool
# Description: # Description:
# check if a boolean string value is true or false # check if a boolean string value is true or false
def checkArgBool(value): def checkArgBool(name, value):
yes = ['1', 'true', 'yes', 'on'] if value in switchvalues:
if value.lower() in yes: if value in switchoff:
return False
return True return True
doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True)
return False return False
# Function: configFromFile # Function: configFromFile
...@@ -5091,60 +5349,116 @@ def configFromFile(file): ...@@ -5091,60 +5349,116 @@ def configFromFile(file):
if 'Settings' in sections: if 'Settings' in sections:
for opt in Config.options('Settings'): for opt in Config.options('Settings'):
value = Config.get('Settings', opt).lower() value = Config.get('Settings', opt).lower()
if(opt.lower() == 'verbose'): option = opt.lower()
sysvals.verbose = checkArgBool(value) if(option == 'verbose'):
elif(opt.lower() == 'addlogs'): sysvals.verbose = checkArgBool(option, value)
sysvals.dmesglog = sysvals.ftracelog = checkArgBool(value) elif(option == 'addlogs'):
elif(opt.lower() == 'dev'): sysvals.dmesglog = sysvals.ftracelog = checkArgBool(option, value)
sysvals.usedevsrc = checkArgBool(value) elif(option == 'dev'):
elif(opt.lower() == 'proc'): sysvals.usedevsrc = checkArgBool(option, value)
sysvals.useprocmon = checkArgBool(value) elif(option == 'proc'):
elif(opt.lower() == 'x2'): sysvals.useprocmon = checkArgBool(option, value)
if checkArgBool(value): elif(option == 'x2'):
if checkArgBool(option, value):
sysvals.execcount = 2 sysvals.execcount = 2
elif(opt.lower() == 'callgraph'): elif(option == 'callgraph'):
sysvals.usecallgraph = checkArgBool(value) sysvals.usecallgraph = checkArgBool(option, value)
elif(opt.lower() == 'override-timeline-functions'): elif(option == 'override-timeline-functions'):
overridekprobes = checkArgBool(value) overridekprobes = checkArgBool(option, value)
elif(opt.lower() == 'override-dev-timeline-functions'): elif(option == 'override-dev-timeline-functions'):
overridedevkprobes = checkArgBool(value) overridedevkprobes = checkArgBool(option, value)
elif(opt.lower() == 'devicefilter'): elif(option == 'skiphtml'):
sysvals.skiphtml = checkArgBool(option, value)
elif(option == 'sync'):
sysvals.sync = checkArgBool(option, value)
elif(option == 'rs' or option == 'runtimesuspend'):
if value in switchvalues:
if value in switchoff:
sysvals.rs = -1
else:
sysvals.rs = 1
else:
doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)
elif(option == 'display'):
if value in switchvalues:
if value in switchoff:
sysvals.display = -1
else:
sysvals.display = 1
else:
doError('invalid value --> (%s: %s), use "on/off"' % (option, value), True)
elif(option == 'gzip'):
sysvals.gzip = checkArgBool(option, value)
elif(option == 'cgfilter'):
sysvals.setCallgraphFilter(value)
elif(option == 'cgskip'):
if value in switchoff:
sysvals.cgskip = ''
else:
sysvals.cgskip = sysvals.configFile(val)
if(not sysvals.cgskip):
doError('%s does not exist' % sysvals.cgskip)
elif(option == 'cgtest'):
sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)
elif(option == 'cgphase'):
d = Data(0)
if value not in d.phases:
doError('invalid phase --> (%s: %s), valid phases are %s'\
% (option, value, d.phases), True)
sysvals.cgphase = value
elif(option == 'fadd'):
file = sysvals.configFile(value)
if(not file):
doError('%s does not exist' % value)
sysvals.addFtraceFilterFunctions(file)
elif(option == 'result'):
sysvals.result = value
elif(option == 'multi'):
nums = value.split()
if len(nums) != 2:
doError('multi requires 2 integers (exec_count and delay)', True)
sysvals.multitest['run'] = True
sysvals.multitest['count'] = getArgInt('multi: n d (exec count)', nums[0], 2, 1000000, False)
sysvals.multitest['delay'] = getArgInt('multi: n d (delay between tests)', nums[1], 0, 3600, False)
elif(option == 'devicefilter'):
sysvals.setDeviceFilter(value) sysvals.setDeviceFilter(value)
elif(opt.lower() == 'expandcg'): elif(option == 'expandcg'):
sysvals.cgexp = checkArgBool(value) sysvals.cgexp = checkArgBool(option, value)
elif(opt.lower() == 'srgap'): elif(option == 'srgap'):
if checkArgBool(value): if checkArgBool(option, value):
sysvals.srgap = 5 sysvals.srgap = 5
elif(opt.lower() == 'mode'): elif(option == 'mode'):
sysvals.suspendmode = value sysvals.suspendmode = value
elif(opt.lower() == 'command'): elif(option == 'command' or option == 'cmd'):
sysvals.testcommand = value sysvals.testcommand = value
elif(opt.lower() == 'x2delay'): elif(option == 'x2delay'):
sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False) sysvals.x2delay = getArgInt('x2delay', value, 0, 60000, False)
elif(opt.lower() == 'predelay'): elif(option == 'predelay'):
sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False) sysvals.predelay = getArgInt('predelay', value, 0, 60000, False)
elif(opt.lower() == 'postdelay'): elif(option == 'postdelay'):
sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False) sysvals.postdelay = getArgInt('postdelay', value, 0, 60000, False)
elif(opt.lower() == 'maxdepth'): elif(option == 'maxdepth'):
sysvals.max_graph_depth = getArgInt('-maxdepth', value, 0, 1000, False) sysvals.max_graph_depth = getArgInt('maxdepth', value, 0, 1000, False)
elif(opt.lower() == 'rtcwake'): elif(option == 'rtcwake'):
if value.lower() == 'off': if value in switchoff:
sysvals.rtcwake = False sysvals.rtcwake = False
else: else:
sysvals.rtcwake = True sysvals.rtcwake = True
sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False) sysvals.rtcwaketime = getArgInt('rtcwake', value, 0, 3600, False)
elif(opt.lower() == 'timeprec'): elif(option == 'timeprec'):
sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False)) sysvals.setPrecision(getArgInt('timeprec', value, 0, 6, False))
elif(opt.lower() == 'mindev'): elif(option == 'mindev'):
sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False) sysvals.mindevlen = getArgFloat('mindev', value, 0.0, 10000.0, False)
elif(opt.lower() == 'callloop-maxgap'): elif(option == 'callloop-maxgap'):
sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False) sysvals.callloopmaxgap = getArgFloat('callloop-maxgap', value, 0.0, 1.0, False)
elif(opt.lower() == 'callloop-maxlen'): elif(option == 'callloop-maxlen'):
sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False) sysvals.callloopmaxgap = getArgFloat('callloop-maxlen', value, 0.0, 1.0, False)
elif(opt.lower() == 'mincg'): elif(option == 'mincg'):
sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False) sysvals.mincglen = getArgFloat('mincg', value, 0.0, 10000.0, False)
elif(opt.lower() == 'output-dir'): elif(option == 'bufsize'):
sysvals.testdir = sysvals.setOutputFolder(value) sysvals.bufsize = getArgInt('bufsize', value, 1, 1024*1024*8, False)
elif(option == 'output-dir'):
sysvals.outdir = sysvals.setOutputFolder(value)
if sysvals.suspendmode == 'command' and not sysvals.testcommand: if sysvals.suspendmode == 'command' and not sysvals.testcommand:
doError('No command supplied for mode "command"') doError('No command supplied for mode "command"')
...@@ -5259,7 +5573,14 @@ def printHelp(): ...@@ -5259,7 +5573,14 @@ def printHelp():
print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)') print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)')
print(' -addlogs Add the dmesg and ftrace logs to the html output') print(' -addlogs Add the dmesg and ftrace logs to the html output')
print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)') print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
print(' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)')
print(' -result fn Export a results table to a text file for parsing.')
print(' [testprep]')
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(' -display on/off Turn the display on or off for the test')
print(' [advanced]') print(' [advanced]')
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"')
print(' -proc Add usermode process info into the timeline (default: disabled)') print(' -proc Add usermode process info into the timeline (default: disabled)')
print(' -dev Add kernel function calls and threads to the timeline (default: disabled)') print(' -dev Add kernel function calls and threads to the timeline (default: disabled)')
...@@ -5280,14 +5601,16 @@ def printHelp(): ...@@ -5280,14 +5601,16 @@ def printHelp():
print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)') print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)')
print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)') print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)') print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
print(' -cgfilter S Filter the callgraph output in the timeline')
print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)')
print(' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)')
print('') print('')
print('Other commands:') print('Other commands:')
print(' -modes List available suspend modes') print(' -modes List available suspend modes')
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(' -sysinfo Print out system info extracted from BIOS') print(' -sysinfo Print out system info extracted from BIOS')
print(' -usbtopo Print out the current USB topology with power info') print(' -devinfo Print out the pm settings of all devices which support runtime suspend')
print(' -usbauto Enable autosuspend for all connected USB devices')
print(' -flist Print the list of functions currently being captured in ftrace') print(' -flist Print the list of functions currently being captured in ftrace')
print(' -flistall Print all functions capable of being captured in ftrace') print(' -flistall Print all functions capable of being captured in ftrace')
print(' -summary directory Create a summary of all test in this dir') print(' -summary directory Create a summary of all test in this dir')
...@@ -5301,9 +5624,9 @@ def printHelp(): ...@@ -5301,9 +5624,9 @@ def printHelp():
# exec start (skipped if script is loaded as library) # exec start (skipped if script is loaded as library)
if __name__ == '__main__': if __name__ == '__main__':
cmd = '' cmd = ''
outdir = '' simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status']
multitest = {'run': False, 'count': 0, 'delay': 0} if '-f' in sys.argv:
simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status'] sysvals.cgskip = sysvals.configFile('cgskip.txt')
# loop through the command line arguments # loop through the command line arguments
args = iter(sys.argv[1:]) args = iter(sys.argv[1:])
for arg in args: for arg in args:
...@@ -5333,6 +5656,10 @@ if __name__ == '__main__': ...@@ -5333,6 +5656,10 @@ if __name__ == '__main__':
sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000) sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
elif(arg == '-f'): elif(arg == '-f'):
sysvals.usecallgraph = True sysvals.usecallgraph = True
elif(arg == '-skiphtml'):
sysvals.skiphtml = True
elif(arg == '-cgdump'):
sysvals.cgdump = True
elif(arg == '-addlogs'): elif(arg == '-addlogs'):
sysvals.dmesglog = sysvals.ftracelog = True sysvals.dmesglog = sysvals.ftracelog = True
elif(arg == '-verbose'): elif(arg == '-verbose'):
...@@ -5341,6 +5668,34 @@ if __name__ == '__main__': ...@@ -5341,6 +5668,34 @@ if __name__ == '__main__':
sysvals.useprocmon = True sysvals.useprocmon = True
elif(arg == '-dev'): elif(arg == '-dev'):
sysvals.usedevsrc = True sysvals.usedevsrc = True
elif(arg == '-sync'):
sysvals.sync = True
elif(arg == '-gzip'):
sysvals.gzip = True
elif(arg == '-rs'):
try:
val = args.next()
except:
doError('-rs requires "enable" or "disable"', True)
if val.lower() in switchvalues:
if val.lower() in switchoff:
sysvals.rs = -1
else:
sysvals.rs = 1
else:
doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True)
elif(arg == '-display'):
try:
val = args.next()
except:
doError('-display requires "on" or "off"', True)
if val.lower() in switchvalues:
if val.lower() in switchoff:
sysvals.display = -1
else:
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'):
...@@ -5348,7 +5703,7 @@ if __name__ == '__main__': ...@@ -5348,7 +5703,7 @@ if __name__ == '__main__':
val = args.next() val = args.next()
except: except:
doError('No rtcwake time supplied', True) doError('No rtcwake time supplied', True)
if val.lower() == 'off': if val.lower() in switchoff:
sysvals.rtcwake = False sysvals.rtcwake = False
else: else:
sysvals.rtcwake = True sysvals.rtcwake = True
...@@ -5359,6 +5714,8 @@ if __name__ == '__main__': ...@@ -5359,6 +5714,8 @@ if __name__ == '__main__':
sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0) sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
elif(arg == '-mincg'): elif(arg == '-mincg'):
sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0) sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
elif(arg == '-bufsize'):
sysvals.bufsize = getArgInt('-bufsize', args, 1, 1024*1024*8)
elif(arg == '-cgtest'): elif(arg == '-cgtest'):
sysvals.cgtest = getArgInt('-cgtest', args, 0, 1) sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
elif(arg == '-cgphase'): elif(arg == '-cgphase'):
...@@ -5368,8 +5725,26 @@ if __name__ == '__main__': ...@@ -5368,8 +5725,26 @@ if __name__ == '__main__':
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.phases:
doError('Invalid phase, valid phaess are %s' % d.phases, True) doError('invalid phase --> (%s: %s), valid phases are %s'\
% (arg, val, d.phases), True)
sysvals.cgphase = val sysvals.cgphase = val
elif(arg == '-cgfilter'):
try:
val = args.next()
except:
doError('No callgraph functions supplied', True)
sysvals.setCallgraphFilter(val)
elif(arg == '-cgskip'):
try:
val = args.next()
except:
doError('No file supplied', True)
if val.lower() in switchoff:
sysvals.cgskip = ''
else:
sysvals.cgskip = sysvals.configFile(val)
if(not sysvals.cgskip):
doError('%s does not exist' % sysvals.cgskip)
elif(arg == '-callloop-maxgap'): elif(arg == '-callloop-maxgap'):
sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0) sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
elif(arg == '-callloop-maxlen'): elif(arg == '-callloop-maxlen'):
...@@ -5386,31 +5761,33 @@ if __name__ == '__main__': ...@@ -5386,31 +5761,33 @@ if __name__ == '__main__':
elif(arg == '-srgap'): elif(arg == '-srgap'):
sysvals.srgap = 5 sysvals.srgap = 5
elif(arg == '-multi'): elif(arg == '-multi'):
multitest['run'] = True sysvals.multitest['run'] = True
multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000) sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000)
multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600) sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600)
elif(arg == '-o'): elif(arg == '-o'):
try: try:
val = args.next() val = args.next()
except: except:
doError('No subdirectory name supplied', True) doError('No subdirectory name supplied', True)
outdir = sysvals.setOutputFolder(val) sysvals.outdir = sysvals.setOutputFolder(val)
elif(arg == '-config'): elif(arg == '-config'):
try: try:
val = args.next() val = args.next()
except: except:
doError('No text file supplied', True) doError('No text file supplied', True)
if(os.path.exists(val) == False): file = sysvals.configFile(val)
if(not file):
doError('%s does not exist' % val) doError('%s does not exist' % val)
configFromFile(val) configFromFile(file)
elif(arg == '-fadd'): elif(arg == '-fadd'):
try: try:
val = args.next() val = args.next()
except: except:
doError('No text file supplied', True) doError('No text file supplied', True)
if(os.path.exists(val) == False): file = sysvals.configFile(val)
if(not file):
doError('%s does not exist' % val) doError('%s does not exist' % val)
sysvals.addFtraceFilterFunctions(val) sysvals.addFtraceFilterFunctions(file)
elif(arg == '-dmesg'): elif(arg == '-dmesg'):
try: try:
val = args.next() val = args.next()
...@@ -5435,7 +5812,7 @@ if __name__ == '__main__': ...@@ -5435,7 +5812,7 @@ if __name__ == '__main__':
except: except:
doError('No directory supplied', True) doError('No directory supplied', True)
cmd = 'summary' cmd = 'summary'
outdir = val sysvals.outdir = val
sysvals.notestrun = True sysvals.notestrun = True
if(os.path.isdir(val) == False): if(os.path.isdir(val) == False):
doError('%s is not accesible' % val) doError('%s is not accesible' % val)
...@@ -5445,6 +5822,12 @@ if __name__ == '__main__': ...@@ -5445,6 +5822,12 @@ if __name__ == '__main__':
except: except:
doError('No devnames supplied', True) doError('No devnames supplied', True)
sysvals.setDeviceFilter(val) sysvals.setDeviceFilter(val)
elif(arg == '-result'):
try:
val = args.next()
except:
doError('No result file supplied', True)
sysvals.result = val
else: else:
doError('Invalid argument: '+arg, True) doError('Invalid argument: '+arg, True)
...@@ -5454,42 +5837,48 @@ if __name__ == '__main__': ...@@ -5454,42 +5837,48 @@ if __name__ == '__main__':
if(sysvals.usecallgraph and sysvals.useprocmon): if(sysvals.usecallgraph and sysvals.useprocmon):
doError('-proc is not compatible with -f') doError('-proc is not compatible with -f')
if sysvals.usecallgraph and sysvals.cgskip:
sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip)
sysvals.setCallgraphBlacklist(sysvals.cgskip)
# callgraph size cannot exceed device size # callgraph size cannot exceed device size
if sysvals.mincglen < sysvals.mindevlen: if sysvals.mincglen < sysvals.mindevlen:
sysvals.mincglen = sysvals.mindevlen sysvals.mincglen = sysvals.mindevlen
# just run a utility command and exit # remove existing buffers before calculating memory
if(sysvals.usecallgraph or sysvals.usedevsrc):
sysvals.fsetVal('16', 'buffer_size_kb')
sysvals.cpuInfo() sysvals.cpuInfo()
# just run a utility command and exit
if(cmd != ''): if(cmd != ''):
if(cmd == 'status'): if(cmd == 'status'):
statusCheck(True) statusCheck(True)
elif(cmd == 'fpdt'): elif(cmd == 'fpdt'):
getFPDT(True) getFPDT(True)
elif(cmd == 'sysinfo'): elif(cmd == 'sysinfo'):
sysvals.printSystemInfo() sysvals.printSystemInfo(True)
elif(cmd == 'usbtopo'): elif(cmd == 'devinfo'):
detectUSB() deviceInfo()
elif(cmd == 'modes'): elif(cmd == 'modes'):
print getModes() print getModes()
elif(cmd == 'flist'): elif(cmd == 'flist'):
sysvals.getFtraceFilterFunctions(True) sysvals.getFtraceFilterFunctions(True)
elif(cmd == 'flistall'): elif(cmd == 'flistall'):
sysvals.getFtraceFilterFunctions(False) sysvals.getFtraceFilterFunctions(False)
elif(cmd == 'usbauto'):
setUSBDevicesAuto()
elif(cmd == 'summary'): elif(cmd == 'summary'):
runSummary(outdir, True) runSummary(sysvals.outdir, True)
sys.exit() sys.exit()
# if instructed, re-analyze existing data files # if instructed, re-analyze existing data files
if(sysvals.notestrun): if(sysvals.notestrun):
rerunTest() stamp = rerunTest()
sysvals.outputResult(stamp)
sys.exit() sys.exit()
# verify that we can run a test # verify that we can run a test
if(not statusCheck()): if(not statusCheck()):
print('Check FAILED, aborting the test run!') doError('Check FAILED, aborting the test run!')
sys.exit()
# extract mem modes and convert # extract mem modes and convert
mode = sysvals.suspendmode mode = sysvals.suspendmode
...@@ -5509,25 +5898,35 @@ if __name__ == '__main__': ...@@ -5509,25 +5898,35 @@ if __name__ == '__main__':
sysvals.systemInfo(dmidecode(sysvals.mempath)) sysvals.systemInfo(dmidecode(sysvals.mempath))
if multitest['run']: setRuntimeSuspend(True)
if sysvals.display:
call('xset -d :0.0 dpms 0 0 0', shell=True)
call('xset -d :0.0 s off', shell=True)
if sysvals.multitest['run']:
# run multiple tests in a separate subdirectory # run multiple tests in a separate subdirectory
if not outdir: if not sysvals.outdir:
s = 'suspend-x%d' % multitest['count'] s = 'suspend-x%d' % sysvals.multitest['count']
outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S') sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
if not os.path.isdir(outdir): if not os.path.isdir(sysvals.outdir):
os.mkdir(outdir) os.mkdir(sysvals.outdir)
for i in range(multitest['count']): for i in range(sysvals.multitest['count']):
if(i != 0): if(i != 0):
print('Waiting %d seconds...' % (multitest['delay'])) print('Waiting %d seconds...' % (sysvals.multitest['delay']))
time.sleep(multitest['delay']) time.sleep(sysvals.multitest['delay'])
print('TEST (%d/%d) START' % (i+1, 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(outdir, datetime.now().strftime(fmt)) sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
runTest() runTest(i+1)
print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
runSummary(outdir, False) sysvals.logmsg = ''
if not sysvals.skiphtml:
runSummary(sysvals.outdir, False)
sysvals.sudouser(sysvals.outdir)
else: else:
if outdir: if sysvals.outdir:
sysvals.testdir = outdir sysvals.testdir = sysvals.outdir
# run the test in the current directory # run the test in the current directory
runTest() runTest()
if sysvals.display:
call('xset -d :0.0 s reset', shell=True)
setRuntimeSuspend(False)
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