Commit 103cf0e5 authored by Rafael J. Wysocki's avatar Rafael J. Wysocki

Merge branches 'pm-cpuidle' and 'pm-tools'

* pm-cpuidle:
  cpuidle: poll_state: Avoid invoking local_clock() too often
  PM: cpuidle/suspend: Add s2idle usage and time state attributes
  cpuidle: Enable coupled cpuidle support on Exynos3250 platform
  cpuidle: poll_state: Add time limit to poll_idle()
  ARM: cpuidle: Drop memory allocation error message from arm_idle_init_cpu()

* pm-tools:
  pm-graph: AnalyzeSuspend v5.0
  pm-graph: AnalyzeBoot v2.2
  pm-graph: config files and installer
......@@ -198,6 +198,31 @@ Description:
time (in microseconds) this cpu should spend in this idle state
to make the transition worth the effort.
What: /sys/devices/system/cpu/cpuX/cpuidle/stateN/s2idle/
Date: March 2018
KernelVersion: v4.17
Contact: Linux power management list <linux-pm@vger.kernel.org>
Description:
Idle state usage statistics related to suspend-to-idle.
This attribute group is only present for states that can be
used in suspend-to-idle with suspended timekeeping.
What: /sys/devices/system/cpu/cpuX/cpuidle/stateN/s2idle/time
Date: March 2018
KernelVersion: v4.17
Contact: Linux power management list <linux-pm@vger.kernel.org>
Description:
Total time spent by the CPU in suspend-to-idle (with scheduler
tick suspended) after requesting this state.
What: /sys/devices/system/cpu/cpuX/cpuidle/stateN/s2idle/usage
Date: March 2018
KernelVersion: v4.17
Contact: Linux power management list <linux-pm@vger.kernel.org>
Description:
Total number of times this state has been requested by the CPU
while entering suspend-to-idle.
What: /sys/devices/system/cpu/cpu#/cpufreq/*
Date: pre-git history
......
......@@ -129,7 +129,6 @@ static int __init arm_idle_init_cpu(int cpu)
dev = kzalloc(sizeof(*dev), GFP_KERNEL);
if (!dev) {
pr_err("Failed to allocate cpuidle device\n");
ret = -ENOMEM;
goto out_unregister_drv;
}
......
......@@ -117,7 +117,8 @@ static int exynos_cpuidle_probe(struct platform_device *pdev)
int ret;
if (IS_ENABLED(CONFIG_SMP) &&
of_machine_is_compatible("samsung,exynos4210")) {
(of_machine_is_compatible("samsung,exynos4210") ||
of_machine_is_compatible("samsung,exynos3250"))) {
exynos_cpuidle_pdata = pdev->dev.platform_data;
ret = cpuidle_register(&exynos_coupled_idle_driver,
......
......@@ -131,6 +131,10 @@ int cpuidle_find_deepest_state(struct cpuidle_driver *drv,
static void enter_s2idle_proper(struct cpuidle_driver *drv,
struct cpuidle_device *dev, int index)
{
ktime_t time_start, time_end;
time_start = ns_to_ktime(local_clock());
/*
* trace_suspend_resume() called by tick_freeze() for the last CPU
* executing it contains RCU usage regarded as invalid in the idle
......@@ -152,6 +156,11 @@ static void enter_s2idle_proper(struct cpuidle_driver *drv,
*/
RCU_NONIDLE(tick_unfreeze());
start_critical_timings();
time_end = ns_to_ktime(local_clock());
dev->states_usage[index].s2idle_time += ktime_us_delta(time_end, time_start);
dev->states_usage[index].s2idle_usage++;
}
/**
......
......@@ -6,15 +6,30 @@
#include <linux/cpuidle.h>
#include <linux/sched.h>
#include <linux/sched/clock.h>
#include <linux/sched/idle.h>
#define POLL_IDLE_TIME_LIMIT (TICK_NSEC / 16)
#define POLL_IDLE_RELAX_COUNT 200
static int __cpuidle poll_idle(struct cpuidle_device *dev,
struct cpuidle_driver *drv, int index)
{
u64 time_start = local_clock();
local_irq_enable();
if (!current_set_polling_and_test()) {
while (!need_resched())
unsigned int loop_count = 0;
while (!need_resched()) {
cpu_relax();
if (loop_count++ < POLL_IDLE_RELAX_COUNT)
continue;
loop_count = 0;
if (local_clock() - time_start > POLL_IDLE_TIME_LIMIT)
break;
}
}
current_clr_polling();
......
......@@ -330,6 +330,58 @@ struct cpuidle_state_kobj {
struct kobject kobj;
};
#ifdef CONFIG_SUSPEND
#define define_show_state_s2idle_ull_function(_name) \
static ssize_t show_state_s2idle_##_name(struct cpuidle_state *state, \
struct cpuidle_state_usage *state_usage, \
char *buf) \
{ \
return sprintf(buf, "%llu\n", state_usage->s2idle_##_name);\
}
define_show_state_s2idle_ull_function(usage);
define_show_state_s2idle_ull_function(time);
#define define_one_state_s2idle_ro(_name, show) \
static struct cpuidle_state_attr attr_s2idle_##_name = \
__ATTR(_name, 0444, show, NULL)
define_one_state_s2idle_ro(usage, show_state_s2idle_usage);
define_one_state_s2idle_ro(time, show_state_s2idle_time);
static struct attribute *cpuidle_state_s2idle_attrs[] = {
&attr_s2idle_usage.attr,
&attr_s2idle_time.attr,
NULL
};
static const struct attribute_group cpuidle_state_s2idle_group = {
.name = "s2idle",
.attrs = cpuidle_state_s2idle_attrs,
};
static void cpuidle_add_s2idle_attr_group(struct cpuidle_state_kobj *kobj)
{
int ret;
if (!kobj->state->enter_s2idle)
return;
ret = sysfs_create_group(&kobj->kobj, &cpuidle_state_s2idle_group);
if (ret)
pr_debug("%s: sysfs attribute group not created\n", __func__);
}
static void cpuidle_remove_s2idle_attr_group(struct cpuidle_state_kobj *kobj)
{
if (kobj->state->enter_s2idle)
sysfs_remove_group(&kobj->kobj, &cpuidle_state_s2idle_group);
}
#else
static inline void cpuidle_add_s2idle_attr_group(struct cpuidle_state_kobj *kobj) { }
static inline void cpuidle_remove_s2idle_attr_group(struct cpuidle_state_kobj *kobj) { }
#endif /* CONFIG_SUSPEND */
#define kobj_to_state_obj(k) container_of(k, struct cpuidle_state_kobj, kobj)
#define kobj_to_state(k) (kobj_to_state_obj(k)->state)
#define kobj_to_state_usage(k) (kobj_to_state_obj(k)->state_usage)
......@@ -383,6 +435,7 @@ static struct kobj_type ktype_state_cpuidle = {
static inline void cpuidle_free_state_kobj(struct cpuidle_device *device, int i)
{
cpuidle_remove_s2idle_attr_group(device->kobjs[i]);
kobject_put(&device->kobjs[i]->kobj);
wait_for_completion(&device->kobjs[i]->kobj_unregister);
kfree(device->kobjs[i]);
......@@ -417,6 +470,7 @@ static int cpuidle_add_state_sysfs(struct cpuidle_device *device)
kfree(kobj);
goto error_state;
}
cpuidle_add_s2idle_attr_group(kobj);
kobject_uevent(&kobj->kobj, KOBJ_ADD);
device->kobjs[i] = kobj;
}
......
......@@ -33,6 +33,10 @@ struct cpuidle_state_usage {
unsigned long long disable;
unsigned long long usage;
unsigned long long time; /* in US */
#ifdef CONFIG_SUSPEND
unsigned long long s2idle_usage;
unsigned long long s2idle_time; /* in US */
#endif
};
struct cpuidle_state {
......
......@@ -7,11 +7,24 @@ all:
install : uninstall
install -d $(DESTDIR)$(PREFIX)/lib/pm-graph
install analyze_suspend.py $(DESTDIR)$(PREFIX)/lib/pm-graph
install analyze_boot.py $(DESTDIR)$(PREFIX)/lib/pm-graph
install sleepgraph.py $(DESTDIR)$(PREFIX)/lib/pm-graph
install bootgraph.py $(DESTDIR)$(PREFIX)/lib/pm-graph
install -d $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/cgskip.txt $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/freeze-callgraph.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/freeze.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/freeze-dev.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/standby-callgraph.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/standby.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/standby-dev.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/suspend-callgraph.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/suspend.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/suspend-dev.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
install -m 644 config/suspend-x2-proc.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config
ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_boot.py $(DESTDIR)$(PREFIX)/bin/bootgraph
ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_suspend.py $(DESTDIR)$(PREFIX)/bin/sleepgraph
install -d $(DESTDIR)$(PREFIX)/bin
ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/bootgraph.py $(DESTDIR)$(PREFIX)/bin/bootgraph
ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/sleepgraph.py $(DESTDIR)$(PREFIX)/bin/sleepgraph
install -d $(DESTDIR)$(PREFIX)/share/man/man8
install bootgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8
......@@ -24,9 +37,11 @@ uninstall :
rm -f $(DESTDIR)$(PREFIX)/bin/bootgraph
rm -f $(DESTDIR)$(PREFIX)/bin/sleepgraph
rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_boot.py
rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_suspend.py
rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/*.pyc
rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/config/*
if [ -d $(DESTDIR)$(PREFIX)/lib/pm-graph/config ] ; then \
rmdir $(DESTDIR)$(PREFIX)/lib/pm-graph/config; \
fi;
rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/*
if [ -d $(DESTDIR)$(PREFIX)/lib/pm-graph ] ; then \
rmdir $(DESTDIR)$(PREFIX)/lib/pm-graph; \
fi;
......@@ -37,6 +37,9 @@ Print the current tool version
Add the dmesg log to the html output. It will be viewable by
clicking a button in the timeline.
.TP
\fB-result \fIfile\fR
Export a results table to a text file for parsing.
.TP
\fB-o \fIname\fR
Overrides the output subdirectory name when running a new test.
Use {date}, {time}, {hostname} for current values.
......@@ -44,14 +47,14 @@ Use {date}, {time}, {hostname} for current values.
e.g. boot-{hostname}-{date}-{time}
.SS "advanced"
.TP
\fB-f\fR
Use ftrace to add function detail (default: disabled)
.TP
\fB-callgraph\fR
\fB-f or -callgraph\fR
Use ftrace to create initcall callgraphs (default: disabled). If -func
is not used there will be one callgraph per initcall. This can produce
very large outputs, i.e. 10MB - 100MB.
.TP
\fB-fstat\fR
Use ftrace to add function detail (default: disabled)
.TP
\fB-maxdepth \fIlevel\fR
limit the callgraph trace depth to \fIlevel\fR (default: 2). This is
the best way to limit the output size when using -callgraph.
......@@ -67,6 +70,13 @@ 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 output in the timeline 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.
(default: none)
.TP
\fB-timeprec \fIn\fR
Number of significant digits in timestamps (0:S, 3:ms, [6:us])
.TP
......
......@@ -32,7 +32,7 @@ import platform
import shutil
from datetime import datetime, timedelta
from subprocess import call, Popen, PIPE
import analyze_suspend as aslib
import sleepgraph as aslib
# ----------------- CLASSES --------------------
......@@ -42,23 +42,18 @@ import analyze_suspend as aslib
# store system values and test parameters
class SystemValues(aslib.SystemValues):
title = 'BootGraph'
version = '2.1'
version = '2.2'
hostname = 'localhost'
testtime = ''
kernel = ''
dmesgfile = ''
ftracefile = ''
htmlfile = 'bootgraph.html'
outfile = ''
testdir = ''
testdirprefix = 'boot'
embedded = False
testlog = False
dmesglog = False
ftracelog = False
kparams = ''
result = ''
useftrace = False
usecallgraph = False
usedevsrc = True
suspendmode = 'boot'
max_graph_depth = 2
graph_filter = 'do_one_initcall'
......@@ -69,11 +64,6 @@ class SystemValues(aslib.SystemValues):
bootloader = 'grub'
blexec = []
def __init__(self):
if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
self.embedded = True
self.dmesglog = True
self.outfile = os.environ['LOG_FILE']
self.htmlfile = os.environ['LOG_FILE']
self.hostname = platform.node()
self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')
if os.path.exists('/proc/version'):
......@@ -148,11 +138,18 @@ class SystemValues(aslib.SystemValues):
cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
args = iter(sys.argv[1:])
for arg in args:
if arg in ['-h', '-v', '-cronjob', '-reboot']:
if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
continue
elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
args.next()
continue
elif arg == '-result':
cmdline += ' %s "%s"' % (arg, os.path.abspath(args.next()))
continue
elif arg == '-cgskip':
file = self.configFile(args.next())
cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
continue
cmdline += ' '+arg
if self.graph_filter != 'do_one_initcall':
cmdline += ' -func "%s"' % self.graph_filter
......@@ -166,14 +163,6 @@ class SystemValues(aslib.SystemValues):
print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n'
print 'CMDLINE="%s"' % cmdline
sys.exit()
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 blGrub(self):
blcmd = ''
for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
......@@ -199,6 +188,14 @@ class SystemValues(aslib.SystemValues):
self.blGrub()
else:
doError('unknown boot loader: %s' % self.bootloader)
def writeDatafileHeader(self, filename):
self.kparams = open('/proc/cmdline', 'r').read().strip()
fp = open(filename, 'w')
fp.write(self.teststamp+'\n')
fp.write(self.sysstamp+'\n')
fp.write('# command | %s\n' % self.cmdline)
fp.write('# kparams | %s\n' % self.kparams)
fp.close()
sysvals = SystemValues()
......@@ -249,7 +246,7 @@ class Data(aslib.Data):
return name
def deviceMatch(self, pid, cg):
if cg.end - cg.start == 0:
return True
return ''
for p in data.phases:
list = self.dmesg[p]['list']
for devname in list:
......@@ -260,14 +257,25 @@ class Data(aslib.Data):
if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
dev['ftrace'] = cg
self.do_one_initcall = True
return True
return devname
else:
if(cg.start > dev['start'] and cg.end < dev['end']):
if 'ftraces' not in dev:
dev['ftraces'] = []
dev['ftraces'].append(cg)
return True
return False
return devname
return ''
def printDetails(self):
sysvals.vprint('Timeline Details:')
sysvals.vprint(' Host: %s' % sysvals.hostname)
sysvals.vprint(' Kernel: %s' % sysvals.kernel)
sysvals.vprint(' Test time: %s' % sysvals.testtime)
sysvals.vprint(' Boot time: %s' % self.boottime)
for phase in self.phases:
dc = len(self.dmesg[phase]['list'])
sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,
self.dmesg[phase]['start']*1000,
self.dmesg[phase]['end']*1000, dc))
# ----------------- FUNCTIONS --------------------
......@@ -275,6 +283,8 @@ class Data(aslib.Data):
# Description:
# parse a kernel log for boot data
def parseKernelLog():
sysvals.vprint('Analyzing the dmesg data (%s)...' % \
os.path.basename(sysvals.dmesgfile))
phase = 'kernel'
data = Data(0)
data.dmesg['kernel']['start'] = data.start = ktime = 0.0
......@@ -298,6 +308,12 @@ def parseKernelLog():
elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line
continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line
continue
elif re.match(tp.kparamsfmt, line):
tp.kparams = line
continue
idx = line.find('[')
if idx > 1:
line = line[idx:]
......@@ -353,6 +369,17 @@ def parseKernelLog():
# Description:
# Check if trace is available and copy to a temp file
def parseTraceLog(data):
sysvals.vprint('Analyzing the ftrace data (%s)...' % \
os.path.basename(sysvals.ftracefile))
# if available, calculate cgfilter allowable ranges
cgfilter = []
if len(sysvals.cgfilter) > 0:
for p in data.phases:
list = data.dmesg[p]['list']
for i in sysvals.cgfilter:
if i in list:
cgfilter.append([list[i]['start']-0.0001,
list[i]['end']+0.0001])
# parse the trace log
ftemp = dict()
tp = aslib.TestProps()
......@@ -366,7 +393,16 @@ def parseTraceLog(data):
continue
m_time, m_proc, m_pid, m_msg, m_dur = \
m.group('time', 'proc', 'pid', 'msg', 'dur')
if float(m_time) > data.end:
t = float(m_time)
if len(cgfilter) > 0:
allow = False
for r in cgfilter:
if t >= r[0] and t < r[1]:
allow = True
break
if not allow:
continue
if t > data.end:
break
if(m_time and m_pid and m_msg):
t = aslib.FTraceLine(m_time, m_msg, m_dur)
......@@ -378,24 +414,36 @@ def parseTraceLog(data):
key = (m_proc, pid)
if(key not in ftemp):
ftemp[key] = []
ftemp[key].append(aslib.FTraceCallGraph(pid))
ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
cg = ftemp[key][-1]
if(cg.addLine(t)):
ftemp[key].append(aslib.FTraceCallGraph(pid))
res = cg.addLine(t)
if(res != 0):
ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
if(res == -1):
ftemp[key][-1].addLine(t)
tf.close()
# add the callgraph data to the device hierarchy
for key in ftemp:
proc, pid = key
for cg in 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
if(not cg.postProcess()):
print('Sanity check failed for %s-%d' % (proc, pid))
continue
# match cg data to devices
if not data.deviceMatch(pid, cg):
print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid, cg.start, cg.end)
devname = data.deviceMatch(pid, cg)
if not devname:
kind = 'Orphan'
if cg.partial:
kind = 'Partial'
sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\
(kind, cg.name, proc, pid, cg.start, cg.end))
elif len(cg.list) > 1000000:
print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\
(devname, len(cg.list))
# Function: retrieveLogs
# Description:
......@@ -473,7 +521,7 @@ def createBootGraph(data):
devtl = aslib.Timeline(100, 20)
# write the test title and general info header
devtl.createHeader(sysvals)
devtl.createHeader(sysvals, sysvals.stamp)
# Generate the header for this timeline
t0 = data.start
......@@ -574,12 +622,9 @@ def createBootGraph(data):
data.dmesg[phase]['color'], phase+'_mode', phase[0])
devtl.html += '</div>\n'
if(sysvals.outfile == sysvals.htmlfile):
hf = open(sysvals.htmlfile, 'a')
else:
hf = open(sysvals.htmlfile, 'w')
hf = open(sysvals.htmlfile, 'w')
# add the css if this is not an embedded run
# add the css
extra = '\
.c1 {background:rgba(209,0,0,0.4);}\n\
.c2 {background:rgba(255,102,34,0.4);}\n\
......@@ -597,8 +642,7 @@ def createBootGraph(data):
.fstat td {text-align:left;width:35px;}\n\
.srccall {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
.srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
if(not sysvals.embedded):
aslib.addCSS(hf, sysvals, 1, False, extra)
aslib.addCSS(hf, sysvals, 1, False, extra)
# write the device timeline
hf.write(devtl.html)
......@@ -631,6 +675,9 @@ def createBootGraph(data):
if(sysvals.usecallgraph):
aslib.addCallgraphs(sysvals, hf, data)
# add the test log as a hidden div
if sysvals.testlog and sysvals.logmsg:
hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
# add the dmesg log as a hidden div
if sysvals.dmesglog:
hf.write('<div id="dmesglog" style="display:none;">\n')
......@@ -639,14 +686,9 @@ def createBootGraph(data):
hf.write(line)
hf.write('</div>\n')
if(not sysvals.embedded):
# write the footer and close
aslib.addScriptCode(hf, [data])
hf.write('</body>\n</html>\n')
else:
# embedded out will be loaded in a page, skip the js
hf.write('<div id=bounds style=display:none>%f,%f</div>' % \
(data.start*1000, data.end*1000))
# write the footer and close
aslib.addScriptCode(hf, [data])
hf.write('</body>\n</html>\n')
hf.close()
return True
......@@ -780,6 +822,7 @@ def doError(msg, help=False):
if help == True:
printHelp()
print 'ERROR: %s\n' % msg
sysvals.outputResult({'error':msg})
sys.exit()
# Function: printHelp
......@@ -806,18 +849,21 @@ def printHelp():
print('Options:')
print(' -h Print this help text')
print(' -v Print the current tool version')
print(' -verbose Print extra information during execution and analysis')
print(' -addlogs Add the dmesg log to the html output')
print(' -result fn Export a results table to a text file for parsing.')
print(' -o name Overrides the output subdirectory name when running a new test')
print(' default: boot-{date}-{time}')
print(' [advanced]')
print(' -f Use ftrace to add function detail (default: disabled)')
print(' -callgraph Add callgraph detail, can be very large (default: disabled)')
print(' -fstat Use ftrace to add function detail and statistics (default: disabled)')
print(' -f/-callgraph Add callgraph detail, can be very large (default: disabled)')
print(' -maxdepth N limit the callgraph data to N call levels (default: 2)')
print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])')
print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
print(' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)')
print(' -cgfilter S Filter the callgraph output in the timeline')
print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)')
print(' -bl name Use the following boot loader for kernel params (default: grub)')
print(' -reboot Reboot the machine automatically and generate a new timeline')
print(' -manual Show the steps to generate a new timeline manually (used with -reboot)')
......@@ -837,8 +883,13 @@ if __name__ == '__main__':
# loop through the command line arguments
cmd = ''
testrun = True
switchoff = ['disable', 'off', 'false', '0']
simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
cgskip = ''
if '-f' in sys.argv:
cgskip = sysvals.configFile('cgskip.txt')
args = iter(sys.argv[1:])
mdset = False
for arg in args:
if(arg == '-h'):
printHelp()
......@@ -846,13 +897,17 @@ if __name__ == '__main__':
elif(arg == '-v'):
print("Version %s" % sysvals.version)
sys.exit()
elif(arg == '-verbose'):
sysvals.verbose = True
elif(arg in simplecmds):
cmd = arg[1:]
elif(arg == '-f'):
elif(arg == '-fstat'):
sysvals.useftrace = True
elif(arg == '-callgraph'):
elif(arg == '-callgraph' or arg == '-f'):
sysvals.useftrace = True
sysvals.usecallgraph = True
elif(arg == '-cgdump'):
sysvals.cgdump = True
elif(arg == '-mincg'):
sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
elif(arg == '-cgfilter'):
......@@ -860,7 +915,18 @@ if __name__ == '__main__':
val = args.next()
except:
doError('No callgraph functions supplied', True)
sysvals.setDeviceFilter(val)
sysvals.setCallgraphFilter(val)
elif(arg == '-cgskip'):
try:
val = args.next()
except:
doError('No file supplied', True)
if val.lower() in switchoff:
cgskip = ''
else:
cgskip = sysvals.configFile(val)
if(not cgskip):
doError('%s does not exist' % cgskip)
elif(arg == '-bl'):
try:
val = args.next()
......@@ -872,6 +938,7 @@ if __name__ == '__main__':
elif(arg == '-timeprec'):
sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
elif(arg == '-maxdepth'):
mdset = True
sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
elif(arg == '-func'):
try:
......@@ -902,8 +969,6 @@ if __name__ == '__main__':
doError('No dmesg file supplied', True)
if(os.path.exists(val) == False):
doError('%s does not exist' % val)
if(sysvals.htmlfile == val or sysvals.outfile == val):
doError('Output filename collision')
testrun = False
sysvals.dmesgfile = val
elif(arg == '-o'):
......@@ -912,6 +977,12 @@ if __name__ == '__main__':
except:
doError('No subdirectory name supplied', True)
sysvals.testdir = sysvals.setOutputFolder(val)
elif(arg == '-result'):
try:
val = args.next()
except:
doError('No result file supplied', True)
sysvals.result = val
elif(arg == '-reboot'):
sysvals.reboot = True
elif(arg == '-manual'):
......@@ -947,7 +1018,7 @@ if __name__ == '__main__':
sysvals.getBootLoader()
print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)
elif(cmd == 'sysinfo'):
sysvals.printSystemInfo()
sysvals.printSystemInfo(True)
sys.exit()
# reboot: update grub, setup a cronjob, and reboot
......@@ -963,6 +1034,10 @@ if __name__ == '__main__':
sysvals.manualRebootRequired()
sys.exit()
if sysvals.usecallgraph and cgskip:
sysvals.vprint('Using cgskip file: %s' % cgskip)
sysvals.setCallgraphBlacklist(cgskip)
# cronjob: remove the cronjob, grub changes, and disable ftrace
if sysvals.iscronjob:
updateCron(True)
......@@ -980,29 +1055,23 @@ if __name__ == '__main__':
# process the log data
if sysvals.dmesgfile:
if not mdset:
sysvals.max_graph_depth = 0
data = parseKernelLog()
if(not data.valid):
doError('No initcall data found in %s' % sysvals.dmesgfile)
if sysvals.useftrace and sysvals.ftracefile:
parseTraceLog(data)
if sysvals.cgdump:
data.debugPrint()
sys.exit()
else:
doError('dmesg file required')
print(' Host: %s' % sysvals.hostname)
print(' Test time: %s' % sysvals.testtime)
print(' Boot time: %s' % data.boottime)
print('Kernel Version: %s' % sysvals.kernel)
print(' Kernel start: %.3f' % (data.start * 1000))
print('Usermode start: %.3f' % (data.tUserMode * 1000))
print('Last Init Call: %.3f' % (data.end * 1000))
# handle embedded output logs
if(sysvals.outfile and sysvals.embedded):
fp = open(sysvals.outfile, 'w')
fp.write('pass %s initstart %.3f end %.3f boot %s\n' %
(data.valid, data.tUserMode*1000, data.end*1000, data.boottime))
fp.close()
sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
sysvals.vprint('Command:\n %s' % sysvals.cmdline)
sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams)
data.printDetails()
createBootGraph(data)
# if running as root, change output dir owner to sudo_user
......@@ -1010,3 +1079,7 @@ if __name__ == '__main__':
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'], sysvals.testdir), shell=True)
sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
sysvals.stamp['lastinit'] = data.end * 1000
sysvals.outputResult(sysvals.stamp)
# -----------------------------------------------
# CallGraph function skip list
#
# This file contains a list of functions which are
# meant to be skipped in the callgraph trace. It reduces
# the callgraph html file size by treating these functions
# as leaves with no child calls. It can be editted by
# adding or removing function symbol names.
#
# The sleepgraph tool automatically pulls this file in when
# it is found in the config folder. It can be ignored if
# the tool is called with "-cgskip off".
# -----------------------------------------------
# low level scheduling and timing
up
down_timeout
mutex_lock
down_read
complete_all
schedule_timeout
wake_up_process
msleep
__udelay
ktime_get
# console calls
printk
dev_printk
console_unlock
# memory handling
__kmalloc
__kmalloc_track_caller
kmem_cache_alloc
kmem_cache_alloc_trace
kmem_cache_free
kstrdup
kstrdup_const
kmalloc_slab
new_slab
__slab_alloc
__slab_free
raw_pci_read
pci_read
alloc_pages_current
# debugfs and sysfs setup
debugfs_remove_recursive
debugfs_create_dir
debugfs_create_files
debugfs_create_dir
debugfs_get_inode
sysfs_add_file_mode_ns
sysfs_add_file
sysfs_create_dir_ns
sysfs_create_link
sysfs_create_group
sysfs_create_groups
sysfs_create_bin_file
dpm_sysfs_add
sysfs_create_file_ns
sysfs_merge_group
sysfs_add_link_to_group
sysfs_create_link_sd
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config thisfile.txt
#
[Settings]
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: mem
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: true
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: suspend-{hostname}-{date}-{time}-custom
# Override default timeline entries
# Do not use the internal default functions for timeline entries (default: false)
# Set this to true if you intend to only use the ones defined in this config
override-timeline-functions: true
# Override default dev timeline entries
# Do not use the internal default functions for dev timeline entries (default: false)
# Set this to true if you intend to only use the ones defined in this config
override-dev-timeline-functions: true
[timeline_functions_x86_64]
#
# Function calls to display in the timeline alongside device callbacks.
# The tool has an internal set of these functions which should cover the
# whole of kernel execution, but you can append or override here.
#
# This is a list of kprobes which use both symbol data and function arg data.
# The function calls are displayed on the timeline alongside the device blocks.
# The args are pulled directly from the stack using this architecture's registers
# and stack formatting. Three pieces of info are required. The function name,
# a format string, and an argument list
#
# Entry format:
#
# function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple]
#
# Required Arguments:
#
# function: The symbol name for the function you want probed, this is the
# minimum required for an entry, it will show up as the function
# name with no arguments.
#
# example: _cpu_up:
#
# Optional Arguments:
#
# format: The format to display the data on the timeline in. Use braces to
# enclose the arg names.
#
# example: CPU_ON[{cpu}]
#
# color: The color of the entry block in the timeline. The default color is
# transparent, so the entry shares the phase color. The color is an
# html color string, either a word, or an RGB.
#
# example: [color=#CC00CC]
#
# arglist: A list of arguments from registers/stack addresses. See URL:
# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt
#
# example: cpu=%di:s32
#
# Example: Display cpu resume in the timeline
#
# _cpu_up: CPU_ON[{cpu}] cpu=%di:s32 [color=orange]
#
_cpu_down: CPU_OFF[{cpu}] cpu=%di:s32
_cpu_up: CPU_ON[{cpu}] cpu=%di:s32
sys_sync:
pm_prepare_console:
pm_notifier_call_chain:
freeze_processes:
freeze_kernel_threads:
pm_restrict_gfp_mask:
acpi_suspend_begin:
suspend_console:
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:
[dev_timeline_functions_x86_64]
#
# Dev mode function calls to display inside timeline entries
#
# This is a list of kprobes which use both symbol data and function arg data.
# The function calls are displayed on the timeline alongside the device blocks.
# The args are pulled directly from the stack using this architecture's registers
# and stack formatting. Three pieces of info are required. The function name,
# a format string, and an argument list
#
# Entry format:
#
# function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple]
#
# Required Arguments:
#
# function: The symbol name for the function you want probed, this is the
# minimum required for an entry, it will show up as the function
# name with no arguments.
#
# example: ata_eh_recover:
#
# Optional Arguments:
#
# format: The format to display the data on the timeline in. Use braces to
# enclose the arg names.
#
# example: ata{port}_port_reset
#
# color: The color of the entry block in the timeline. The default color is
# transparent, so the entry shares the phase color. The color is an
# html color string, either a word, or an RGB.
#
# example: [color=#CC00CC]
#
# arglist: A list of arguments from registers/stack addresses. See URL:
# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt
#
# example: port=+36(%di):s32
#
# Example: Display ATA port reset as ataN_port_reset in the timeline
#
# ata_eh_recover: ata{port}_port_reset port=+36(%di):s32
#
msleep: msleep time=%di:s32
schedule_timeout_uninterruptible: schedule_timeout_uninterruptible timeout=%di:s32
schedule_timeout: schedule_timeout timeout=%di:s32
usleep_range: usleep_range min=%di:s32 max=%si:s32
__const_udelay: udelay loops=%di:s32
__mutex_lock_slowpath: mutex_lock_slowpath
ata_eh_recover: ata_eh_recover port=+36(%di):s32
acpi_os_stall:
acpi_resume_power_resources:
acpi_ps_parse_aml:
ext4_sync_fs:
i915_gem_resume:
i915_restore_state:
intel_opregion_setup:
g4x_pre_enable_dp:
vlv_pre_enable_dp:
chv_pre_enable_dp:
g4x_enable_dp:
vlv_enable_dp:
intel_hpd_init:
intel_opregion_register:
intel_dp_detect:
intel_hdmi_detect:
intel_opregion_init:
intel_fbdev_set_suspend:
#
# Generic S3 (Suspend to Mem) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/example.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: mem
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: suspend-{hostname}-{date}-{time}
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: true
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# Skip HTML generation
# Only capture the logs, don't generate the html timeline (default: false)
skiphtml: false
# Sync filesystem before suspend
# run sync before the test, minimizes sys_sync call time (default: false)
sync: true
# Runtime suspend enable/disable
# Enable/disable runtime suspend for all devices, restore all after test (default: no-action)
# rs: disable
# Turn display on/off for test
# Switch the display on/off for the test using xset (default: no-action)
# display: on
# Print results to text file
# Print the status of the test run in the given file (default: no-action)
result: result.txt
# Gzip the log files to save space
# Gzip the generated log files, and read gzipped log files (default: false)
gzip: true
# ---- Advanced Options ----
# Command to execute in lieu of suspend (default: "")
# command: echo mem > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Multiple test runs
# Run N tests D seconds apart, generates separate outputs with a summary (default: false)
# multi: 3 5
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back and display in the same timeline (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 0.001
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Callgraph phase filter
# Only enable callgraphs for one phase, i.e. resume_noirq (default: all)
cgphase: suspend
# Callgraph x2 test filter
# Only enable callgraphs test 0 or 1 when using -x2 (default: 1)
cgtest: 0
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 6
# Device Filter
# show only devices whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
# Add kprobe functions to the timeline
# Add functions to the timeline from a text file (default: no-action)
# fadd: file.txt
#
# Full Callgraph for S2 (Freeze) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/freeze-callgraph.cfg
#
# NOTE: the output of this test is very large (> 30MB)
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: freeze
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: freeze-{hostname}-{date}-{time}-cg
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of freeze (default: "")
# command: echo freeze > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: true
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 6
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Dev S2 (Freeze) test - includes src calls / kernel threads
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/freeze-dev.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: freeze
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: freeze-{hostname}-{date}-{time}-dev
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of freeze (default: "")
# command: echo freeze > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: true
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Generic S2 (Freeze) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/freeze.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: freeze
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: freeze-{hostname}-{date}-{time}
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of freeze (default: "")
# command: echo freeze > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 0.001
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Full Callgraph for S1 (Standby) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/standby-callgraph.cfg
#
# NOTE: the output of this test is very large (> 30MB)
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: standby
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: standby-{hostname}-{date}-{time}-cg
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of standby (default: "")
# command: echo standby > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: true
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 6
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Dev S1 (Standby) test - includes src calls / kernel threads
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/standby-dev.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: standby
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: standby-{hostname}-{date}-{time}-dev
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of standby (default: "")
# command: echo standby > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: true
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Generic S1 (Standby) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/standby.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: standby
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: standby-{hostname}-{date}-{time}
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of standby (default: "")
# command: echo standby > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 0.001
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Full Callgraph for S3 (Suspend to Mem) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/suspend.cfg
#
# NOTE: the output of this test is very large (> 30MB)
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: mem
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: suspend-{hostname}-{date}-{time}-cg
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of suspend (default: "")
# command: echo mem > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 0.001
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: true
# Max graph depth
# limit the callgraph trace to this depth (default: 0 = all)
maxdepth: 5
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 6
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Dev S3 (Suspend to Mem) test - includes src calls / kernel threads
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/suspend-dev.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: mem
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: suspend-{hostname}-{date}-{time}-dev
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of suspend (default: "")
# command: echo mem > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: true
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Proc S3 (Suspend to Mem) x2 test - includes user processes
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/suspend-proc.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: mem
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: suspend-{hostname}-{date}-{time}-x2-proc
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of suspend (default: "")
# command: echo mem > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: true
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: true
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 1000
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 1000
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 1000
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 1
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
#
# Generic S3 (Suspend to Mem) test
#
# This is the configuration file for sleepgraph. It contains
# all the tool arguments so that they don't have to be given on the
# command line. It also includes advanced settings for functions
# and kprobes. It is run like this
#
# sudo ./sleepgraph.py -config config/suspend.cfg
#
[Settings]
# ---- General Options ----
# Verbosity
# print verbose messages (default: false)
verbose: false
# Suspend Mode
# e.g. standby, mem, freeze, disk (default: mem)
mode: mem
# Output Directory Format
# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values
output-dir: suspend-{hostname}-{date}-{time}
# Automatic Wakeup
# Use rtcwake to autoresume after X seconds, or off to disable (default: 15)
rtcwake: 15
# Add Logs
# add the dmesg and ftrace log to the html output (default: false)
addlogs: false
# Suspend/Resume Gap
# insert a small visible gap between suspend and resume on the timeline (default: false)
srgap: false
# ---- Advanced Options ----
# Command to execute in lieu of suspend (default: "")
# command: echo mem > /sys/power/state
# Display user processes
# graph user processes and cpu usage in the timeline (default: false)
proc: false
# Display function calls
# graph source functions in the timeline (default: false)
dev: false
# Back to Back Suspend/Resume
# Run two suspend/resumes back to back (default: false)
x2: false
# Back to Back Suspend Delay
# Time delay between the two test runs in ms (default: 0 ms)
x2delay: 0
# Pre Suspend Delay
# Include an N ms delay before (1st) suspend (default: 0 ms)
predelay: 0
# Post Resume Delay
# Include an N ms delay after (last) resume (default: 0 ms)
postdelay: 0
# Minimum Device Length
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 0.001
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
# Expand Callgraph
# pre-expand the callgraph data in the html output (default: disabled)
expandcg: false
# Minimum Callgraph Length
# provide callgraph data for blocks longer than min (default: 0.001 ms)
mincg: 1
# Timestamp Precision
# Number of significant digits in timestamps (0:S, [3:ms], 6:us)
timeprec: 3
# Device Filter
# show only devs whose name/driver includes one of these strings
# devicefilter: _cpu_up,_cpu_down,i915,usb
......@@ -52,9 +52,32 @@ disable rtcwake and require a user keypress to resume.
\fB-addlogs\fR
Add the dmesg and ftrace logs to the html output. They will be viewable by
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"
.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
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
......@@ -114,6 +137,18 @@ This reduces the html file size as there can be many tiny callgraphs
which are barely visible in the timeline.
The value is a float: e.g. 0.001 represents 1 us.
.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
Only show callgraph data for phase \fIp\fR (e.g. suspend_late).
.TP
......@@ -122,6 +157,9 @@ In an x2 run, only show callgraph data for test \fIn\fR (e.g. 0 or 1).
.TP
\fB-timeprec \fIn\fR
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
.TP
......@@ -144,11 +182,8 @@ Print out the contents of the ACPI Firmware Performance Data Table.
\fB-sysinfo\fR
Print out system info extracted from BIOS. Reads /dev/mem directly instead of going through dmidecode.
.TP
\fB-usbtopo\fR
Print out the current USB topology with power info.
.TP
\fB-usbauto\fR
Enable autosuspend for all connected USB devices.
\fB-devinfo\fR
Print out the pm settings of all devices which support runtime suspend.
.TP
\fB-flist\fR
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.
.PP
Execute a standby with a 15 second wakeup. Change the output folder name.
.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
Execute a freeze with no wakeup (require keypress). Change output folder name.
.IP
......
......@@ -19,7 +19,7 @@
# Home Page
# https://01.org/suspendresume
# Source repo
# https://github.com/01org/pm-graph
# git@github.com:01org/pm-graph
#
# Description:
# This tool is designed to assist kernel and OS developers in optimizing
......@@ -57,6 +57,7 @@ import platform
from datetime import datetime
import struct
import ConfigParser
import gzip
from threading import Thread
from subprocess import call, Popen, PIPE
......@@ -68,8 +69,12 @@ from subprocess import call, Popen, PIPE
# store system values and test parameters
class SystemValues:
title = 'SleepGraph'
version = '4.7'
version = '5.0'
ansi = False
rs = 0
display = 0
gzip = False
sync = False
verbose = False
testlog = True
dmesglog = False
......@@ -78,14 +83,19 @@ class SystemValues:
mincglen = 0.0
cgphase = ''
cgtest = -1
cgskip = ''
multitest = {'run': False, 'count': 0, 'delay': 0}
max_graph_depth = 0
callloopmaxgap = 0.0001
callloopmaxlen = 0.005
bufsize = 0
cpucount = 0
memtotal = 204800
memfree = 204800
srgap = 0
cgexp = False
testdir = ''
outdir = ''
tpath = '/sys/kernel/debug/tracing/'
fpdtpath = '/sys/firmware/acpi/tables/FPDT'
epath = '/sys/kernel/debug/tracing/events/power/'
......@@ -109,22 +119,24 @@ class SystemValues:
dmesgfile = ''
ftracefile = ''
htmlfile = 'output.html'
embedded = False
result = ''
rtcwake = True
rtcwaketime = 15
rtcpath = ''
devicefilter = []
cgfilter = []
stamp = 0
execcount = 1
x2delay = 0
skiphtml = False
usecallgraph = False
usetraceevents = False
usetraceeventsonly = False
usetracemarkers = True
usekprobes = True
usedevsrc = False
useprocmon = False
notestrun = False
cgdump = False
mixedphaseheight = True
devprops = dict()
predelay = 0
......@@ -134,24 +146,33 @@ class SystemValues:
tracertypefmt = '# tracer: (?P<t>.*)'
firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
tracefuncs = {
'sys_sync': dict(),
'pm_prepare_console': dict(),
'pm_notifier_call_chain': dict(),
'freeze_processes': dict(),
'freeze_kernel_threads': dict(),
'pm_restrict_gfp_mask': dict(),
'acpi_suspend_begin': dict(),
'suspend_console': dict(),
'acpi_pm_prepare': dict(),
'syscore_suspend': dict(),
'arch_enable_nonboot_cpus_end': dict(),
'syscore_resume': dict(),
'acpi_pm_finish': dict(),
'resume_console': dict(),
'acpi_pm_end': dict(),
'pm_restore_gfp_mask': dict(),
'thaw_processes': dict(),
'pm_restore_console': dict(),
'sys_sync': {},
'__pm_notifier_call_chain': {},
'pm_prepare_console': {},
'pm_notifier_call_chain': {},
'freeze_processes': {},
'freeze_kernel_threads': {},
'pm_restrict_gfp_mask': {},
'acpi_suspend_begin': {},
'acpi_hibernation_begin': {},
'acpi_hibernation_enter': {},
'acpi_hibernation_leave': {},
'acpi_pm_freeze': {},
'acpi_pm_thaw': {},
'hibernate_preallocate_memory': {},
'create_basic_memory_bitmaps': {},
'swsusp_write': {},
'suspend_console': {},
'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': {
'func':'_cpu_down',
'args_x86_64': {'cpu':'%di:s32'},
......@@ -173,56 +194,54 @@ class SystemValues:
'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
'acpi_os_stall': {'ub': 1},
# ACPI
'acpi_resume_power_resources': dict(),
'acpi_ps_parse_aml': dict(),
'acpi_resume_power_resources': {},
'acpi_ps_parse_aml': {},
# filesystem
'ext4_sync_fs': dict(),
'ext4_sync_fs': {},
# 80211
'iwlagn_mac_start': dict(),
'iwlagn_alloc_bcast_station': dict(),
'iwl_trans_pcie_start_hw': dict(),
'iwl_trans_pcie_start_fw': dict(),
'iwl_run_init_ucode': dict(),
'iwl_load_ucode_wait_alive': dict(),
'iwl_alive_start': dict(),
'iwlagn_mac_stop': dict(),
'iwlagn_mac_suspend': dict(),
'iwlagn_mac_resume': dict(),
'iwlagn_mac_add_interface': dict(),
'iwlagn_mac_remove_interface': dict(),
'iwlagn_mac_change_interface': dict(),
'iwlagn_mac_config': dict(),
'iwlagn_configure_filter': dict(),
'iwlagn_mac_hw_scan': dict(),
'iwlagn_bss_info_changed': dict(),
'iwlagn_mac_channel_switch': dict(),
'iwlagn_mac_flush': dict(),
'iwlagn_mac_start': {},
'iwlagn_alloc_bcast_station': {},
'iwl_trans_pcie_start_hw': {},
'iwl_trans_pcie_start_fw': {},
'iwl_run_init_ucode': {},
'iwl_load_ucode_wait_alive': {},
'iwl_alive_start': {},
'iwlagn_mac_stop': {},
'iwlagn_mac_suspend': {},
'iwlagn_mac_resume': {},
'iwlagn_mac_add_interface': {},
'iwlagn_mac_remove_interface': {},
'iwlagn_mac_change_interface': {},
'iwlagn_mac_config': {},
'iwlagn_configure_filter': {},
'iwlagn_mac_hw_scan': {},
'iwlagn_bss_info_changed': {},
'iwlagn_mac_channel_switch': {},
'iwlagn_mac_flush': {},
# ATA
'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
# i915
'i915_gem_resume': dict(),
'i915_restore_state': dict(),
'intel_opregion_setup': dict(),
'g4x_pre_enable_dp': dict(),
'vlv_pre_enable_dp': dict(),
'chv_pre_enable_dp': dict(),
'g4x_enable_dp': dict(),
'vlv_enable_dp': dict(),
'intel_hpd_init': dict(),
'intel_opregion_register': dict(),
'intel_dp_detect': dict(),
'intel_hdmi_detect': dict(),
'intel_opregion_init': dict(),
'intel_fbdev_set_suspend': dict(),
'i915_gem_resume': {},
'i915_restore_state': {},
'intel_opregion_setup': {},
'g4x_pre_enable_dp': {},
'vlv_pre_enable_dp': {},
'chv_pre_enable_dp': {},
'g4x_enable_dp': {},
'vlv_enable_dp': {},
'intel_hpd_init': {},
'intel_opregion_register': {},
'intel_dp_detect': {},
'intel_hdmi_detect': {},
'intel_opregion_init': {},
'intel_fbdev_set_suspend': {},
}
cgblacklist = []
kprobes = dict()
timeformat = '%.3f'
cmdline = '%s %s' % \
(os.path.basename(sys.argv[0]), string.join(sys.argv[1:], ' '))
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.hostname = platform.node()
if(self.hostname == ''):
......@@ -237,18 +256,36 @@ class SystemValues:
if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
self.ansi = True
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):
if(os.access(self.powerfile, os.W_OK)):
return True
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
def rootUser(self, fatal=False):
if 'USER' in os.environ and os.environ['USER'] == 'root':
return True
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
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):
if num < 0 or num > 6:
return
......@@ -258,15 +295,15 @@ class SystemValues:
n = datetime.now()
args['date'] = n.strftime('%y%m%d')
args['time'] = n.strftime('%H%M%S')
args['hostname'] = self.hostname
args['hostname'] = args['host'] = self.hostname
return value.format(**args)
def setOutputFile(self):
if self.dmesgfile != '':
m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)
if(m):
self.htmlfile = m.group('name')+'.html'
if self.ftracefile != '':
m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
if(m):
self.htmlfile = m.group('name')+'.html'
def systemInfo(self, info):
......@@ -283,16 +320,19 @@ class SystemValues:
c = info['processor-version']
if 'bios-version' in info:
b = info['bios-version']
self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d' % \
(m, p, c, b, self.cpucount, self.memtotal)
def printSystemInfo(self):
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, self.memfree)
def printSystemInfo(self, fatal=False):
self.rootCheck(True)
out = dmidecode(self.mempath, True)
out = dmidecode(self.mempath, fatal)
if len(out) < 1:
return
fmt = '%-24s: %s'
for name in sorted(out):
print fmt % (name, out[name])
print fmt % ('cpucount', ('%d' % self.cpucount))
print fmt % ('memtotal', ('%d kB' % self.memtotal))
print fmt % ('memfree', ('%d kB' % self.memfree))
def cpuInfo(self):
self.cpucount = 0
fp = open('/proc/cpuinfo', 'r')
......@@ -305,7 +345,9 @@ class SystemValues:
m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
if m:
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()
def initTestOutput(self, name):
self.prefix = self.hostname
......@@ -315,39 +357,34 @@ class SystemValues:
testtime = datetime.now().strftime(fmt)
self.teststamp = \
'# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
if(self.embedded):
self.dmesgfile = \
'/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'
self.ftracefile = \
'/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
return
ext = ''
if self.gzip:
ext = '.gz'
self.dmesgfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
self.ftracefile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
self.htmlfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
if not os.path.isdir(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):
self.devicefilter = []
if value:
value = value.split(',')
for i in value:
self.devicefilter.append(i.strip())
self.devicefilter = self.getValueList(value)
def setCallgraphFilter(self, value):
self.cgfilter = self.getValueList(value)
def setCallgraphBlacklist(self, file):
self.cgblacklist = self.listFromFile(file)
def rtcWakeAlarmOn(self):
call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
outD = open(self.rtcpath+'/date', 'r').read().strip()
outT = open(self.rtcpath+'/time', 'r').read().strip()
mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
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
nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()
if nowtime:
nowtime = int(nowtime)
else:
# if hardware time fails, use the software time
nowtime = int(datetime.now().strftime('%s'))
......@@ -369,10 +406,10 @@ class SystemValues:
ktime = m.group('ktime')
fp.close()
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
fp = Popen('dmesg', stdout=PIPE).stdout
op = open(self.dmesgfile, 'a')
for line in fp:
line = line.replace('\r\n', '')
idx = line.find('[')
......@@ -386,11 +423,17 @@ class SystemValues:
op.write(line)
fp.close()
op.close()
def addFtraceFilterFunctions(self, file):
def listFromFile(self, file):
list = []
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()
for i in list:
return list
def addFtraceFilterFunctions(self, file):
for i in self.listFromFile(file):
if len(i) < 2:
continue
self.tracefuncs[i] = dict()
......@@ -399,9 +442,7 @@ class SystemValues:
if not current:
call('cat '+self.tpath+'available_filter_functions', shell=True)
return
fp = open(self.tpath+'available_filter_functions')
master = fp.read().split('\n')
fp.close()
master = self.listFromFile(self.tpath+'available_filter_functions')
for i in self.tracefuncs:
if 'func' in self.tracefuncs[i]:
i = self.tracefuncs[i]['func']
......@@ -410,9 +451,7 @@ class SystemValues:
else:
print self.colorText(i)
def setFtraceFilterFunctions(self, list):
fp = open(self.tpath+'available_filter_functions')
master = fp.read().split('\n')
fp.close()
master = self.listFromFile(self.tpath+'available_filter_functions')
flist = ''
for i in list:
if i not in master:
......@@ -501,6 +540,7 @@ class SystemValues:
rejects = []
# sort kprobes: trace, ub-dev, custom, dev
kpl = [[], [], [], []]
linesout = len(self.kprobes)
for name in sorted(self.kprobes):
res = self.colorText('YES', 32)
if not self.testKprobe(name, self.kprobes[name]):
......@@ -528,17 +568,10 @@ class SystemValues:
for kp in kplist:
kprobeevents += self.kprobeText(kp, self.kprobes[kp])
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:
res = '%d/%d' % (linesack, linesout)
if linesack < linesout:
res = self.colorText(res, 31)
else:
res = self.colorText(res, 32)
print(' working kprobe functions enabled: %s' % res)
check = self.fgetVal('kprobe_events')
linesack = (len(check.split('\n')) - 1) / 2
print(' kprobe functions enabled: %d/%d' % (linesack, linesout))
self.fsetVal('1', 'events/kprobes/enable')
def testKprobe(self, kname, kprobe):
self.fsetVal('0', 'events/kprobes/enable')
......@@ -555,8 +588,7 @@ class SystemValues:
if linesack < linesout:
return False
return True
def fsetVal(self, val, path, mode='w'):
file = self.tpath+path
def setVal(self, val, file, mode='w'):
if not os.path.exists(file):
return False
try:
......@@ -567,8 +599,9 @@ class SystemValues:
except:
return False
return True
def fgetVal(self, path):
file = self.tpath+path
def fsetVal(self, val, path, mode='w'):
return self.setVal(val, self.tpath+path, mode)
def getVal(self, file):
res = ''
if not os.path.exists(file):
return res
......@@ -579,10 +612,13 @@ class SystemValues:
except:
pass
return res
def fgetVal(self, path):
return self.getVal(self.tpath+path)
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('', 'kprobe_events')
self.fsetVal('1024', 'buffer_size_kb')
def setupAllKprobes(self):
for name in self.tracefuncs:
self.defaultKprobe(name, self.tracefuncs[name])
......@@ -599,7 +635,8 @@ class SystemValues:
if name == f:
return True
return False
def initFtrace(self, testing=False):
def initFtrace(self):
self.printSystemInfo(False)
print('INITIALIZING FTRACE...')
# turn trace off
self.fsetVal('0', 'tracing_on')
......@@ -607,17 +644,21 @@ class SystemValues:
# set the trace clock to global
self.fsetVal('global', 'trace_clock')
self.fsetVal('nop', 'current_tracer')
# set trace buffer to a huge value
if self.usecallgraph or self.usedevsrc:
tgtsize = min(self.memtotal / 2, 2*1024*1024)
maxbuf = '%d' % (tgtsize / max(1, self.cpucount))
if self.cpucount < 1 or not self.fsetVal(maxbuf, 'buffer_size_kb'):
self.fsetVal('131072', 'buffer_size_kb')
# set trace buffer to an appropriate value
cpus = max(1, self.cpucount)
if self.bufsize > 0:
tgtsize = self.bufsize
elif self.usecallgraph or self.usedevsrc:
tgtsize = min(self.memfree, 3*1024*1024)
else:
self.fsetVal('16384', 'buffer_size_kb')
# go no further if this is just a status check
if testing:
return
tgtsize = 65536
while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'):
# if the size failed to set, lower it and keep trying
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
if(self.usecallgraph):
# set trace type
......@@ -635,7 +676,7 @@ class SystemValues:
self.fsetVal('graph-time', 'trace_options')
self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
cf = ['dpm_run_callback']
if(self.usetraceeventsonly):
if(self.usetraceevents):
cf += ['dpm_prepare', 'dpm_complete']
for fn in self.tracefuncs:
if 'func' in self.tracefuncs[fn]:
......@@ -688,16 +729,65 @@ class SystemValues:
return str
return '\x1B[%d;40m%s\x1B[m' % (color, str)
def writeDatafileHeader(self, filename, fwdata=[]):
fp = open(filename, 'w')
fp.write(self.teststamp+'\n')
fp.write(self.sysstamp+'\n')
fp = self.openlog(filename, 'w')
fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
if(self.suspendmode == 'mem' or self.suspendmode == 'command'):
for fw in fwdata:
if(fw):
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()
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()
switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
switchoff = ['disable', 'off', 'false', '0']
suspendmodename = {
'freeze': 'Freeze (S0)',
'standby': 'Standby (S1)',
......@@ -826,34 +916,65 @@ class Data:
for phase in self.phases:
self.devicegroups.append([phase])
self.errorinfo = {'suspend':[],'resume':[]}
def extractErrorInfo(self, dmesg):
error = ''
tm = 0.0
for i in range(len(dmesg)):
if 'Call Trace:' in dmesg[i]:
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i])
if not m:
continue
tm = float(m.group('ktime'))
if tm < self.start or tm > self.end:
continue
for j in range(i-10, i+1):
error += dmesg[j]
def extractErrorInfo(self):
lf = sysvals.openlog(sysvals.dmesgfile, 'r')
i = 0
list = []
# sl = start line, et = error time, el = error line
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:
continue
if error:
m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
if m:
error += dmesg[i]
else:
if tm < self.tSuspended:
dir = 'suspend'
else:
dir = 'resume'
error = error.replace('<', '&lt').replace('>', '&gt')
vprint('kernel error found in %s at %f' % (dir, tm))
self.errorinfo[dir].append((tm, error))
t = float(m.group('ktime'))
if t < self.start or t > self.end:
continue
if t < self.tSuspended:
dir = 'suspend'
else:
dir = 'resume'
msg = m.group('msg')
if re.match('-*\[ *cut here *\]-*', msg):
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
error = ''
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
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):
self.start = time
def setEnd(self, time):
......@@ -867,6 +988,14 @@ class Data:
time < d['end']):
return False
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):
for phase in self.phases:
pend = self.dmesg[phase]['end']
......@@ -918,7 +1047,7 @@ class Data:
return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
# this should not happen
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))
return False
# place the call data inside the src element of the tgtdev
......@@ -1054,6 +1183,13 @@ class Data:
if('src' in d):
for e in d['src']:
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):
# trim out any standby or freeze clock time
if(self.tSuspended != self.tResumed):
......@@ -1100,7 +1236,7 @@ class Data:
if self.dmesg[p]['end'] > dev['start']:
dev['end'] = self.dmesg[p]['end']
break
vprint('%s (%s): callback didnt return' % (devname, phase))
sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
def deviceFilter(self, devicefilter):
for phase in self.phases:
list = self.dmesg[phase]['list']
......@@ -1200,15 +1336,15 @@ class Data:
devlist.append(child)
return devlist
def printDetails(self):
vprint('Timeline Details:')
vprint(' test start: %f' % self.start)
vprint('kernel suspend start: %f' % self.tKernSus)
sysvals.vprint('Timeline Details:')
sysvals.vprint(' test start: %f' % self.start)
sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
for phase in self.phases:
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))
vprint(' kernel resume end: %f' % self.tKernRes)
vprint(' test end: %f' % self.end)
sysvals.vprint(' kernel resume end: %f' % self.tKernRes)
sysvals.vprint(' test end: %f' % self.end)
def deviceChildrenAllPhases(self, devname):
devlist = []
for phase in self.phases:
......@@ -1358,14 +1494,21 @@ class Data:
tres.append(t)
# process the events for suspend and resume
if len(proclist) > 0:
vprint('Process Execution:')
sysvals.vprint('Process Execution:')
for ps in proclist:
c = self.addProcessUsageEvent(ps, tsus)
if c > 0:
vprint('%25s (sus): %d' % (ps, c))
sysvals.vprint('%25s (sus): %d' % (ps, c))
c = self.addProcessUsageEvent(ps, tres)
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
# Description:
......@@ -1504,18 +1647,24 @@ class FTraceLine:
# something else (possibly a trace marker)
else:
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):
return len(str)/2
def debugPrint(self, dev=''):
if(self.freturn and self.fcall):
print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
self.depth, self.name, self.length*1000000))
elif(self.freturn):
print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
self.depth, self.name, self.length*1000000))
def debugPrint(self, info=''):
if self.isLeaf():
print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000, info))
elif self.freturn:
print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000, info))
else:
print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
self.depth, self.name, self.length*1000000))
print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000, info))
def startMarker(self):
# Is this the starting line of a suspend?
if not self.fevent:
......@@ -1558,107 +1707,160 @@ class FTraceCallGraph:
depth = 0
pid = 0
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.end = -1.0
self.list = []
self.depth = 0
self.pid = pid
def addLine(self, line, debug=False):
self.sv = sv
def addLine(self, line):
# if this is already invalid, just leave
if(self.invalid):
return False
# invalidate on too much data or bad depth
if(len(self.list) >= 1000000 or self.depth < 0):
if(line.depth == 0 and line.freturn):
return 1
return 0
# invalidate on bad depth
if(self.depth < 0):
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
prelinedep = line.depth
if(line.freturn and not line.fcall):
if line.isReturn():
prelinedep += 1
last = 0
lasttime = line.time
virtualfname = 'missing_function_name'
if len(self.list) > 0:
last = self.list[-1]
lasttime = last.time
if last.isLeaf():
lasttime += last.length
# handle low misalignments by inserting returns
if prelinedep < self.depth:
if debug and last:
print '-------- task %d --------' % self.pid
last.debugPrint()
mismatch = prelinedep - self.depth
warning = self.sv.verbose and abs(mismatch) > 1
info = []
if mismatch < 0:
idx = 0
# add return calls to get the depth down
while prelinedep < self.depth:
if debug:
print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
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
last.depth = self.depth
last.freturn = True
last.length = line.time - last.time
if debug:
last.debugPrint()
if warning:
info.append(('[make leaf]', last))
else:
vline = FTraceLine(lasttime)
vline.depth = self.depth
vline.name = virtualfname
vline.name = self.vfname
vline.freturn = True
self.list.append(vline)
if debug:
vline.debugPrint()
if warning:
if idx == 0:
info.append(('', last))
info.append(('[add return]', vline))
idx += 1
if debug:
line.debugPrint()
print ''
if warning:
info.append(('', line))
# handle high misalignments by inserting calls
elif prelinedep > self.depth:
if debug and last:
print '-------- task %d --------' % self.pid
last.debugPrint()
elif mismatch > 0:
idx = 0
if warning:
info.append(('', last))
# add calls to get the depth up
while prelinedep > self.depth:
if debug:
print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
if idx == 0 and line.freturn and not line.fcall:
if idx == 0 and line.isReturn():
# special case, turn this return into a leaf
line.fcall = True
prelinedep -= 1
if warning:
info.append(('[make leaf]', line))
else:
vline = FTraceLine(lasttime)
vline.depth = self.depth
vline.name = virtualfname
vline.name = self.vfname
vline.fcall = True
if debug:
vline.debugPrint()
self.list.append(vline)
self.depth += 1
if not last:
self.start = vline.time
if warning:
info.append(('[add call]', vline))
idx += 1
if debug:
line.debugPrint()
print ''
if warning and ('[make leaf]', line) not in info:
info.append(('', line))
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
if(line.fcall and not line.freturn):
self.depth += 1
elif(line.freturn and not line.fcall):
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
elif line.isReturn():
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:
self.start = line.time
self.list.append(line)
# 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)
if(line.depth == 0 and line.freturn):
if(self.start < 0):
self.start = line.time
self.end = line.time
if line.fcall:
self.end += line.length
if self.list[0].name == virtualfname:
if self.list[0].name == self.vfname:
self.invalid = True
return True
return False
if res == -1:
self.partial = True
return res
return 0
def invalidate(self, line):
if(len(self.list) > 0):
first = self.list[0]
......@@ -1668,29 +1870,30 @@ class FTraceCallGraph:
id = 'task %s' % (self.pid)
window = '(%f - %f)' % (self.start, line.time)
if(self.depth < 0):
vprint('Too much data for '+id+\
print('Data misalignment for '+id+\
' (buffer overflow), ignoring this callback')
else:
vprint('Too much data for '+id+\
print('Too much data for '+id+\
' '+window+', ignoring this callback')
def slice(self, t0, tN):
minicg = FTraceCallGraph(0)
count = -1
firstdepth = 0
def slice(self, dev):
minicg = FTraceCallGraph(dev['pid'], self.sv)
minicg.name = self.name
mydepth = -1
good = False
for l in self.list:
if(l.time < t0 or l.time > tN):
if(l.time < dev['start'] or l.time > dev['end']):
continue
if(count < 0):
if(not l.fcall or l.name == 'dev_driver_string'):
continue
firstdepth = l.depth
count = 0
l.depth -= firstdepth
minicg.addLine(l)
if((count == 0 and l.freturn and l.fcall) or
(count > 0 and l.depth <= 0)):
if mydepth < 0:
if l.name == 'mutex_lock' and l.freturn:
mydepth = l.depth
continue
elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall:
good = True
break
count += 1
l.depth -= mydepth
minicg.addLine(l)
if not good or len(minicg.list) < 1:
return 0
return minicg
def repair(self, enddepth):
# bring the depth back to 0 with additional returns
......@@ -1701,11 +1904,11 @@ class FTraceCallGraph:
t.depth = i
t.freturn = True
fixed = self.addLine(t)
if fixed:
if fixed != 0:
self.end = last.time
return True
return False
def postProcess(self, debug=False):
def postProcess(self):
if len(self.list) > 0:
self.name = self.list[0].name
stack = dict()
......@@ -1714,20 +1917,23 @@ class FTraceCallGraph:
for l in self.list:
# ftrace bug: reported duration is not reliable
# 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:
last.length = l.time - last.time
if(l.fcall and not l.freturn):
if l.isCall():
stack[l.depth] = l
cnt += 1
elif(l.freturn and not l.fcall):
elif l.isReturn():
if(l.depth not in stack):
if debug:
if self.sv.verbose:
print 'Post Process Error: Depth missing'
l.debugPrint()
return False
# 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)
l.length = 0
cnt -= 1
......@@ -1736,13 +1942,13 @@ class FTraceCallGraph:
# trace caught the whole call tree
return True
elif(cnt < 0):
if debug:
if self.sv.verbose:
print 'Post Process Error: Depth is less than 0'
return False
# trace ended before call tree finished
return self.repair(cnt)
def deviceMatch(self, pid, data):
found = False
found = ''
# add the callgraph data to the device hierarchy
borderphase = {
'dpm_prepare': 'suspend_prepare',
......@@ -1756,8 +1962,10 @@ class FTraceCallGraph:
if(pid == dev['pid'] and
self.start <= dev['start'] and
self.end >= dev['end']):
dev['ftrace'] = self.slice(dev['start'], dev['end'])
found = True
cg = self.slice(dev)
if cg:
dev['ftrace'] = cg
found = devname
return found
for p in data.phases:
if(data.dmesg[p]['start'] <= self.start and
......@@ -1769,7 +1977,7 @@ class FTraceCallGraph:
self.start <= dev['start'] and
self.end >= dev['end']):
dev['ftrace'] = self
found = True
found = devname
break
break
return found
......@@ -1793,18 +2001,20 @@ class FTraceCallGraph:
if out:
phase, myname = out
data.dmesg[phase]['list'][myname]['ftrace'] = self
def debugPrint(self):
print('[%f - %f] %s (%d)') % (self.start, self.end, self.name, self.pid)
def debugPrint(self, info=''):
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:
if(l.freturn and l.fcall):
print('%f (%02d): %s(); (%.3f us)' % (l.time, \
l.depth, l.name, l.length*1000000))
elif(l.freturn):
print('%f (%02d): %s} (%.3f us)' % (l.time, \
l.depth, l.name, l.length*1000000))
if l.isLeaf():
print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \
l.depth, l.name, l.length*1000000, info))
elif l.freturn:
print('%f (%02d): %s} (%.3f us)%s' % (l.time, \
l.depth, l.name, l.length*1000000, info))
else:
print('%f (%02d): %s() { (%.3f us)' % (l.time, \
l.depth, l.name, l.length*1000000))
print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \
l.depth, l.name, l.length*1000000, info))
print(' ')
class DevItem:
......@@ -1839,8 +2049,8 @@ class Timeline:
self.rowH = rowheight
self.scaleH = scaleheight
self.html = ''
def createHeader(self, sv):
if(not sv.stamp['time']):
def createHeader(self, sv, stamp):
if(not stamp['time']):
return
self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \
% (sv.title, sv.version)
......@@ -1851,12 +2061,12 @@ class Timeline:
if sv.ftracelog:
self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>'
headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
self.html += headline_stamp.format(sv.stamp['host'], sv.stamp['kernel'],
sv.stamp['mode'], sv.stamp['time'])
if 'man' in sv.stamp and 'plat' in sv.stamp and 'cpu' in sv.stamp:
self.html += headline_stamp.format(stamp['host'], stamp['kernel'],
stamp['mode'], stamp['time'])
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'
self.html += headline_sysinfo.format(sv.stamp['man'],
sv.stamp['plat'], sv.stamp['cpu'])
self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu'])
# Function: getDeviceRows
# Description:
......@@ -2067,12 +2277,16 @@ class Timeline:
class TestProps:
stamp = ''
sysinfo = ''
cmdline = ''
kparams = ''
S0i3 = False
fwdata = []
stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
sysinfofmt = '^# sysinfo .*'
cmdlinefmt = '^# command \| (?P<cmd>.*)'
kparamsfmt = '^# kparams \| (?P<kp>.*)'
ftrace_line_fmt_fg = \
'^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
......@@ -2116,13 +2330,20 @@ class TestProps:
sv.hostname = data.stamp['host']
sv.suspendmode = data.stamp['mode']
if sv.suspendmode == 'command' and sv.ftracefile != '':
modes = ['on', 'freeze', 'standby', 'mem']
out = Popen(['grep', 'suspend_enter', sv.ftracefile],
modes = ['on', 'freeze', 'standby', 'mem', 'disk']
out = Popen(['grep', 'machine_suspend', sv.ftracefile],
stderr=PIPE, stdout=PIPE).stdout.read()
m = re.match('.* suspend_enter\[(?P<mode>.*)\]', out)
if m and m.group('mode') in ['1', '2', '3']:
m = re.match('.* machine_suspend\[(?P<mode>.*)\]', out)
if m and m.group('mode') in ['1', '2', '3', '4']:
sv.suspendmode = modes[int(m.group('mode'))]
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:
sv.stamp = data.stamp
......@@ -2186,47 +2407,43 @@ class ProcessMonitor:
# ----------------- 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
# Description:
# Quickly determine if the ftrace log has some or all of the trace events
# required for primary parsing. Set the usetraceevents and/or
# usetraceeventsonly flags in the global sysvals object
# Quickly determine if the ftrace log has all of the trace events,
# markers, and/or kprobes required for primary parsing.
def doesTraceLogHaveTraceEvents():
# check for kprobes
kpcheck = ['_cal: (', '_cpu_down()']
techeck = sysvals.traceevents[:]
tmcheck = ['SUSPEND START', 'RESUME COMPLETE']
sysvals.usekprobes = False
out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True)
if(out == 0):
sysvals.usekprobes = True
# check for callgraph data on trace event blocks
out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True)
if(out == 0):
sysvals.usekprobes = True
out = Popen(['head', '-1', sysvals.ftracefile],
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
# figure out what level of trace events are supported
sysvals.usetraceeventsonly = True
sysvals.usetraceevents = False
for e in sysvals.traceevents:
out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True)
if(out != 0):
sysvals.usetraceeventsonly = False
if(e == 'suspend_resume' and out == 0):
sysvals.usetraceevents = True
# determine is this log is properly formatted
for e in ['SUSPEND START', 'RESUME COMPLETE']:
out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True)
if(out != 0):
sysvals.usetracemarkers = False
fp = sysvals.openlog(sysvals.ftracefile, 'r')
for line in fp:
# check for kprobes
if not sysvals.usekprobes:
for i in kpcheck:
if i in line:
sysvals.usekprobes = True
# check for all necessary trace events
check = techeck[:]
for i in techeck:
if i in line:
check.remove(i)
techeck = check
# check for all necessary trace markers
check = tmcheck[:]
for i in tmcheck:
if i in line:
check.remove(i)
tmcheck = check
fp.close()
if len(techeck) == 0:
sysvals.usetraceevents = True
else:
sysvals.usetraceevents = False
if len(tmcheck) == 0:
sysvals.usetracemarkers = True
else:
sysvals.usetracemarkers = False
# Function: appendIncompleteTraceLog
# Description:
......@@ -2247,9 +2464,10 @@ def appendIncompleteTraceLog(testruns):
testrun.append(TestRun(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()
tf = open(sysvals.ftracefile, 'r')
tf = sysvals.openlog(sysvals.ftracefile, 'r')
data = 0
for line in tf:
# remove any latent carriage returns
......@@ -2261,6 +2479,9 @@ def appendIncompleteTraceLog(testruns):
elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line
continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line
continue
# determine the trace data type (required for further parsing)
m = re.match(sysvals.tracertypefmt, line)
if(m):
......@@ -2393,11 +2614,14 @@ def appendIncompleteTraceLog(testruns):
# create a callgraph object for the data
if(pid not in testrun[testidx].ftemp):
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
cg = testrun[testidx].ftemp[pid][-1]
if(cg.addLine(t)):
testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
res = cg.addLine(t)
if(res != 0):
testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals))
if(res == -1):
testrun[testidx].ftemp[pid][-1].addLine(t)
tf.close()
for test in testrun:
......@@ -2410,11 +2634,11 @@ def appendIncompleteTraceLog(testruns):
# add the callgraph data to the device hierarchy
for pid in test.ftemp:
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
if(not cg.postProcess()):
id = 'task %s cpu %s' % (pid, m.group('cpu'))
vprint('Sanity check failed for '+\
sysvals.vprint('Sanity check failed for '+\
id+', ignoring this callback')
continue
callstart = cg.start
......@@ -2431,8 +2655,6 @@ def appendIncompleteTraceLog(testruns):
dev['ftrace'] = cg
break
test.data.printDetails()
# Function: parseTraceLog
# Description:
# Analyze an ftrace log output file generated from this app during
......@@ -2441,12 +2663,13 @@ def appendIncompleteTraceLog(testruns):
# The ftrace filename is taken from sysvals
# Output:
# An array of Data objects
def parseTraceLog():
vprint('Analyzing the ftrace data...')
def parseTraceLog(live=False):
sysvals.vprint('Analyzing the ftrace data (%s)...' % \
os.path.basename(sysvals.ftracefile))
if(os.path.exists(sysvals.ftracefile) == False):
doError('%s does not exist' % sysvals.ftracefile)
sysvals.setupAllKprobes()
if not live:
sysvals.setupAllKprobes()
tracewatch = []
if sysvals.usekprobes:
tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
......@@ -2458,7 +2681,7 @@ def parseTraceLog():
testdata = []
testrun = 0
data = 0
tf = open(sysvals.ftracefile, 'r')
tf = sysvals.openlog(sysvals.ftracefile, 'r')
phase = 'suspend_prepare'
for line in tf:
# remove any latent carriage returns
......@@ -2470,6 +2693,9 @@ def parseTraceLog():
elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line
continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line
continue
# firmware line: pull out any firmware data
m = re.match(sysvals.firmwarefmt, line)
if(m):
......@@ -2591,6 +2817,8 @@ def parseTraceLog():
phase = 'suspend_prepare'
if(not isbegin):
data.dmesg[phase]['end'] = t.time
if data.dmesg[phase]['start'] < 0:
data.dmesg[phase]['start'] = data.start
continue
# suspend start
elif(re.match('dpm_suspend\[.*', t.name)):
......@@ -2604,6 +2832,8 @@ def parseTraceLog():
continue
# suspend_noirq start
elif(re.match('dpm_suspend_noirq\[.*', t.name)):
if data.phaseCollision('suspend_noirq', isbegin, line):
continue
phase = 'suspend_noirq'
data.setPhase(phase, t.time, isbegin)
if(not isbegin):
......@@ -2636,6 +2866,8 @@ def parseTraceLog():
continue
# resume_noirq start
elif(re.match('dpm_resume_noirq\[.*', t.name)):
if data.phaseCollision('resume_noirq', isbegin, line):
continue
phase = 'resume_noirq'
data.setPhase(phase, t.time, isbegin)
if(isbegin):
......@@ -2742,11 +2974,14 @@ def parseTraceLog():
key = (m_proc, pid)
if(key not in testrun.ftemp):
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
cg = testrun.ftemp[key][-1]
if(cg.addLine(t)):
testrun.ftemp[key].append(FTraceCallGraph(pid))
res = cg.addLine(t)
if(res != 0):
testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals))
if(res == -1):
testrun.ftemp[key][-1].addLine(t)
tf.close()
if sysvals.suspendmode == 'command':
......@@ -2812,28 +3047,31 @@ def parseTraceLog():
for key in test.ftemp:
proc, pid = 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
if(not cg.postProcess()):
id = 'task %s' % (pid)
vprint('Sanity check failed for '+\
sysvals.vprint('Sanity check failed for '+\
id+', ignoring this callback')
continue
# 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)
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
for sortkey in sorted(sortlist):
cg = sortlist[sortkey]
name = cg.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)
if sysvals.suspendmode == 'command':
for data in testdata:
data.printDetails()
return testdata
# fill in any missing phases
......@@ -2841,7 +3079,7 @@ def parseTraceLog():
lp = data.phases[0]
for p in data.phases:
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):
data.dmesg[p]['start'] = data.dmesg[lp]['end']
if(p == 'resume_machine'):
......@@ -2859,7 +3097,6 @@ def parseTraceLog():
data.fixupInitcallsThatDidntReturn()
if sysvals.usedevsrc:
data.optimizeDevSrc()
data.printDetails()
# x2: merge any overlapping devices between test runs
if sysvals.usedevsrc and len(testdata) > 1:
......@@ -2878,19 +3115,18 @@ def parseTraceLog():
# The dmesg filename is taken from sysvals
# Output:
# An array of empty Data objects with only their dmesgtext attributes set
def loadKernelLog(justtext=False):
vprint('Analyzing the dmesg data...')
def loadKernelLog():
sysvals.vprint('Analyzing the dmesg data (%s)...' % \
os.path.basename(sysvals.dmesgfile))
if(os.path.exists(sysvals.dmesgfile) == False):
doError('%s does not exist' % sysvals.dmesgfile)
if justtext:
dmesgtext = []
# there can be multiple test runs in a single file
tp = TestProps()
tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
testruns = []
data = 0
lf = open(sysvals.dmesgfile, 'r')
lf = sysvals.openlog(sysvals.dmesgfile, 'r')
for line in lf:
line = line.replace('\r\n', '')
idx = line.find('[')
......@@ -2903,6 +3139,9 @@ def loadKernelLog(justtext=False):
elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line
continue
elif re.match(tp.cmdlinefmt, line):
tp.cmdline = line
continue
m = re.match(sysvals.firmwarefmt, line)
if(m):
tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
......@@ -2911,9 +3150,6 @@ def loadKernelLog(justtext=False):
if(not m):
continue
msg = m.group("msg")
if justtext:
dmesgtext.append(line)
continue
if(re.match('PM: Syncing filesystems.*', msg)):
if(data):
testruns.append(data)
......@@ -2934,8 +3170,6 @@ def loadKernelLog(justtext=False):
data.dmesgtext.append(line)
lf.close()
if justtext:
return dmesgtext
if data:
testruns.append(data)
if len(testruns) < 1:
......@@ -2975,7 +3209,7 @@ def parseKernelLog(data):
phase = 'suspend_runtime'
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))
# dmesg phase match table
......@@ -3201,7 +3435,6 @@ def parseKernelLog(data):
for event in actions[name]:
data.newActionGlobal(name, event['begin'], event['end'])
data.printDetails()
if(len(sysvals.devicefilter) > 0):
data.deviceFilter(sysvals.devicefilter)
data.fixupInitcallsThatDidntReturn()
......@@ -3230,9 +3463,9 @@ def callgraphHTML(sv, hf, num, cg, title, color, devid):
else:
fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'
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))
elif(line.freturn):
elif line.freturn:
hf.write(html_func_end)
else:
hf.write(html_func_start.format(num, line.name, flen))
......@@ -3249,7 +3482,7 @@ def addCallgraphs(sv, hf, data):
continue
list = data.dmesg[p]['list']
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
dev = list[devname]
color = 'white'
......@@ -3270,7 +3503,6 @@ def addCallgraphs(sv, hf, data):
for cg in dev['ftraces']:
num = callgraphHTML(sv, hf, num, cg,
name+' &rarr; '+cg.name, color, dev['id'])
hf.write('\n\n </section>\n')
# Function: createHTMLSummarySimple
......@@ -3311,7 +3543,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
sTimeAvg = rTimeAvg = 0.0
mode = ''
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']:
# test average line
if(num > 0):
......@@ -3387,7 +3619,7 @@ def createHTML(testruns):
data.normalizeTime(testruns[-1].tSuspended)
# 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_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>'\
......@@ -3416,20 +3648,17 @@ def createHTML(testruns):
scaleH = 40
# device timeline
vprint('Creating Device Timeline...')
devtl = Timeline(30, scaleH)
# write the test title and general info header
devtl.createHeader(sysvals)
devtl.createHeader(sysvals, testruns[0].stamp)
# Generate the header for this timeline
for data in testruns:
tTotal = data.end - data.start
sktime, rktime = data.getTimeValues()
if(tTotal == 0):
print('ERROR: No timeline data')
sys.exit()
doError('No timeline data')
if(data.tLow > 0):
low_time = '%.0f'%(data.tLow*1000)
if sysvals.suspendmode == 'command':
......@@ -3567,9 +3796,10 @@ def createHTML(testruns):
data.dmesg[b]['color'], '')
for e in data.errorinfo[dir]:
# 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)
devtl.html += html_error.format(right, err)
devtl.html += html_error.format(right, id, type)
for b in sorted(phases[dir]):
# draw the devices for this phase
phaselist = data.dmesg[b]['list']
......@@ -3663,14 +3893,7 @@ def createHTML(testruns):
devtl.html += '</div>\n'
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
hf.write(devtl.html)
......@@ -3701,7 +3924,7 @@ def createHTML(testruns):
data = testruns[sysvals.cgtest]
else:
data = testruns[-1]
if(sysvals.usecallgraph and not sysvals.embedded):
if sysvals.usecallgraph:
addCallgraphs(sysvals, hf, data)
# add the test log as a hidden div
......@@ -3710,7 +3933,7 @@ def createHTML(testruns):
# add the dmesg log as a hidden div
if sysvals.dmesglog and sysvals.dmesgfile:
hf.write('<div id="dmesglog" style="display:none;">\n')
lf = open(sysvals.dmesgfile, 'r')
lf = sysvals.openlog(sysvals.dmesgfile, 'r')
for line in lf:
line = line.replace('<', '&lt').replace('>', '&gt')
hf.write(line)
......@@ -3719,28 +3942,15 @@ def createHTML(testruns):
# add the ftrace log as a hidden div
if sysvals.ftracelog and sysvals.ftracefile:
hf.write('<div id="ftracelog" style="display:none;">\n')
lf = open(sysvals.ftracefile, 'r')
lf = sysvals.openlog(sysvals.ftracefile, 'r')
for line in lf:
hf.write(line)
lf.close()
hf.write('</div>\n')
if(not sysvals.embedded):
# write the footer and close
addScriptCode(hf, testruns)
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')
# write the footer and close
addScriptCode(hf, testruns)
hf.write('</body>\n</html>\n')
hf.close()
return True
......@@ -4149,9 +4359,25 @@ def addScriptCode(hf, testruns):
' win.document.write(html+dt);\n'\
' }\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'\
' 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'\
' }\n'\
' function logWindow(e) {\n'\
......@@ -4219,6 +4445,30 @@ def addScriptCode(hf, testruns):
'</script>\n'
hf.write(script_code);
def setRuntimeSuspend(before=True):
global sysvals
sv = sysvals
if sv.rs == 0:
return
if before:
# runtime suspend disable or enable
if sv.rs > 0:
sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled'
else:
sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled'
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
# Description:
# Execute system suspend through the sysfs interface, then copy the output
......@@ -4227,6 +4477,19 @@ def executeSuspend():
pm = ProcessMonitor()
tp = sysvals.tpath
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
sysvals.initdmesg()
# start ftrace
......@@ -4298,47 +4561,22 @@ def executeSuspend():
pm.stop()
sysvals.fsetVal('0', 'tracing_on')
print('CAPTURING TRACE')
sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata)
call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True)
op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata)
fp = open(tp+'trace', 'r')
for line in fp:
op.write(line)
op.close()
sysvals.fsetVal('', 'trace')
devProps()
# grab a copy of the dmesg output
print('CAPTURING DMESG')
sysvals.writeDatafileHeader(sysvals.dmesgfile, fwdata)
sysvals.getdmesg()
sysvals.getdmesg(fwdata)
# Function: setUSBDevicesAuto
# Description:
# Set the autosuspend control parameter of all USB devices to auto
# This can be dangerous, so use at your own risk, most devices are set
# to always-on since the kernel cant determine if the device can
# 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 ' '
def readFile(file):
if os.path.islink(file):
return os.readlink(file).split('/')[-1]
else:
return sysvals.getVal(file).strip()
# Function: ms2nice
# Description:
......@@ -4346,69 +4584,81 @@ def yesno(val):
# Output:
# The time string, e.g. "1901m16s"
def ms2nice(val):
ms = 0
try:
ms = int(val)
except:
return 0.0
m = ms / 60000
s = (ms / 1000) - (m * 60)
return '%3dm%2ds' % (m, s)
val = int(val)
h = val / 3600000
m = (val / 60000) % 60
s = (val / 1000) % 60
if h > 0:
return '%d:%02d:%02d' % (h, m, s)
if m > 0:
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:
# Detect all the USB hosts and devices currently connected and add
# a list of USB device names to sysvals for better timeline readability
def detectUSB():
field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
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('---------------------------------------------------------------------------------------------')
print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
print(' P = persist across suspend Y/N rSUSPEN = 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('---------------------------------------------------------------------------------------------')
print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
print('---------------------------------------------------------------------------------------------')
def deviceInfo(output=''):
if not output:
print('LEGEND')
print('---------------------------------------------------------------------------------------------')
print(' A = async/sync PM queue (A/S) C = runtime active children')
print(' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)')
print(' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)')
print(' U = runtime usage count')
print('---------------------------------------------------------------------------------------------')
print('DEVICE NAME A R S U C rACTIVE rSUSPEND')
print('---------------------------------------------------------------------------------------------')
res = []
tgtval = 'runtime_status'
lines = dict()
for dirname, dirnames, filenames in os.walk('/sys/devices'):
if(re.match('.*/usb[0-9]*.*', dirname) and
'idVendor' in filenames and 'idProduct' in filenames):
for i in field:
field[i] = Popen(['cat', '%s/%s' % (dirname, i)],
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
name = dirname.split('/')[-1]
for i in power:
power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)],
stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
if(re.match('usb[0-9]*', name)):
first = '%-8s' % name
else:
first = '%8s' % name
print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
(first, field['idVendor'], field['idProduct'], \
field['product'][0:20], field['speed'], \
yesno(power['async']), \
yesno(power['control']), \
yesno(power['persist']), \
yesno(power['runtime_enabled']), \
yesno(power['runtime_status']), \
power['runtime_usage'], \
power['autosuspend'], \
ms2nice(power['runtime_active_time']), \
ms2nice(power['runtime_suspended_time']), \
ms2nice(power['active_duration']), \
ms2nice(power['connected_duration'])))
if(not re.match('.*/power', dirname) or
'control' not in filenames or
tgtval not in filenames):
continue
name = ''
dirname = dirname[:-6]
device = dirname.split('/')[-1]
power = dict()
power[tgtval] = readFile('%s/power/%s' % (dirname, tgtval))
# only list devices which support runtime suspend
if power[tgtval] not in ['active', 'suspended', 'suspending']:
continue
for i in ['product', 'driver', 'subsystem']:
file = '%s/%s' % (dirname, i)
if os.path.exists(file):
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['control']), \
yesno(power['runtime_status']), \
power['runtime_usage'], \
power['runtime_active_kids'], \
ms2nice(power['runtime_active_time']), \
ms2nice(power['runtime_suspended_time']))
for i in sorted(lines):
print lines[i]
return res
# Function: devProps
# Description:
......@@ -4444,7 +4694,7 @@ def devProps(data=0):
msghead = 'Additional data added by AnalyzeSuspend'
alreadystamped = False
tp = TestProps()
tf = open(sysvals.ftracefile, 'r')
tf = sysvals.openlog(sysvals.ftracefile, 'r')
for line in tf:
if msghead in line:
alreadystamped = True
......@@ -4469,7 +4719,7 @@ def devProps(data=0):
if not alreadystamped and sysvals.suspendmode == 'command':
out = '#\n# '+msghead+'\n# Device Properties: '
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')
sysvals.devprops = props
return
......@@ -4526,7 +4776,7 @@ def devProps(data=0):
out = '#\n# '+msghead+'\n# Device Properties: '
for dev in sorted(props):
out += props[dev].out(dev)
with open(sysvals.ftracefile, 'a') as fp:
with sysvals.openlog(sysvals.ftracefile, 'a') as fp:
fp.write(out+'\n')
sysvals.devprops = props
......@@ -4869,20 +5119,12 @@ def statusCheck(probecheck=False):
# what data source are we using
res = 'DMESG'
if(ftgood):
sysvals.usetraceeventsonly = True
sysvals.usetraceevents = False
sysvals.usetraceevents = True
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
if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
if not os.path.exists(sysvals.epath+e):
sysvals.usetraceevents = False
if(sysvals.usetraceevents):
res = 'FTRACE (all trace events found)'
elif(sysvals.usetraceevents):
res = 'DMESG and FTRACE (suspend_resume trace event found)'
print(' timeline data source: %s' % res)
# check if rtcwake
......@@ -4917,6 +5159,7 @@ def doError(msg, help=False):
if(help == True):
printHelp()
print('ERROR: %s\n') % msg
sysvals.outputResult({'error':msg})
sys.exit()
# Function: getArgInt
......@@ -4957,22 +5200,36 @@ def getArgFloat(name, args, min, max, main=True):
doError(name+': value should be between %f and %f' % (min, max), True)
return val
def processData():
def processData(live=False):
print('PROCESSING DATA')
if(sysvals.usetraceeventsonly):
testruns = parseTraceLog()
if(sysvals.usetraceevents):
testruns = parseTraceLog(live)
if sysvals.dmesgfile:
dmesgtext = loadKernelLog(True)
for data in testruns:
data.extractErrorInfo(dmesgtext)
data.extractErrorInfo()
else:
testruns = loadKernelLog()
for data in testruns:
parseKernelLog(data)
if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
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)
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
# Description:
......@@ -4980,37 +5237,36 @@ def processData():
def rerunTest():
if sysvals.ftracefile:
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')
sysvals.setOutputFile()
vprint('Output file: %s' % sysvals.htmlfile)
if os.path.exists(sysvals.htmlfile):
if not os.path.isfile(sysvals.htmlfile):
doError('a directory already exists with this name: %s' % sysvals.htmlfile)
elif not os.access(sysvals.htmlfile, os.W_OK):
doError('missing permission to write to %s' % sysvals.htmlfile)
return processData()
testruns, stamp = processData(False)
return stamp
# Function: runTest
# Description:
# execute a suspend/resume, gather the logs, and generate the output
def runTest():
def runTest(n=0):
# prepare for the test
sysvals.initFtrace()
sysvals.initTestOutput('suspend')
vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
(sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
# execute the test
executeSuspend()
sysvals.cleanupFtrace()
processData()
# if running as root, change output dir owner to sudo_user
if os.path.isdir(sysvals.testdir) 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'], sysvals.testdir), shell=True)
if sysvals.skiphtml:
sysvals.sudouser(sysvals.testdir)
return
testruns, stamp = processData(True)
for data in testruns:
del data
sysvals.sudouser(sysvals.testdir)
sysvals.outputResult(stamp, n)
def find_in_html(html, strs, div=False):
for str in strs:
......@@ -5072,10 +5328,12 @@ def runSummary(subdir, local=True):
# Function: checkArgBool
# Description:
# check if a boolean string value is true or false
def checkArgBool(value):
yes = ['1', 'true', 'yes', 'on']
if value.lower() in yes:
def checkArgBool(name, value):
if value in switchvalues:
if value in switchoff:
return False
return True
doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True)
return False
# Function: configFromFile
......@@ -5091,60 +5349,116 @@ def configFromFile(file):
if 'Settings' in sections:
for opt in Config.options('Settings'):
value = Config.get('Settings', opt).lower()
if(opt.lower() == 'verbose'):
sysvals.verbose = checkArgBool(value)
elif(opt.lower() == 'addlogs'):
sysvals.dmesglog = sysvals.ftracelog = checkArgBool(value)
elif(opt.lower() == 'dev'):
sysvals.usedevsrc = checkArgBool(value)
elif(opt.lower() == 'proc'):
sysvals.useprocmon = checkArgBool(value)
elif(opt.lower() == 'x2'):
if checkArgBool(value):
option = opt.lower()
if(option == 'verbose'):
sysvals.verbose = checkArgBool(option, value)
elif(option == 'addlogs'):
sysvals.dmesglog = sysvals.ftracelog = checkArgBool(option, value)
elif(option == 'dev'):
sysvals.usedevsrc = checkArgBool(option, value)
elif(option == 'proc'):
sysvals.useprocmon = checkArgBool(option, value)
elif(option == 'x2'):
if checkArgBool(option, value):
sysvals.execcount = 2
elif(opt.lower() == 'callgraph'):
sysvals.usecallgraph = checkArgBool(value)
elif(opt.lower() == 'override-timeline-functions'):
overridekprobes = checkArgBool(value)
elif(opt.lower() == 'override-dev-timeline-functions'):
overridedevkprobes = checkArgBool(value)
elif(opt.lower() == 'devicefilter'):
elif(option == 'callgraph'):
sysvals.usecallgraph = checkArgBool(option, value)
elif(option == 'override-timeline-functions'):
overridekprobes = checkArgBool(option, value)
elif(option == 'override-dev-timeline-functions'):
overridedevkprobes = checkArgBool(option, value)
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)
elif(opt.lower() == 'expandcg'):
sysvals.cgexp = checkArgBool(value)
elif(opt.lower() == 'srgap'):
if checkArgBool(value):
elif(option == 'expandcg'):
sysvals.cgexp = checkArgBool(option, value)
elif(option == 'srgap'):
if checkArgBool(option, value):
sysvals.srgap = 5
elif(opt.lower() == 'mode'):
elif(option == 'mode'):
sysvals.suspendmode = value
elif(opt.lower() == 'command'):
elif(option == 'command' or option == 'cmd'):
sysvals.testcommand = value
elif(opt.lower() == 'x2delay'):
sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
elif(opt.lower() == 'predelay'):
sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False)
elif(opt.lower() == 'postdelay'):
sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False)
elif(opt.lower() == 'maxdepth'):
sysvals.max_graph_depth = getArgInt('-maxdepth', value, 0, 1000, False)
elif(opt.lower() == 'rtcwake'):
if value.lower() == 'off':
elif(option == 'x2delay'):
sysvals.x2delay = getArgInt('x2delay', value, 0, 60000, False)
elif(option == 'predelay'):
sysvals.predelay = getArgInt('predelay', value, 0, 60000, False)
elif(option == 'postdelay'):
sysvals.postdelay = getArgInt('postdelay', value, 0, 60000, False)
elif(option == 'maxdepth'):
sysvals.max_graph_depth = getArgInt('maxdepth', value, 0, 1000, False)
elif(option == 'rtcwake'):
if value in switchoff:
sysvals.rtcwake = False
else:
sysvals.rtcwake = True
sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
elif(opt.lower() == 'timeprec'):
sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
elif(opt.lower() == 'mindev'):
sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
elif(opt.lower() == 'callloop-maxgap'):
sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False)
elif(opt.lower() == 'callloop-maxlen'):
sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False)
elif(opt.lower() == 'mincg'):
sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
elif(opt.lower() == 'output-dir'):
sysvals.testdir = sysvals.setOutputFolder(value)
sysvals.rtcwaketime = getArgInt('rtcwake', value, 0, 3600, False)
elif(option == 'timeprec'):
sysvals.setPrecision(getArgInt('timeprec', value, 0, 6, False))
elif(option == 'mindev'):
sysvals.mindevlen = getArgFloat('mindev', value, 0.0, 10000.0, False)
elif(option == 'callloop-maxgap'):
sysvals.callloopmaxgap = getArgFloat('callloop-maxgap', value, 0.0, 1.0, False)
elif(option == 'callloop-maxlen'):
sysvals.callloopmaxgap = getArgFloat('callloop-maxlen', value, 0.0, 1.0, False)
elif(option == 'mincg'):
sysvals.mincglen = getArgFloat('mincg', value, 0.0, 10000.0, False)
elif(option == 'bufsize'):
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:
doError('No command supplied for mode "command"')
......@@ -5259,7 +5573,14 @@ def printHelp():
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(' -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(' -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(' -proc Add usermode process info into the timeline (default: disabled)')
print(' -dev Add kernel function calls and threads to the timeline (default: disabled)')
......@@ -5280,14 +5601,16 @@ def printHelp():
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(' -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('Other commands:')
print(' -modes List available suspend modes')
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(' -sysinfo Print out system info extracted from BIOS')
print(' -usbtopo Print out the current USB topology with power info')
print(' -usbauto Enable autosuspend for all connected USB devices')
print(' -devinfo Print out the pm settings of all devices which support runtime suspend')
print(' -flist Print the list of functions currently being captured in ftrace')
print(' -flistall Print all functions capable of being captured in ftrace')
print(' -summary directory Create a summary of all test in this dir')
......@@ -5301,9 +5624,9 @@ def printHelp():
# exec start (skipped if script is loaded as library)
if __name__ == '__main__':
cmd = ''
outdir = ''
multitest = {'run': False, 'count': 0, 'delay': 0}
simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status']
if '-f' in sys.argv:
sysvals.cgskip = sysvals.configFile('cgskip.txt')
# loop through the command line arguments
args = iter(sys.argv[1:])
for arg in args:
......@@ -5333,6 +5656,10 @@ if __name__ == '__main__':
sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
elif(arg == '-f'):
sysvals.usecallgraph = True
elif(arg == '-skiphtml'):
sysvals.skiphtml = True
elif(arg == '-cgdump'):
sysvals.cgdump = True
elif(arg == '-addlogs'):
sysvals.dmesglog = sysvals.ftracelog = True
elif(arg == '-verbose'):
......@@ -5341,6 +5668,34 @@ if __name__ == '__main__':
sysvals.useprocmon = True
elif(arg == '-dev'):
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'):
sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
elif(arg == '-rtcwake'):
......@@ -5348,7 +5703,7 @@ if __name__ == '__main__':
val = args.next()
except:
doError('No rtcwake time supplied', True)
if val.lower() == 'off':
if val.lower() in switchoff:
sysvals.rtcwake = False
else:
sysvals.rtcwake = True
......@@ -5359,6 +5714,8 @@ if __name__ == '__main__':
sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
elif(arg == '-mincg'):
sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
elif(arg == '-bufsize'):
sysvals.bufsize = getArgInt('-bufsize', args, 1, 1024*1024*8)
elif(arg == '-cgtest'):
sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
elif(arg == '-cgphase'):
......@@ -5368,8 +5725,26 @@ if __name__ == '__main__':
doError('No phase name supplied', True)
d = Data(0)
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
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'):
sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
elif(arg == '-callloop-maxlen'):
......@@ -5386,31 +5761,33 @@ if __name__ == '__main__':
elif(arg == '-srgap'):
sysvals.srgap = 5
elif(arg == '-multi'):
multitest['run'] = True
multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
sysvals.multitest['run'] = True
sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000)
sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600)
elif(arg == '-o'):
try:
val = args.next()
except:
doError('No subdirectory name supplied', True)
outdir = sysvals.setOutputFolder(val)
sysvals.outdir = sysvals.setOutputFolder(val)
elif(arg == '-config'):
try:
val = args.next()
except:
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)
configFromFile(val)
configFromFile(file)
elif(arg == '-fadd'):
try:
val = args.next()
except:
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)
sysvals.addFtraceFilterFunctions(val)
sysvals.addFtraceFilterFunctions(file)
elif(arg == '-dmesg'):
try:
val = args.next()
......@@ -5435,7 +5812,7 @@ if __name__ == '__main__':
except:
doError('No directory supplied', True)
cmd = 'summary'
outdir = val
sysvals.outdir = val
sysvals.notestrun = True
if(os.path.isdir(val) == False):
doError('%s is not accesible' % val)
......@@ -5445,6 +5822,12 @@ if __name__ == '__main__':
except:
doError('No devnames supplied', True)
sysvals.setDeviceFilter(val)
elif(arg == '-result'):
try:
val = args.next()
except:
doError('No result file supplied', True)
sysvals.result = val
else:
doError('Invalid argument: '+arg, True)
......@@ -5454,42 +5837,48 @@ if __name__ == '__main__':
if(sysvals.usecallgraph and sysvals.useprocmon):
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
if 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()
# just run a utility command and exit
if(cmd != ''):
if(cmd == 'status'):
statusCheck(True)
elif(cmd == 'fpdt'):
getFPDT(True)
elif(cmd == 'sysinfo'):
sysvals.printSystemInfo()
elif(cmd == 'usbtopo'):
detectUSB()
sysvals.printSystemInfo(True)
elif(cmd == 'devinfo'):
deviceInfo()
elif(cmd == 'modes'):
print getModes()
elif(cmd == 'flist'):
sysvals.getFtraceFilterFunctions(True)
elif(cmd == 'flistall'):
sysvals.getFtraceFilterFunctions(False)
elif(cmd == 'usbauto'):
setUSBDevicesAuto()
elif(cmd == 'summary'):
runSummary(outdir, True)
runSummary(sysvals.outdir, True)
sys.exit()
# if instructed, re-analyze existing data files
if(sysvals.notestrun):
rerunTest()
stamp = rerunTest()
sysvals.outputResult(stamp)
sys.exit()
# verify that we can run a test
if(not statusCheck()):
print('Check FAILED, aborting the test run!')
sys.exit()
doError('Check FAILED, aborting the test run!')
# extract mem modes and convert
mode = sysvals.suspendmode
......@@ -5509,25 +5898,35 @@ if __name__ == '__main__':
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
if not outdir:
s = 'suspend-x%d' % multitest['count']
outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
if not os.path.isdir(outdir):
os.mkdir(outdir)
for i in range(multitest['count']):
if not sysvals.outdir:
s = 'suspend-x%d' % sysvals.multitest['count']
sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
if not os.path.isdir(sysvals.outdir):
os.mkdir(sysvals.outdir)
for i in range(sysvals.multitest['count']):
if(i != 0):
print('Waiting %d seconds...' % (multitest['delay']))
time.sleep(multitest['delay'])
print('TEST (%d/%d) START' % (i+1, multitest['count']))
print('Waiting %d seconds...' % (sysvals.multitest['delay']))
time.sleep(sysvals.multitest['delay'])
print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count']))
fmt = 'suspend-%y%m%d-%H%M%S'
sysvals.testdir = os.path.join(outdir, datetime.now().strftime(fmt))
runTest()
print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
runSummary(outdir, False)
sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
runTest(i+1)
print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
sysvals.logmsg = ''
if not sysvals.skiphtml:
runSummary(sysvals.outdir, False)
sysvals.sudouser(sysvals.outdir)
else:
if outdir:
sysvals.testdir = outdir
if sysvals.outdir:
sysvals.testdir = sysvals.outdir
# run the test in the current directory
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