diff options
author | Linus Torvalds <torvalds@linux-foundation.org> | 2016-07-26 17:29:07 -0700 |
---|---|---|
committer | Linus Torvalds <torvalds@linux-foundation.org> | 2016-07-26 17:29:07 -0700 |
commit | 6453dbdda30428a3c56568c96fe70ea3612f07e2 (patch) | |
tree | 9a3c6087a2832c36e8c49296fb05f95b877e0111 /scripts/analyze_suspend.py | |
parent | 27b79027bc112a63ad4004eb83c6acacae08a0de (diff) | |
parent | bc841e260c95608921809a2c7481cf6f03bec21a (diff) | |
download | linux-6453dbdda30428a3c56568c96fe70ea3612f07e2.tar.bz2 |
Merge tag 'pm-4.8-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
Pull power management updates from Rafael Wysocki:
"Again, the majority of changes go into the cpufreq subsystem, but
there are no big features this time. The cpufreq changes that stand
out somewhat are the governor interface rework and improvements
related to the handling of frequency tables. Apart from those, there
are fixes and new device/CPU IDs in drivers, cleanups and an
improvement of the new schedutil governor.
Next, there are some changes in the hibernation core, including a fix
for a nasty problem related to the MONITOR/MWAIT usage by CPU offline
during resume from hibernation, a few core improvements related to
memory management during resume, a couple of additional debug features
and cleanups.
Finally, we have some fixes and cleanups in the devfreq subsystem,
generic power domains framework improvements related to system
suspend/resume, support for some new chips in intel_idle and in the
power capping RAPL driver, a new version of the AnalyzeSuspend utility
and some assorted fixes and cleanups.
Specifics:
- Rework the cpufreq governor interface to make it more
straightforward and modify the conservative governor to avoid using
transition notifications (Rafael Wysocki).
- Rework the handling of frequency tables by the cpufreq core to make
it more efficient (Viresh Kumar).
- Modify the schedutil governor to reduce the number of wakeups it
causes to occur in cases when the CPU frequency doesn't need to be
changed (Steve Muckle, Viresh Kumar).
- Fix some minor issues and clean up code in the cpufreq core and
governors (Rafael Wysocki, Viresh Kumar).
- Add Intel Broxton support to the intel_pstate driver (Srinivas
Pandruvada).
- Fix problems related to the config TDP feature and to the validity
of the MSR_HWP_INTERRUPT register in intel_pstate (Jan Kiszka,
Srinivas Pandruvada).
- Make intel_pstate update the cpu_frequency tracepoint even if the
frequency doesn't change to avoid confusing powertop (Rafael
Wysocki).
- Clean up the usage of __init/__initdata in intel_pstate, mark some
of its internal variables as __read_mostly and drop an unused
structure element from it (Jisheng Zhang, Carsten Emde).
- Clean up the usage of some duplicate MSR symbols in intel_pstate
and turbostat (Srinivas Pandruvada).
- Update/fix the powernv, s3c24xx and mvebu cpufreq drivers (Akshay
Adiga, Viresh Kumar, Ben Dooks).
- Fix a regression (introduced during the 4.5 cycle) in the
pcc-cpufreq driver by reverting the problematic commit (Andreas
Herrmann).
- Add support for Intel Denverton to intel_idle, clean up Broxton
support in it and make it explicitly non-modular (Jacob Pan, Jan
Beulich, Paul Gortmaker).
- Add support for Denverton and Ivy Bridge server to the Intel RAPL
power capping driver and make it more careful about the handing of
MSRs that may not be present (Jacob Pan, Xiaolong Wang).
- Fix resume from hibernation on x86-64 by making the CPU offline
during resume avoid using MONITOR/MWAIT in the "play dead" loop
which may lead to an inadvertent "revival" of a "dead" CPU and a
page fault leading to a kernel crash from it (Rafael Wysocki).
- Make memory management during resume from hibernation more
straightforward (Rafael Wysocki).
- Add debug features that should help to detect problems related to
hibernation and resume from it (Rafael Wysocki, Chen Yu).
- Clean up hibernation core somewhat (Rafael Wysocki).
- Prevent KASAN from instrumenting the hibernation core which leads
to large numbers of false-positives from it (James Morse).
- Prevent PM (hibernate and suspend) notifiers from being called
during the cleanup phase if they have not been called during the
corresponding preparation phase which is possible if one of the
other notifiers returns an error at that time (Lianwei Wang).
- Improve suspend-related debug printout in the tasks freezer and
clean up suspend-related console handling (Roger Lu, Borislav
Petkov).
- Update the AnalyzeSuspend script in the kernel sources to version
4.2 (Todd Brandt).
- Modify the generic power domains framework to make it handle system
suspend/resume better (Ulf Hansson).
- Make the runtime PM framework avoid resuming devices synchronously
when user space changes the runtime PM settings for them and
improve its error reporting (Rafael Wysocki, Linus Walleij).
- Fix error paths in devfreq drivers (exynos, exynos-ppmu,
exynos-bus) and in the core, make some devfreq code explicitly
non-modular and change some of it into tristate (Bartlomiej
Zolnierkiewicz, Peter Chen, Paul Gortmaker).
- Add DT support to the generic PM clocks management code and make it
export some more symbols (Jon Hunter, Paul Gortmaker).
- Make the PCI PM core code slightly more robust against possible
driver errors (Andy Shevchenko).
- Make it possible to change DESTDIR and PREFIX in turbostat (Andy
Shevchenko)"
* tag 'pm-4.8-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm: (89 commits)
Revert "cpufreq: pcc-cpufreq: update default value of cpuinfo_transition_latency"
PM / hibernate: Introduce test_resume mode for hibernation
cpufreq: export cpufreq_driver_resolve_freq()
cpufreq: Disallow ->resolve_freq() for drivers providing ->target_index()
PCI / PM: check all fields in pci_set_platform_pm()
cpufreq: acpi-cpufreq: use cached frequency mapping when possible
cpufreq: schedutil: map raw required frequency to driver frequency
cpufreq: add cpufreq_driver_resolve_freq()
cpufreq: intel_pstate: Check cpuid for MSR_HWP_INTERRUPT
intel_pstate: Update cpu_frequency tracepoint every time
cpufreq: intel_pstate: clean remnant struct element
PM / tools: scripts: AnalyzeSuspend v4.2
x86 / hibernate: Use hlt_play_dead() when resuming from hibernation
cpufreq: powernv: Replacing pstate_id with frequency table index
intel_pstate: Fix MSR_CONFIG_TDP_x addressing in core_get_max_pstate()
PM / hibernate: Image data protection during restoration
PM / hibernate: Add missing braces in __register_nosave_region()
PM / hibernate: Clean up comments in snapshot.c
PM / hibernate: Clean up function headers in snapshot.c
PM / hibernate: Add missing braces in hibernate_setup()
...
Diffstat (limited to 'scripts/analyze_suspend.py')
-rwxr-xr-x | scripts/analyze_suspend.py | 3641 |
1 files changed, 2474 insertions, 1167 deletions
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py index 93e1fd40f430..a0ba48fa2c5e 100755 --- a/scripts/analyze_suspend.py +++ b/scripts/analyze_suspend.py @@ -19,6 +19,17 @@ # Authors: # Todd Brandt <todd.e.brandt@linux.intel.com> # +# Links: +# Home Page +# https://01.org/suspendresume +# Source repo +# https://github.com/01org/suspendresume +# Documentation +# Getting Started +# https://01.org/suspendresume/documentation/getting-started +# Command List: +# https://01.org/suspendresume/documentation/command-list +# # Description: # This tool is designed to assist kernel and OS developers in optimizing # their linux stack's suspend/resume time. Using a kernel image built @@ -35,6 +46,8 @@ # CONFIG_FTRACE=y # CONFIG_FUNCTION_TRACER=y # CONFIG_FUNCTION_GRAPH_TRACER=y +# CONFIG_KPROBES=y +# CONFIG_KPROBES_ON_FTRACE=y # # For kernel versions older than 3.15: # The following additional kernel parameters are required: @@ -52,6 +65,7 @@ import re import platform from datetime import datetime import struct +import ConfigParser # ----------------- CLASSES -------------------- @@ -60,8 +74,15 @@ import struct # A global, single-instance container used to # store system values and test parameters class SystemValues: - version = 3.0 + ansi = False + version = '4.2' verbose = False + addlogs = False + mindevlen = 0.001 + mincglen = 1.0 + srgap = 0 + cgexp = False + outdir = '' testdir = '.' tpath = '/sys/kernel/debug/tracing/' fpdtpath = '/sys/firmware/acpi/tables/FPDT' @@ -71,26 +92,21 @@ class SystemValues: 'device_pm_callback_end', 'device_pm_callback_start' ] - modename = { - 'freeze': 'Suspend-To-Idle (S0)', - 'standby': 'Power-On Suspend (S1)', - 'mem': 'Suspend-to-RAM (S3)', - 'disk': 'Suspend-to-disk (S4)' - } + testcommand = '' mempath = '/dev/mem' powerfile = '/sys/power/state' suspendmode = 'mem' hostname = 'localhost' prefix = 'test' teststamp = '' + dmesgstart = 0.0 dmesgfile = '' ftracefile = '' htmlfile = '' + embedded = False rtcwake = False rtcwaketime = 10 rtcpath = '' - android = False - adb = 'adb' devicefilter = [] stamp = 0 execcount = 1 @@ -98,16 +114,90 @@ class SystemValues: usecallgraph = False usetraceevents = False usetraceeventsonly = False + usetracemarkers = True + usekprobes = True + usedevsrc = False notestrun = False - altdevname = dict() + devprops = dict() postresumetime = 0 + devpropfmt = '# Device Properties: .*' tracertypefmt = '# tracer: (?P<t>.*)' firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' postresumefmt = '# post resume time (?P<t>[0-9]*)$' stampfmt = '# suspend-(?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>.*)$' + kprobecolor = 'rgba(204,204,204,0.5)' + synccolor = 'rgba(204,204,204,0.5)' + debugfuncs = [] + 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(), + 'CPU_OFF': { + 'func':'_cpu_down', + 'args_x86_64': {'cpu':'%di:s32'}, + 'format': 'CPU_OFF[{cpu}]', + 'mask': 'CPU_.*_DOWN' + }, + 'CPU_ON': { + 'func':'_cpu_up', + 'args_x86_64': {'cpu':'%di:s32'}, + 'format': 'CPU_ON[{cpu}]', + 'mask': 'CPU_.*_UP' + }, + } + dev_tracefuncs = { + # general wait/delay/sleep + 'msleep': { 'args_x86_64': {'time':'%di:s32'} }, + 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} }, + 'acpi_os_stall': dict(), + # ACPI + 'acpi_resume_power_resources': dict(), + 'acpi_ps_parse_aml': dict(), + # filesystem + 'ext4_sync_fs': dict(), + # ATA + 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} }, + # i915 + 'i915_gem_restore_gtt_mappings': dict(), + 'intel_opregion_setup': dict(), + 'intel_dp_detect': dict(), + 'intel_hdmi_detect': dict(), + 'intel_opregion_init': dict(), + } + kprobes_postresume = [ + { + 'name': 'ataportrst', + 'func': 'ata_eh_recover', + 'args': {'port':'+36(%di):s32'}, + 'format': 'ata{port}_port_reset', + 'mask': 'ata.*_port_reset' + } + ] + kprobes = dict() + timeformat = '%.3f' 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.addlogs = True + self.htmlfile = os.environ['LOG_FILE'] self.hostname = platform.node() if(self.hostname == ''): self.hostname = 'localhost' @@ -118,6 +208,12 @@ class SystemValues: if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \ os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'): self.rtcpath = rtc + if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): + self.ansi = True + def setPrecision(self, num): + if num < 0 or num > 6: + return + self.timeformat = '%.{0}f'.format(num) def setOutputFile(self): if((self.htmlfile == '') and (self.dmesgfile != '')): m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) @@ -129,32 +225,37 @@ class SystemValues: self.htmlfile = m.group('name')+'.html' if(self.htmlfile == ''): self.htmlfile = 'output.html' - def initTestOutput(self, subdir): - if(not self.android): - self.prefix = self.hostname - v = open('/proc/version', 'r').read().strip() - kver = string.split(v)[2] - else: - self.prefix = 'android' - v = os.popen(self.adb+' shell cat /proc/version').read().strip() - kver = string.split(v)[2] - testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S') + def initTestOutput(self, subdir, testpath=''): + self.prefix = self.hostname + v = open('/proc/version', 'r').read().strip() + kver = string.split(v)[2] + n = datetime.now() + testtime = n.strftime('suspend-%m%d%y-%H%M%S') + if not testpath: + testpath = n.strftime('suspend-%y%m%d-%H%M%S') if(subdir != "."): - self.testdir = subdir+"/"+testtime + self.testdir = subdir+"/"+testpath else: - self.testdir = testtime + self.testdir = testpath 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 self.dmesgfile = \ self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' self.ftracefile = \ self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' self.htmlfile = \ self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' - os.mkdir(self.testdir) + if not os.path.isdir(self.testdir): + os.mkdir(self.testdir) def setDeviceFilter(self, devnames): self.devicefilter = string.split(devnames) - def rtcWakeAlarm(self): + def rtcWakeAlarmOn(self): os.system('echo 0 > '+self.rtcpath+'/wakealarm') outD = open(self.rtcpath+'/date', 'r').read().strip() outT = open(self.rtcpath+'/time', 'r').read().strip() @@ -172,9 +273,361 @@ class SystemValues: nowtime = int(datetime.now().strftime('%s')) alarm = nowtime + self.rtcwaketime os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath)) + def rtcWakeAlarmOff(self): + os.system('echo 0 > %s/wakealarm' % self.rtcpath) + def initdmesg(self): + # get the latest time stamp from the dmesg log + fp = os.popen('dmesg') + ktime = '0' + for line in fp: + line = line.replace('\r\n', '') + idx = line.find('[') + if idx > 1: + line = line[idx:] + m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + if(m): + ktime = m.group('ktime') + fp.close() + self.dmesgstart = float(ktime) + def getdmesg(self): + # store all new dmesg lines since initdmesg was called + fp = os.popen('dmesg') + op = open(self.dmesgfile, 'a') + for line in fp: + line = line.replace('\r\n', '') + idx = line.find('[') + if idx > 1: + line = line[idx:] + m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + if(not m): + continue + ktime = float(m.group('ktime')) + if ktime > self.dmesgstart: + op.write(line) + fp.close() + op.close() + def addFtraceFilterFunctions(self, file): + fp = open(file) + list = fp.read().split('\n') + fp.close() + for i in list: + if len(i) < 2: + continue + self.tracefuncs[i] = dict() + def getFtraceFilterFunctions(self, current): + rootCheck(True) + if not current: + os.system('cat '+self.tpath+'available_filter_functions') + return + fp = open(self.tpath+'available_filter_functions') + master = fp.read().split('\n') + fp.close() + if len(self.debugfuncs) > 0: + for i in self.debugfuncs: + if i in master: + print i + else: + print self.colorText(i) + else: + for i in self.tracefuncs: + if 'func' in self.tracefuncs[i]: + i = self.tracefuncs[i]['func'] + if i in master: + print i + else: + print self.colorText(i) + def setFtraceFilterFunctions(self, list): + fp = open(self.tpath+'available_filter_functions') + master = fp.read().split('\n') + fp.close() + flist = '' + for i in list: + if i not in master: + continue + if ' [' in i: + flist += i.split(' ')[0]+'\n' + else: + flist += i+'\n' + fp = open(self.tpath+'set_graph_function', 'w') + fp.write(flist) + fp.close() + def kprobeMatch(self, name, target): + if name not in self.kprobes: + return False + if re.match(self.kprobes[name]['mask'], target): + return True + return False + def basicKprobe(self, name): + self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name,'mask': name} + def defaultKprobe(self, name, kdata): + k = kdata + for field in ['name', 'format', 'mask', 'func']: + if field not in k: + k[field] = name + archargs = 'args_'+platform.machine() + if archargs in k: + k['args'] = k[archargs] + else: + k['args'] = dict() + k['format'] = name + self.kprobes[name] = k + def kprobeColor(self, name): + if name not in self.kprobes or 'color' not in self.kprobes[name]: + return '' + return self.kprobes[name]['color'] + def kprobeDisplayName(self, name, dataraw): + if name not in self.kprobes: + self.basicKprobe(name) + data = '' + quote=0 + # first remvoe any spaces inside quotes, and the quotes + for c in dataraw: + if c == '"': + quote = (quote + 1) % 2 + if quote and c == ' ': + data += '_' + elif c != '"': + data += c + fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args'] + arglist = dict() + # now process the args + for arg in sorted(args): + arglist[arg] = '' + m = re.match('.* '+arg+'=(?P<arg>.*) ', data); + if m: + arglist[arg] = m.group('arg') + else: + m = re.match('.* '+arg+'=(?P<arg>.*)', data); + if m: + arglist[arg] = m.group('arg') + out = fmt.format(**arglist) + out = out.replace(' ', '_').replace('"', '') + return out + def kprobeText(self, kprobe): + name, fmt, func, args = kprobe['name'], kprobe['format'], kprobe['func'], kprobe['args'] + if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func): + doError('Kprobe "%s" has format info in the function name "%s"' % (name, func), False) + for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt): + if arg not in args: + doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False) + val = 'p:%s_cal %s' % (name, func) + for i in sorted(args): + val += ' %s=%s' % (i, args[i]) + val += '\nr:%s_ret %s $retval\n' % (name, func) + return val + def addKprobes(self): + # first test each kprobe + print('INITIALIZING KPROBES...') + rejects = [] + for name in sorted(self.kprobes): + if not self.testKprobe(self.kprobes[name]): + rejects.append(name) + # remove all failed ones from the list + for name in rejects: + vprint('Skipping KPROBE: %s' % name) + self.kprobes.pop(name) + self.fsetVal('', 'kprobe_events') + kprobeevents = '' + # set the kprobes all at once + for kp in self.kprobes: + val = self.kprobeText(self.kprobes[kp]) + vprint('Adding KPROBE: %s\n%s' % (kp, val.strip())) + kprobeevents += self.kprobeText(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')) + linesack = len(check.split('\n')) + if linesack < linesout: + # if not, try appending the kprobes 1 by 1 + for kp in self.kprobes: + kprobeevents = self.kprobeText(self.kprobes[kp]) + self.fsetVal(kprobeevents, 'kprobe_events', 'a') + self.fsetVal('1', 'events/kprobes/enable') + def testKprobe(self, kprobe): + kprobeevents = self.kprobeText(kprobe) + if not kprobeevents: + return False + try: + self.fsetVal(kprobeevents, 'kprobe_events') + check = self.fgetVal('kprobe_events') + except: + return False + linesout = len(kprobeevents.split('\n')) + linesack = len(check.split('\n')) + if linesack < linesout: + return False + return True + def fsetVal(self, val, path, mode='w'): + file = self.tpath+path + if not os.path.exists(file): + return False + try: + fp = open(file, mode) + fp.write(val) + fp.close() + except: + pass + return True + def fgetVal(self, path): + file = self.tpath+path + res = '' + if not os.path.exists(file): + return res + try: + fp = open(file, 'r') + res = fp.read() + fp.close() + except: + pass + return res + def cleanupFtrace(self): + if(self.usecallgraph or self.usetraceevents): + self.fsetVal('0', 'events/kprobes/enable') + self.fsetVal('', 'kprobe_events') + def setupAllKprobes(self): + for name in self.tracefuncs: + self.defaultKprobe(name, self.tracefuncs[name]) + for name in self.dev_tracefuncs: + self.defaultKprobe(name, self.dev_tracefuncs[name]) + def isCallgraphFunc(self, name): + if len(self.debugfuncs) < 1 and self.suspendmode == 'command': + return True + if name in self.debugfuncs: + return True + funclist = [] + for i in self.tracefuncs: + if 'func' in self.tracefuncs[i]: + funclist.append(self.tracefuncs[i]['func']) + else: + funclist.append(i) + if name in funclist: + return True + return False + def initFtrace(self, testing=False): + tp = self.tpath + print('INITIALIZING FTRACE...') + # turn trace off + self.fsetVal('0', 'tracing_on') + self.cleanupFtrace() + # set the trace clock to global + self.fsetVal('global', 'trace_clock') + # set trace buffer to a huge value + self.fsetVal('nop', 'current_tracer') + self.fsetVal('100000', 'buffer_size_kb') + # go no further if this is just a status check + if testing: + return + if self.usekprobes: + # add tracefunc kprobes so long as were not using full callgraph + if(not self.usecallgraph or len(self.debugfuncs) > 0): + for name in self.tracefuncs: + self.defaultKprobe(name, self.tracefuncs[name]) + if self.usedevsrc: + for name in self.dev_tracefuncs: + self.defaultKprobe(name, self.dev_tracefuncs[name]) + else: + self.usedevsrc = False + self.addKprobes() + # initialize the callgraph trace, unless this is an x2 run + if(self.usecallgraph): + # set trace type + self.fsetVal('function_graph', 'current_tracer') + self.fsetVal('', 'set_ftrace_filter') + # set trace format options + self.fsetVal('print-parent', 'trace_options') + self.fsetVal('funcgraph-abstime', 'trace_options') + self.fsetVal('funcgraph-cpu', 'trace_options') + self.fsetVal('funcgraph-duration', 'trace_options') + self.fsetVal('funcgraph-proc', 'trace_options') + self.fsetVal('funcgraph-tail', 'trace_options') + self.fsetVal('nofuncgraph-overhead', 'trace_options') + self.fsetVal('context-info', 'trace_options') + self.fsetVal('graph-time', 'trace_options') + self.fsetVal('0', 'max_graph_depth') + if len(self.debugfuncs) > 0: + self.setFtraceFilterFunctions(self.debugfuncs) + elif self.suspendmode == 'command': + self.fsetVal('', 'set_graph_function') + else: + cf = ['dpm_run_callback'] + if(self.usetraceeventsonly): + cf += ['dpm_prepare', 'dpm_complete'] + for fn in self.tracefuncs: + if 'func' in self.tracefuncs[fn]: + cf.append(self.tracefuncs[fn]['func']) + else: + cf.append(fn) + self.setFtraceFilterFunctions(cf) + if(self.usetraceevents): + # turn trace events on + events = iter(self.traceevents) + for e in events: + self.fsetVal('1', 'events/power/'+e+'/enable') + # clear the trace buffer + self.fsetVal('', 'trace') + def verifyFtrace(self): + # files needed for any trace data + files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock', + 'trace_marker', 'trace_options', 'tracing_on'] + # files needed for callgraph trace data + tp = self.tpath + if(self.usecallgraph): + files += [ + 'available_filter_functions', + 'set_ftrace_filter', + 'set_graph_function' + ] + for f in files: + if(os.path.exists(tp+f) == False): + return False + return True + def verifyKprobes(self): + # files needed for kprobes to work + files = ['kprobe_events', 'events'] + tp = self.tpath + for f in files: + if(os.path.exists(tp+f) == False): + return False + return True + def colorText(self, str): + if not self.ansi: + return str + return '\x1B[31;40m'+str+'\x1B[m' sysvals = SystemValues() +# Class: DevProps +# Description: +# Simple class which holds property values collected +# for all the devices used in the timeline. +class DevProps: + syspath = '' + altname = '' + async = True + xtraclass = '' + xtrainfo = '' + def out(self, dev): + return '%s,%s,%d;' % (dev, self.altname, self.async) + def debug(self, dev): + print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async) + def altName(self, dev): + if not self.altname or self.altname == dev: + return dev + return '%s [%s]' % (self.altname, dev) + def xtraClass(self): + if self.xtraclass: + return ' '+self.xtraclass + if not self.async: + return ' sync' + return '' + def xtraInfo(self): + if self.xtraclass: + return ' '+self.xtraclass + if self.async: + return ' async' + return ' sync' + # Class: DeviceNode # Description: # A container used to create a device hierachy, with a single root node @@ -228,6 +681,7 @@ class Data: html_device_id = 0 stamp = 0 outfile = '' + dev_ubiquitous = ['msleep', 'udelay'] def __init__(self, num): idchar = 'abcdefghijklmnopqrstuvwxyz' self.testnumber = num @@ -257,6 +711,9 @@ class Data: 'row': 0, 'color': '#FFFFCC', 'order': 9} } self.phases = self.sortedPhases() + self.devicegroups = [] + for phase in self.phases: + self.devicegroups.append([phase]) def getStart(self): return self.dmesg[self.phases[0]]['start'] def setStart(self, time): @@ -273,51 +730,61 @@ class Data: for dev in list: d = list[dev] if(d['pid'] == pid and time >= d['start'] and - time <= d['end']): + time < d['end']): return False return True - def addIntraDevTraceEvent(self, action, name, pid, time): - if(action == 'mutex_lock_try'): - color = 'red' - elif(action == 'mutex_lock_pass'): - color = 'green' - elif(action == 'mutex_unlock'): - color = 'blue' - else: - # create separate colors based on the name - v1 = len(name)*10 % 256 - v2 = string.count(name, 'e')*100 % 256 - v3 = ord(name[0])*20 % 256 - color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3) - for phase in self.phases: - list = self.dmesg[phase]['list'] - for dev in list: - d = list[dev] - if(d['pid'] == pid and time >= d['start'] and - time <= d['end']): - e = TraceEvent(action, name, color, time) - if('traceevents' not in d): - d['traceevents'] = [] - d['traceevents'].append(e) - return d - break - return 0 - def capIntraDevTraceEvent(self, action, name, pid, time): - for phase in self.phases: + def targetDevice(self, phaselist, start, end, pid=-1): + tgtdev = '' + for phase in phaselist: list = self.dmesg[phase]['list'] - for dev in list: - d = list[dev] - if(d['pid'] == pid and time >= d['start'] and - time <= d['end']): - if('traceevents' not in d): - return - for e in d['traceevents']: - if(e.action == action and - e.name == name and not e.ready): - e.length = time - e.time - e.ready = True - break - return + for devname in list: + dev = list[devname] + if(pid >= 0 and dev['pid'] != pid): + continue + devS = dev['start'] + devE = dev['end'] + if(start < devS or start >= devE or end <= devS or end > devE): + continue + tgtdev = dev + break + return tgtdev + def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata): + machstart = self.dmesg['suspend_machine']['start'] + machend = self.dmesg['resume_machine']['end'] + tgtdev = self.targetDevice(self.phases, start, end, pid) + if not tgtdev and start >= machstart and end < machend: + # device calls in machine phases should be serial + tgtdev = self.targetDevice(['suspend_machine', 'resume_machine'], start, end) + if not tgtdev: + if 'scsi_eh' in proc: + self.newActionGlobal(proc, start, end, pid) + self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) + else: + vprint('IGNORE: %s[%s](%d) [%f - %f] | %s | %s | %s' % (displayname, kprobename, + pid, start, end, cdata, rdata, proc)) + return False + # detail block fits within tgtdev + if('src' not in tgtdev): + tgtdev['src'] = [] + title = cdata+' '+rdata + mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)' + m = re.match(mstr, title) + if m: + c = m.group('caller') + a = m.group('args').strip() + r = m.group('ret') + if len(r) > 6: + r = '' + else: + r = 'ret=%s ' % r + l = '%0.3fms' % ((end - start) * 1000) + if kprobename in self.dev_ubiquitous: + title = '%s(%s) <- %s, %s(%s)' % (displayname, a, c, r, l) + else: + title = '%s(%s) %s(%s)' % (displayname, a, r, l) + e = TraceEvent(title, kprobename, start, end - start) + tgtdev['src'].append(e) + return True def trimTimeVal(self, t, t0, dT, left): if left: if(t > t0): @@ -353,11 +820,11 @@ class Data: cg.end = self.trimTimeVal(cg.end, t0, dT, left) for line in cg.list: line.time = self.trimTimeVal(line.time, t0, dT, left) - if('traceevents' in d): - for e in d['traceevents']: + if('src' in d): + for e in d['src']: e.time = self.trimTimeVal(e.time, t0, dT, left) def normalizeTime(self, tZero): - # first trim out any standby or freeze clock time + # trim out any standby or freeze clock time if(self.tSuspended != self.tResumed): if(self.tResumed > tZero): self.trimTime(self.tSuspended, \ @@ -365,29 +832,6 @@ class Data: else: self.trimTime(self.tSuspended, \ self.tResumed-self.tSuspended, False) - # shift the timeline so that tZero is the new 0 - self.tSuspended -= tZero - self.tResumed -= tZero - self.start -= tZero - self.end -= tZero - for phase in self.phases: - p = self.dmesg[phase] - p['start'] -= tZero - p['end'] -= tZero - list = p['list'] - for name in list: - d = list[name] - d['start'] -= tZero - d['end'] -= tZero - if('ftrace' in d): - cg = d['ftrace'] - cg.start -= tZero - cg.end -= tZero - for line in cg.list: - line.time -= tZero - if('traceevents' in d): - for e in d['traceevents']: - e.time -= tZero def newPhaseWithSingleAction(self, phasename, devname, start, end, color): for phase in self.phases: self.dmesg[phase]['order'] += 1 @@ -417,6 +861,7 @@ class Data: {'list': list, 'start': start, 'end': end, 'row': 0, 'color': color, 'order': order} self.phases = self.sortedPhases() + self.devicegroups.append([phasename]) def setPhase(self, phase, ktime, isbegin): if(isbegin): self.dmesg[phase]['start'] = ktime @@ -442,7 +887,10 @@ class Data: for devname in phaselist: dev = phaselist[devname] if(dev['end'] < 0): - dev['end'] = end + for p in self.phases: + if self.dmesg[p]['end'] > dev['start']: + dev['end'] = self.dmesg[p]['end'] + break vprint('%s (%s): callback didnt return' % (devname, phase)) def deviceFilter(self, devicefilter): # remove all by the relatives of the filter devnames @@ -472,22 +920,58 @@ class Data: # if any calls never returned, clip them at system resume end for phase in self.phases: self.fixupInitcalls(phase, self.getEnd()) - def newActionGlobal(self, name, start, end): + def isInsideTimeline(self, start, end): + if(self.start <= start and self.end > start): + return True + return False + def phaseOverlap(self, phases): + rmgroups = [] + newgroup = [] + for group in self.devicegroups: + for phase in phases: + if phase not in group: + continue + for p in group: + if p not in newgroup: + newgroup.append(p) + if group not in rmgroups: + rmgroups.append(group) + for group in rmgroups: + self.devicegroups.remove(group) + self.devicegroups.append(newgroup) + def newActionGlobal(self, name, start, end, pid=-1, color=''): + # if event starts before timeline start, expand timeline + if(start < self.start): + self.setStart(start) + # if event ends after timeline end, expand the timeline + if(end > self.end): + self.setEnd(end) # which phase is this device callback or action "in" targetphase = "none" + htmlclass = '' overlap = 0.0 + phases = [] for phase in self.phases: pstart = self.dmesg[phase]['start'] pend = self.dmesg[phase]['end'] o = max(0, min(end, pend) - max(start, pstart)) - if(o > overlap): + if o > 0: + phases.append(phase) + if o > overlap: + if overlap > 0 and phase == 'post_resume': + continue targetphase = phase overlap = o + if pid == -2: + htmlclass = ' bg' + if len(phases) > 1: + htmlclass = ' bg' + self.phaseOverlap(phases) if targetphase in self.phases: - self.newAction(targetphase, name, -1, '', start, end, '') - return True + newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color) + return (targetphase, newname) return False - def newAction(self, phase, name, pid, parent, start, end, drv): + def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''): # new device callback for a specific phase self.html_device_id += 1 devid = '%s%d' % (self.idstr, self.html_device_id) @@ -495,8 +979,19 @@ class Data: length = -1.0 if(start >= 0 and end >= 0): length = end - start + if pid == -2: + i = 2 + origname = name + while(name in list): + name = '%s[%d]' % (origname, i) + i += 1 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv } + if htmlclass: + list[name]['htmlclass'] = htmlclass + if color: + list[name]['color'] = color + return name def deviceIDs(self, devlist, phase): idlist = [] list = self.dmesg[phase]['list'] @@ -536,10 +1031,21 @@ class Data: vprint(' %16s: %f - %f (%d devices)' % (phase, \ self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) vprint(' test end: %f' % self.end) + def deviceChildrenAllPhases(self, devname): + devlist = [] + for phase in self.phases: + list = self.deviceChildren(devname, phase) + for dev in list: + if dev not in devlist: + devlist.append(dev) + return devlist def masterTopology(self, name, list, depth): node = DeviceNode(name, depth) for cname in list: - clist = self.deviceChildren(cname, 'resume') + # avoid recursions + if name == cname: + continue + clist = self.deviceChildrenAllPhases(cname) cnode = self.masterTopology(cname, clist, depth+1) node.children.append(cnode) return node @@ -580,7 +1086,8 @@ class Data: list = self.dmesg[phase]['list'] for dev in list: pdev = list[dev]['par'] - if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): + pid = list[dev]['pid'] + if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): continue if pdev and pdev not in real and pdev not in rootlist: rootlist.append(pdev) @@ -589,22 +1096,33 @@ class Data: rootlist = self.rootDeviceList() master = self.masterTopology('', rootlist, 0) return self.printTopology(master) + def selectTimelineDevices(self, widfmt, tTotal, mindevlen): + # only select devices that will actually show up in html + self.tdevlist = dict() + for phase in self.dmesg: + devlist = [] + list = self.dmesg[phase]['list'] + for dev in list: + length = (list[dev]['end'] - list[dev]['start']) * 1000 + width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal) + if width != '0.000000' and length >= mindevlen: + devlist.append(dev) + self.tdevlist[phase] = devlist # Class: TraceEvent # Description: # A container for trace event data found in the ftrace file class TraceEvent: - ready = False - name = '' + text = '' time = 0.0 - color = '#FFFFFF' length = 0.0 - action = '' - def __init__(self, a, n, c, t): - self.action = a - self.name = n - self.color = c + title = '' + row = 0 + def __init__(self, a, n, t, l): + self.title = a + self.text = n self.time = t + self.length = l # Class: FTraceLine # Description: @@ -623,11 +1141,14 @@ class FTraceLine: fcall = False freturn = False fevent = False + fkprobe = False depth = 0 name = '' type = '' - def __init__(self, t, m, d): + def __init__(self, t, m='', d=''): self.time = float(t) + if not m and not d: + return # is this a trace event if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)): if(d == 'traceevent'): @@ -644,6 +1165,18 @@ class FTraceLine: self.type = emm.group('call') else: self.name = msg + km = re.match('^(?P<n>.*)_cal$', self.type) + if km: + self.fcall = True + self.fkprobe = True + self.type = km.group('n') + return + km = re.match('^(?P<n>.*)_ret$', self.type) + if km: + self.freturn = True + self.fkprobe = True + self.type = km.group('n') + return self.fevent = True return # convert the duration to seconds @@ -662,7 +1195,7 @@ class FTraceLine: # includes comment with function name match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m) if(match): - self.name = match.group('n') + self.name = match.group('n').strip() # function call else: self.fcall = True @@ -670,19 +1203,19 @@ class FTraceLine: if(m[-1] == '{'): match = re.match('^(?P<n>.*) *\(.*', m) if(match): - self.name = match.group('n') + self.name = match.group('n').strip() # function call with no children (leaf) elif(m[-1] == ';'): self.freturn = True match = re.match('^(?P<n>.*) *\(.*', m) if(match): - self.name = match.group('n') + self.name = match.group('n').strip() # something else (possibly a trace marker) else: self.name = m def getDepth(self, str): return len(str)/2 - def debugPrint(self, dev): + 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)) @@ -692,6 +1225,33 @@ class FTraceLine: else: print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ self.depth, self.name, self.length*1000000)) + def startMarker(self): + global sysvals + # Is this the starting line of a suspend? + if not self.fevent: + return False + if sysvals.usetracemarkers: + if(self.name == 'SUSPEND START'): + return True + return False + else: + if(self.type == 'suspend_resume' and + re.match('suspend_enter\[.*\] begin', self.name)): + return True + return False + def endMarker(self): + # Is this the ending line of a resume? + if not self.fevent: + return False + if sysvals.usetracemarkers: + if(self.name == 'RESUME COMPLETE'): + return True + return False + else: + if(self.type == 'suspend_resume' and + re.match('thaw_processes\[.*\] end', self.name)): + return True + return False # Class: FTraceCallGraph # Description: @@ -705,54 +1265,124 @@ class FTraceCallGraph: list = [] invalid = False depth = 0 - def __init__(self): + pid = 0 + def __init__(self, pid): self.start = -1.0 self.end = -1.0 self.list = [] self.depth = 0 - def setDepth(self, line): + self.pid = pid + def addLine(self, line, debug=False): + # 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): + self.invalidate(line) + return False + # compare current depth with this lines pre-call depth + prelinedep = line.depth + if(line.freturn and not line.fcall): + prelinedep += 1 + last = 0 + lasttime = line.time + virtualfname = 'execution_misalignment' + if len(self.list) > 0: + last = self.list[-1] + lasttime = last.time + # handle low misalignments by inserting returns + if prelinedep < self.depth: + if debug and last: + print '-------- task %d --------' % self.pid + last.debugPrint() + 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: + # 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() + else: + vline = FTraceLine(lasttime) + vline.depth = self.depth + vline.name = virtualfname + vline.freturn = True + self.list.append(vline) + if debug: + vline.debugPrint() + idx += 1 + if debug: + line.debugPrint() + print '' + # handle high misalignments by inserting calls + elif prelinedep > self.depth: + if debug and last: + print '-------- task %d --------' % self.pid + last.debugPrint() + idx = 0 + # 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: + # special case, turn this return into a leaf + line.fcall = True + prelinedep -= 1 + else: + vline = FTraceLine(lasttime) + vline.depth = self.depth + vline.name = virtualfname + vline.fcall = True + if debug: + vline.debugPrint() + self.list.append(vline) + self.depth += 1 + if not last: + self.start = vline.time + idx += 1 + if debug: + line.debugPrint() + print '' + # process the call and set the new depth if(line.fcall and not line.freturn): - line.depth = self.depth self.depth += 1 elif(line.freturn and not line.fcall): self.depth -= 1 - line.depth = self.depth - else: - line.depth = self.depth - def addLine(self, line, match): - if(not self.invalid): - self.setDepth(line) + if len(self.list) < 1: + self.start = line.time + self.list.append(line) if(line.depth == 0 and line.freturn): if(self.start < 0): self.start = line.time self.end = line.time - self.list.append(line) + if line.fcall: + self.end += line.length + if self.list[0].name == virtualfname: + self.invalid = True return True - if(self.invalid): - return False - if(len(self.list) >= 1000000 or self.depth < 0): - if(len(self.list) > 0): - first = self.list[0] - self.list = [] - self.list.append(first) - self.invalid = True - if(not match): - return False - id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu')) - window = '(%f - %f)' % (self.start, line.time) - if(self.depth < 0): - print('Too much data for '+id+\ - ' (buffer overflow), ignoring this callback') - else: - print('Too much data for '+id+\ - ' '+window+', ignoring this callback') - return False - self.list.append(line) - if(self.start < 0): - self.start = line.time return False + def invalidate(self, line): + if(len(self.list) > 0): + first = self.list[0] + self.list = [] + self.list.append(first) + self.invalid = True + id = 'task %s' % (self.pid) + window = '(%f - %f)' % (self.start, line.time) + if(self.depth < 0): + vprint('Too much data for '+id+\ + ' (buffer overflow), ignoring this callback') + else: + vprint('Too much data for '+id+\ + ' '+window+', ignoring this callback') def slice(self, t0, tN): - minicg = FTraceCallGraph() + minicg = FTraceCallGraph(0) count = -1 firstdepth = 0 for l in self.list: @@ -764,13 +1394,26 @@ class FTraceCallGraph: firstdepth = l.depth count = 0 l.depth -= firstdepth - minicg.addLine(l, 0) + minicg.addLine(l) if((count == 0 and l.freturn and l.fcall) or (count > 0 and l.depth <= 0)): break count += 1 return minicg - def sanityCheck(self): + def repair(self, enddepth): + # bring the depth back to 0 with additional returns + fixed = False + last = self.list[-1] + for i in reversed(range(enddepth)): + t = FTraceLine(last.time) + t.depth = i + t.freturn = True + fixed = self.addLine(t) + if fixed: + self.end = last.time + return True + return False + def postProcess(self, debug=False): stack = dict() cnt = 0 for l in self.list: @@ -779,98 +1422,317 @@ class FTraceCallGraph: cnt += 1 elif(l.freturn and not l.fcall): if(l.depth not in stack): + if debug: + print 'Post Process Error: Depth missing' + l.debugPrint() return False + # transfer total time from return line to call line stack[l.depth].length = l.length - stack[l.depth] = 0 + stack.pop(l.depth) l.length = 0 cnt -= 1 if(cnt == 0): + # trace caught the whole call tree return True - return False - def debugPrint(self, filename): - if(filename == 'stdout'): - print('[%f - %f]') % (self.start, self.end) - 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)) - else: - print('%f (%02d): %s() { (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) - print(' ') - else: - fp = open(filename, 'w') - print(filename) - for l in self.list: - if(l.freturn and l.fcall): - fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \ - l.depth, l.name, l.length*1000000)) - elif(l.freturn): - fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \ - l.depth, l.name, l.length*1000000)) - else: - fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \ - l.depth, l.name, l.length*1000000)) - fp.close() + elif(cnt < 0): + if debug: + 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 + # add the callgraph data to the device hierarchy + borderphase = { + 'dpm_prepare': 'suspend_prepare', + 'dpm_complete': 'resume_complete' + } + if(self.list[0].name in borderphase): + p = borderphase[self.list[0].name] + list = data.dmesg[p]['list'] + for devname in list: + dev = list[devname] + if(pid == dev['pid'] and + self.start <= dev['start'] and + self.end >= dev['end']): + dev['ftrace'] = self.slice(dev['start'], dev['end']) + found = True + return found + for p in data.phases: + if(data.dmesg[p]['start'] <= self.start and + self.start <= data.dmesg[p]['end']): + list = data.dmesg[p]['list'] + for devname in list: + dev = list[devname] + if(pid == dev['pid'] and + self.start <= dev['start'] and + self.end >= dev['end']): + dev['ftrace'] = self + found = True + break + break + return found + def newActionFromFunction(self, data): + name = self.list[0].name + if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']: + return + fs = self.start + fe = self.end + if fs < data.start or fe > data.end: + return + phase = '' + for p in data.phases: + if(data.dmesg[p]['start'] <= self.start and + self.start < data.dmesg[p]['end']): + phase = p + break + if not phase: + return + out = data.newActionGlobal(name, fs, fe, -2) + 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.list[0].name, self.pid) + 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)) + else: + print('%f (%02d): %s() { (%.3f us)' % (l.time, \ + l.depth, l.name, l.length*1000000)) + print(' ') # Class: Timeline # Description: -# A container for a suspend/resume html timeline. In older versions -# of the script there were multiple timelines, but in the latest -# there is only one. +# A container for a device timeline which calculates +# all the html properties to display it correctly class Timeline: html = {} - scaleH = 0.0 # height of the row as a percent of the timeline height - rowH = 0.0 # height of each row in percent of the timeline height - row_height_pixels = 30 - maxrows = 0 - height = 0 - def __init__(self): + height = 0 # total timeline height + scaleH = 20 # timescale (top) row height + rowH = 30 # device row height + bodyH = 0 # body height + rows = 0 # total timeline rows + phases = [] + rowmaxlines = dict() + rowcount = dict() + rowheight = dict() + def __init__(self, rowheight): + self.rowH = rowheight self.html = { + 'header': '', 'timeline': '', 'legend': '', - 'scale': '' } - def setRows(self, rows): - self.maxrows = int(rows) - self.scaleH = 100.0/float(self.maxrows) - self.height = self.maxrows*self.row_height_pixels - r = float(self.maxrows - 1) - if(r < 1.0): - r = 1.0 - self.rowH = (100.0 - self.scaleH)/r + # Function: getDeviceRows + # Description: + # determine how may rows the device funcs will take + # Arguments: + # rawlist: the list of devices/actions for a single phase + # Output: + # The total number of rows needed to display this phase of the timeline + def getDeviceRows(self, rawlist): + # clear all rows and set them to undefined + lendict = dict() + for item in rawlist: + item.row = -1 + lendict[item] = item.length + list = [] + for i in sorted(lendict, key=lendict.get, reverse=True): + list.append(i) + remaining = len(list) + rowdata = dict() + row = 1 + # try to pack each row with as many ranges as possible + while(remaining > 0): + if(row not in rowdata): + rowdata[row] = [] + for i in list: + if(i.row >= 0): + continue + s = i.time + e = i.time + i.length + valid = True + for ritem in rowdata[row]: + rs = ritem.time + re = ritem.time + ritem.length + if(not (((s <= rs) and (e <= rs)) or + ((s >= re) and (e >= re)))): + valid = False + break + if(valid): + rowdata[row].append(i) + i.row = row + remaining -= 1 + row += 1 + return row + # Function: getPhaseRows + # Description: + # Organize the timeline entries into the smallest + # number of rows possible, with no entry overlapping + # Arguments: + # list: the list of devices/actions for a single phase + # devlist: string list of device names to use + # Output: + # The total number of rows needed to display this phase of the timeline + def getPhaseRows(self, dmesg, devlist): + # clear all rows and set them to undefined + remaining = len(devlist) + rowdata = dict() + row = 0 + lendict = dict() + myphases = [] + for item in devlist: + if item[0] not in self.phases: + self.phases.append(item[0]) + if item[0] not in myphases: + myphases.append(item[0]) + self.rowmaxlines[item[0]] = dict() + self.rowheight[item[0]] = dict() + dev = dmesg[item[0]]['list'][item[1]] + dev['row'] = -1 + lendict[item] = float(dev['end']) - float(dev['start']) + if 'src' in dev: + dev['devrows'] = self.getDeviceRows(dev['src']) + lenlist = [] + for i in sorted(lendict, key=lendict.get, reverse=True): + lenlist.append(i) + orderedlist = [] + for item in lenlist: + dev = dmesg[item[0]]['list'][item[1]] + if dev['pid'] == -2: + orderedlist.append(item) + for item in lenlist: + if item not in orderedlist: + orderedlist.append(item) + # try to pack each row with as many ranges as possible + while(remaining > 0): + rowheight = 1 + if(row not in rowdata): + rowdata[row] = [] + for item in orderedlist: + dev = dmesg[item[0]]['list'][item[1]] + if(dev['row'] < 0): + s = dev['start'] + e = dev['end'] + valid = True + for ritem in rowdata[row]: + rs = ritem['start'] + re = ritem['end'] + if(not (((s <= rs) and (e <= rs)) or + ((s >= re) and (e >= re)))): + valid = False + break + if(valid): + rowdata[row].append(dev) + dev['row'] = row + remaining -= 1 + if 'devrows' in dev and dev['devrows'] > rowheight: + rowheight = dev['devrows'] + for phase in myphases: + self.rowmaxlines[phase][row] = rowheight + self.rowheight[phase][row] = rowheight * self.rowH + row += 1 + if(row > self.rows): + self.rows = int(row) + for phase in myphases: + self.rowcount[phase] = row + return row + def phaseRowHeight(self, phase, row): + return self.rowheight[phase][row] + def phaseRowTop(self, phase, row): + top = 0 + for i in sorted(self.rowheight[phase]): + if i >= row: + break + top += self.rowheight[phase][i] + return top + # Function: calcTotalRows + # Description: + # Calculate the heights and offsets for the header and rows + def calcTotalRows(self): + maxrows = 0 + standardphases = [] + for phase in self.phases: + total = 0 + for i in sorted(self.rowmaxlines[phase]): + total += self.rowmaxlines[phase][i] + if total > maxrows: + maxrows = total + if total == self.rowcount[phase]: + standardphases.append(phase) + self.height = self.scaleH + (maxrows*self.rowH) + self.bodyH = self.height - self.scaleH + for phase in standardphases: + for i in sorted(self.rowheight[phase]): + self.rowheight[phase][i] = self.bodyH/self.rowcount[phase] + # Function: createTimeScale + # Description: + # Create the timescale for a timeline block + # Arguments: + # m0: start time (mode begin) + # mMax: end time (mode end) + # tTotal: total timeline time + # mode: suspend or resume + # Output: + # The html code needed to display the time scale + def createTimeScale(self, m0, mMax, tTotal, mode): + timescale = '<div class="t" style="right:{0}%">{1}</div>\n' + rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n' + output = '<div class="timescale">\n' + # set scale for timeline + mTotal = mMax - m0 + tS = 0.1 + if(tTotal <= 0): + return output+'</div>\n' + if(tTotal > 4): + tS = 1 + divTotal = int(mTotal/tS) + 1 + divEdge = (mTotal - tS*(divTotal-1))*100/mTotal + for i in range(divTotal): + htmlline = '' + if(mode == 'resume'): + pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal)) + val = '%0.fms' % (float(i)*tS*1000) + htmlline = timescale.format(pos, val) + if(i == 0): + htmlline = rline + else: + pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge) + val = '%0.fms' % (float(i-divTotal+1)*tS*1000) + if(i == divTotal - 1): + val = 'Suspend' + htmlline = timescale.format(pos, val) + output += htmlline + output += '</div>\n' + return output -# Class: TestRun +# Class: TestProps # Description: -# A container for a suspend/resume test run. This is necessary as -# there could be more than one, and they need to be separate. -class TestRun: +# A list of values describing the properties of these test runs +class TestProps: + stamp = '' + tracertype = '' + S0i3 = False + fwdata = [] ftrace_line_fmt_fg = \ '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ - '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' + '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' ftrace_line_fmt_nop = \ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ '(?P<msg>.*)' ftrace_line_fmt = ftrace_line_fmt_nop cgformat = False - ftemp = dict() - ttemp = dict() - inthepipe = False - tracertype = '' data = 0 - def __init__(self, dataobj): - self.data = dataobj - self.ftemp = dict() - self.ttemp = dict() - def isReady(self): - if(tracertype == '' or not data): - return False - return True + ktemp = dict() + def __init__(self): + self.ktemp = dict() def setTracerType(self, tracer): self.tracertype = tracer if(tracer == 'function_graph'): @@ -881,6 +1743,19 @@ class TestRun: else: doError('Invalid tracer format: [%s]' % tracer, False) +# Class: TestRun +# Description: +# A container for a suspend/resume test run. This is necessary as +# there could be more than one, and they need to be separate. +class TestRun: + ftemp = dict() + ttemp = dict() + data = 0 + def __init__(self, dataobj): + self.data = dataobj + self.ftemp = dict() + self.ttemp = dict() + # ----------------- FUNCTIONS -------------------- # Function: vprint @@ -893,104 +1768,16 @@ def vprint(msg): if(sysvals.verbose): print(msg) -# Function: initFtrace -# Description: -# Configure ftrace to use trace events and/or a callgraph -def initFtrace(): - global sysvals - - tp = sysvals.tpath - cf = 'dpm_run_callback' - if(sysvals.usetraceeventsonly): - cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback' - if(sysvals.usecallgraph or sysvals.usetraceevents): - print('INITIALIZING FTRACE...') - # turn trace off - os.system('echo 0 > '+tp+'tracing_on') - # set the trace clock to global - os.system('echo global > '+tp+'trace_clock') - # set trace buffer to a huge value - os.system('echo nop > '+tp+'current_tracer') - os.system('echo 100000 > '+tp+'buffer_size_kb') - # initialize the callgraph trace, unless this is an x2 run - if(sysvals.usecallgraph and sysvals.execcount == 1): - # set trace type - os.system('echo function_graph > '+tp+'current_tracer') - os.system('echo "" > '+tp+'set_ftrace_filter') - # set trace format options - os.system('echo funcgraph-abstime > '+tp+'trace_options') - os.system('echo funcgraph-proc > '+tp+'trace_options') - # focus only on device suspend and resume - os.system('cat '+tp+'available_filter_functions | grep '+\ - cf+' > '+tp+'set_graph_function') - if(sysvals.usetraceevents): - # turn trace events on - events = iter(sysvals.traceevents) - for e in events: - os.system('echo 1 > '+sysvals.epath+e+'/enable') - # clear the trace buffer - os.system('echo "" > '+tp+'trace') - -# Function: initFtraceAndroid -# Description: -# Configure ftrace to capture trace events -def initFtraceAndroid(): - global sysvals - - tp = sysvals.tpath - if(sysvals.usetraceevents): - print('INITIALIZING FTRACE...') - # turn trace off - os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'") - # set the trace clock to global - os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'") - # set trace buffer to a huge value - os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'") - os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'") - # turn trace events on - events = iter(sysvals.traceevents) - for e in events: - os.system(sysvals.adb+" shell 'echo 1 > "+\ - sysvals.epath+e+"/enable'") - # clear the trace buffer - os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'") - -# Function: verifyFtrace -# Description: -# Check that ftrace is working on the system -# Output: -# True or False -def verifyFtrace(): - global sysvals - # files needed for any trace data - files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock', - 'trace_marker', 'trace_options', 'tracing_on'] - # files needed for callgraph trace data - tp = sysvals.tpath - if(sysvals.usecallgraph): - files += [ - 'available_filter_functions', - 'set_ftrace_filter', - 'set_graph_function' - ] - for f in files: - if(sysvals.android): - out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip() - if(out != tp+f): - return False - else: - if(os.path.exists(tp+f) == False): - return False - return True - # Function: parseStamp # Description: # Pull in the stamp comment line from the data file(s), # create the stamp, and add it to the global sysvals object # Arguments: # m: the valid re.match output for the stamp line -def parseStamp(m, data): +def parseStamp(line, data): global sysvals + + m = re.match(sysvals.stampfmt, line) data.stamp = {'time': '', 'host': '', 'mode': ''} dt = datetime(int(m.group('y'))+2000, int(m.group('m')), int(m.group('d')), int(m.group('H')), int(m.group('M')), @@ -999,6 +1786,7 @@ def parseStamp(m, data): data.stamp['host'] = m.group('host') data.stamp['mode'] = m.group('mode') data.stamp['kernel'] = m.group('kernel') + sysvals.hostname = data.stamp['host'] sysvals.suspendmode = data.stamp['mode'] if not sysvals.stamp: sysvals.stamp = data.stamp @@ -1031,14 +1819,35 @@ def diffStamp(stamp1, stamp2): def doesTraceLogHaveTraceEvents(): global sysvals + # check for kprobes + sysvals.usekprobes = False + out = os.system('grep -q "_cal: (" '+sysvals.ftracefile) + if(out == 0): + sysvals.usekprobes = True + # check for callgraph data on trace event blocks + out = os.system('grep -q "_cpu_down()" '+sysvals.ftracefile) + if(out == 0): + sysvals.usekprobes = True + out = os.popen('head -1 '+sysvals.ftracefile).read().replace('\n', '') + m = re.match(sysvals.stampfmt, out) + if m and m.group('mode') == 'command': + sysvals.usetraceeventsonly = True + sysvals.usetraceevents = True + return + # figure out what level of trace events are supported sysvals.usetraceeventsonly = True sysvals.usetraceevents = False for e in sysvals.traceevents: - out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read() - if(not out): + out = os.system('grep -q "'+e+': " '+sysvals.ftracefile) + if(out != 0): sysvals.usetraceeventsonly = False - if(e == 'suspend_resume' and out): + 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 = os.system('grep -q "'+e+'" '+sysvals.ftracefile) + if(out != 0): + sysvals.usetracemarkers = False # Function: appendIncompleteTraceLog # Description: @@ -1055,44 +1864,42 @@ def appendIncompleteTraceLog(testruns): # create TestRun vessels for ftrace parsing testcnt = len(testruns) - testidx = -1 + testidx = 0 testrun = [] for data in testruns: testrun.append(TestRun(data)) # extract the callgraph and traceevent data vprint('Analyzing the ftrace data...') + tp = TestProps() tf = open(sysvals.ftracefile, 'r') + data = 0 for line in tf: # remove any latent carriage returns line = line.replace('\r\n', '') - # grab the time stamp first (signifies the start of the test run) + # grab the time stamp m = re.match(sysvals.stampfmt, line) if(m): - testidx += 1 - parseStamp(m, testrun[testidx].data) - continue - # pull out any firmware data - if(re.match(sysvals.firmwarefmt, line)): - continue - # if we havent found a test time stamp yet keep spinning til we do - if(testidx < 0): + tp.stamp = line continue # determine the trace data type (required for further parsing) m = re.match(sysvals.tracertypefmt, line) if(m): - tracer = m.group('t') - testrun[testidx].setTracerType(tracer) + tp.setTracerType(m.group('t')) + continue + # device properties line + if(re.match(sysvals.devpropfmt, line)): + devProps(line) continue - # parse only valid lines, if this isnt one move on - m = re.match(testrun[testidx].ftrace_line_fmt, line) + # parse only valid lines, if this is not one move on + m = re.match(tp.ftrace_line_fmt, line) if(not m): continue # gather the basic message data from the line m_time = m.group('time') m_pid = m.group('pid') m_msg = m.group('msg') - if(testrun[testidx].cgformat): + if(tp.cgformat): m_param3 = m.group('dur') else: m_param3 = 'traceevent' @@ -1104,119 +1911,114 @@ def appendIncompleteTraceLog(testruns): # the line should be a call, return, or event if(not t.fcall and not t.freturn and not t.fevent): continue - # only parse the ftrace data during suspend/resume - data = testrun[testidx].data - if(not testrun[testidx].inthepipe): - # look for the suspend start marker - if(t.fevent): - if(t.name == 'SUSPEND START'): - testrun[testidx].inthepipe = True - data.setStart(t.time) + # look for the suspend start marker + if(t.startMarker()): + data = testrun[testidx].data + parseStamp(tp.stamp, data) + data.setStart(t.time) + continue + if(not data): + continue + # find the end of resume + if(t.endMarker()): + data.setEnd(t.time) + testidx += 1 + if(testidx >= testcnt): + break + continue + # trace event processing + if(t.fevent): + # general trace events have two types, begin and end + if(re.match('(?P<name>.*) begin$', t.name)): + isbegin = True + elif(re.match('(?P<name>.*) end$', t.name)): + isbegin = False + else: continue - else: - # trace event processing - if(t.fevent): - if(t.name == 'RESUME COMPLETE'): - testrun[testidx].inthepipe = False - data.setEnd(t.time) - if(testidx == testcnt - 1): - break - continue - # general trace events have two types, begin and end - if(re.match('(?P<name>.*) begin$', t.name)): - isbegin = True - elif(re.match('(?P<name>.*) end$', t.name)): - isbegin = False + m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) + if(m): + val = m.group('val') + if val == '0': + name = m.group('name') else: - continue - m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) - if(m): - val = m.group('val') - if val == '0': - name = m.group('name') - else: - name = m.group('name')+'['+val+']' + name = m.group('name')+'['+val+']' + else: + m = re.match('(?P<name>.*) .*', t.name) + name = m.group('name') + # special processing for trace events + if re.match('dpm_prepare\[.*', name): + continue + elif re.match('machine_suspend.*', name): + continue + elif re.match('suspend_enter\[.*', name): + if(not isbegin): + data.dmesg['suspend_prepare']['end'] = t.time + continue + elif re.match('dpm_suspend\[.*', name): + if(not isbegin): + data.dmesg['suspend']['end'] = t.time + continue + elif re.match('dpm_suspend_late\[.*', name): + if(isbegin): + data.dmesg['suspend_late']['start'] = t.time else: - m = re.match('(?P<name>.*) .*', t.name) - name = m.group('name') - # special processing for trace events - if re.match('dpm_prepare\[.*', name): - continue - elif re.match('machine_suspend.*', name): - continue - elif re.match('suspend_enter\[.*', name): - if(not isbegin): - data.dmesg['suspend_prepare']['end'] = t.time - continue - elif re.match('dpm_suspend\[.*', name): - if(not isbegin): - data.dmesg['suspend']['end'] = t.time - continue - elif re.match('dpm_suspend_late\[.*', name): - if(isbegin): - data.dmesg['suspend_late']['start'] = t.time - else: - data.dmesg['suspend_late']['end'] = t.time - continue - elif re.match('dpm_suspend_noirq\[.*', name): - if(isbegin): - data.dmesg['suspend_noirq']['start'] = t.time - else: - data.dmesg['suspend_noirq']['end'] = t.time - continue - elif re.match('dpm_resume_noirq\[.*', name): - if(isbegin): - data.dmesg['resume_machine']['end'] = t.time - data.dmesg['resume_noirq']['start'] = t.time - else: - data.dmesg['resume_noirq']['end'] = t.time - continue - elif re.match('dpm_resume_early\[.*', name): - if(isbegin): - data.dmesg['resume_early']['start'] = t.time - else: - data.dmesg['resume_early']['end'] = t.time - continue - elif re.match('dpm_resume\[.*', name): - if(isbegin): - data.dmesg['resume']['start'] = t.time - else: - data.dmesg['resume']['end'] = t.time - continue - elif re.match('dpm_complete\[.*', name): - if(isbegin): - data.dmesg['resume_complete']['start'] = t.time - else: - data.dmesg['resume_complete']['end'] = t.time - continue - # is this trace event outside of the devices calls - if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): - # global events (outside device calls) are simply graphed - if(isbegin): - # store each trace event in ttemp - if(name not in testrun[testidx].ttemp): - testrun[testidx].ttemp[name] = [] - testrun[testidx].ttemp[name].append(\ - {'begin': t.time, 'end': t.time}) - else: - # finish off matching trace event in ttemp - if(name in testrun[testidx].ttemp): - testrun[testidx].ttemp[name][-1]['end'] = t.time + data.dmesg['suspend_late']['end'] = t.time + continue + elif re.match('dpm_suspend_noirq\[.*', name): + if(isbegin): + data.dmesg['suspend_noirq']['start'] = t.time else: - if(isbegin): - data.addIntraDevTraceEvent('', name, pid, t.time) - else: - data.capIntraDevTraceEvent('', name, pid, t.time) - # call/return processing - elif sysvals.usecallgraph: - # create a callgraph object for the data - if(pid not in testrun[testidx].ftemp): - testrun[testidx].ftemp[pid] = [] - testrun[testidx].ftemp[pid].append(FTraceCallGraph()) - # when the call is finished, see which device matches it - cg = testrun[testidx].ftemp[pid][-1] - if(cg.addLine(t, m)): - testrun[testidx].ftemp[pid].append(FTraceCallGraph()) + data.dmesg['suspend_noirq']['end'] = t.time + continue + elif re.match('dpm_resume_noirq\[.*', name): + if(isbegin): + data.dmesg['resume_machine']['end'] = t.time + data.dmesg['resume_noirq']['start'] = t.time + else: + data.dmesg['resume_noirq']['end'] = t.time + continue + elif re.match('dpm_resume_early\[.*', name): + if(isbegin): + data.dmesg['resume_early']['start'] = t.time + else: + data.dmesg['resume_early']['end'] = t.time + continue + elif re.match('dpm_resume\[.*', name): + if(isbegin): + data.dmesg['resume']['start'] = t.time + else: + data.dmesg['resume']['end'] = t.time + continue + elif re.match('dpm_complete\[.*', name): + if(isbegin): + data.dmesg['resume_complete']['start'] = t.time + else: + data.dmesg['resume_complete']['end'] = t.time + continue + # skip trace events inside devices calls + if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)): + continue + # global events (outside device calls) are simply graphed + if(isbegin): + # store each trace event in ttemp + if(name not in testrun[testidx].ttemp): + testrun[testidx].ttemp[name] = [] + testrun[testidx].ttemp[name].append(\ + {'begin': t.time, 'end': t.time}) + else: + # finish off matching trace event in ttemp + if(name in testrun[testidx].ttemp): + testrun[testidx].ttemp[name][-1]['end'] = t.time + # call/return processing + elif sysvals.usecallgraph: + # 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)) + # 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)) tf.close() for test in testrun: @@ -1224,20 +2026,14 @@ def appendIncompleteTraceLog(testruns): if(sysvals.usetraceevents): for name in test.ttemp: for event in test.ttemp[name]: - begin = event['begin'] - end = event['end'] - # if event starts before timeline start, expand timeline - if(begin < test.data.start): - test.data.setStart(begin) - # if event ends after timeline end, expand the timeline - if(end > test.data.end): - test.data.setEnd(end) - test.data.newActionGlobal(name, begin, end) + test.data.newActionGlobal(name, event['begin'], event['end']) # add the callgraph data to the device hierarchy for pid in test.ftemp: for cg in test.ftemp[pid]: - if(not cg.sanityCheck()): + if len(cg.list) < 1 or cg.invalid: + continue + if(not cg.postProcess()): id = 'task %s cpu %s' % (pid, m.group('cpu')) vprint('Sanity check failed for '+\ id+', ignoring this callback') @@ -1259,14 +2055,6 @@ def appendIncompleteTraceLog(testruns): if(sysvals.verbose): test.data.printDetails() - - # add the time in between the tests as a new phase so we can see it - if(len(testruns) > 1): - t1e = testruns[0].getEnd() - t2s = testruns[-1].getStart() - testruns[-1].newPhaseWithSingleAction('user mode', \ - 'user mode', t1e, t2s, '#FF9966') - # Function: parseTraceLog # Description: # Analyze an ftrace log output file generated from this app during @@ -1280,9 +2068,16 @@ def parseTraceLog(): vprint('Analyzing the ftrace data...') if(os.path.exists(sysvals.ftracefile) == False): - doError('%s doesnt exist' % sysvals.ftracefile, False) + doError('%s does not exist' % sysvals.ftracefile, False) + + sysvals.setupAllKprobes() + tracewatch = ['suspend_enter'] + if sysvals.usekprobes: + tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', + 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF'] # extract the callgraph and traceevent data + tp = TestProps() testruns = [] testdata = [] testrun = 0 @@ -1295,27 +2090,17 @@ def parseTraceLog(): # stamp line: each stamp means a new test run m = re.match(sysvals.stampfmt, line) if(m): - data = Data(len(testdata)) - testdata.append(data) - testrun = TestRun(data) - testruns.append(testrun) - parseStamp(m, data) - continue - if(not data): + tp.stamp = line continue # firmware line: pull out any firmware data m = re.match(sysvals.firmwarefmt, line) if(m): - data.fwSuspend = int(m.group('s')) - data.fwResume = int(m.group('r')) - if(data.fwSuspend > 0 or data.fwResume > 0): - data.fwValid = True + tp.fwdata.append((int(m.group('s')), int(m.group('r')))) continue # tracer type line: determine the trace data type m = re.match(sysvals.tracertypefmt, line) if(m): - tracer = m.group('t') - testrun.setTracerType(tracer) + tp.setTracerType(m.group('t')) continue # post resume time line: did this test run include post-resume data m = re.match(sysvals.postresumefmt, line) @@ -1324,15 +2109,20 @@ def parseTraceLog(): if(t > 0): sysvals.postresumetime = t continue + # device properties line + if(re.match(sysvals.devpropfmt, line)): + devProps(line) + continue # ftrace line: parse only valid lines - m = re.match(testrun.ftrace_line_fmt, line) + m = re.match(tp.ftrace_line_fmt, line) if(not m): continue # gather the basic message data from the line m_time = m.group('time') + m_proc = m.group('proc') m_pid = m.group('pid') m_msg = m.group('msg') - if(testrun.cgformat): + if(tp.cgformat): m_param3 = m.group('dur') else: m_param3 = 'traceevent' @@ -1344,24 +2134,38 @@ def parseTraceLog(): # the line should be a call, return, or event if(not t.fcall and not t.freturn and not t.fevent): continue - # only parse the ftrace data during suspend/resume - if(not testrun.inthepipe): - # look for the suspend start marker - if(t.fevent): - if(t.name == 'SUSPEND START'): - testrun.inthepipe = True - data.setStart(t.time) + # find the start of suspend + if(t.startMarker()): + phase = 'suspend_prepare' + data = Data(len(testdata)) + testdata.append(data) + testrun = TestRun(data) + testruns.append(testrun) + parseStamp(tp.stamp, data) + if len(tp.fwdata) > data.testnumber: + data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber] + if(data.fwSuspend > 0 or data.fwResume > 0): + data.fwValid = True + data.setStart(t.time) + continue + if(not data): + continue + # find the end of resume + if(t.endMarker()): + if(sysvals.usetracemarkers and sysvals.postresumetime > 0): + phase = 'post_resume' + data.newPhase(phase, t.time, t.time, '#F0F0F0', -1) + data.setEnd(t.time) + if(not sysvals.usetracemarkers): + # no trace markers? then quit and be sure to finish recording + # the event we used to trigger resume end + if(len(testrun.ttemp['thaw_processes']) > 0): + # if an entry exists, assume this is its end + testrun.ttemp['thaw_processes'][-1]['end'] = t.time + break continue # trace event processing if(t.fevent): - if(t.name == 'RESUME COMPLETE'): - if(sysvals.postresumetime > 0): - phase = 'post_resume' - data.newPhase(phase, t.time, t.time, '#FF9966', -1) - else: - testrun.inthepipe = False - data.setEnd(t.time) - continue if(phase == 'post_resume'): data.setEnd(t.time) if(t.type == 'suspend_resume'): @@ -1383,8 +2187,7 @@ def parseTraceLog(): m = re.match('(?P<name>.*) .*', t.name) name = m.group('name') # ignore these events - if(re.match('acpi_suspend\[.*', t.name) or - re.match('suspend_enter\[.*', name)): + if(name.split('[')[0] in tracewatch): continue # -- phase changes -- # suspend_prepare start @@ -1418,7 +2221,7 @@ def parseTraceLog(): data.dmesg[phase]['end'] = t.time data.tSuspended = t.time else: - if(sysvals.suspendmode in ['mem', 'disk']): + if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3): data.dmesg['suspend_machine']['end'] = t.time data.tSuspended = t.time phase = 'resume_machine' @@ -1426,6 +2229,15 @@ def parseTraceLog(): data.tResumed = t.time data.tLow = data.tResumed - data.tSuspended continue + # acpi_suspend + elif(re.match('acpi_suspend\[.*', t.name)): + # acpi_suspend[0] S0i3 + if(re.match('acpi_suspend\[0\] begin', t.name)): + if(sysvals.suspendmode == 'mem'): + tp.S0i3 = True + data.dmesg['suspend_machine']['end'] = t.time + data.tSuspended = t.time + continue # resume_noirq start elif(re.match('dpm_resume_noirq\[.*', t.name)): phase = 'resume_noirq' @@ -1449,30 +2261,25 @@ def parseTraceLog(): if(isbegin): data.dmesg[phase]['start'] = t.time continue - - # is this trace event outside of the devices calls - if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): - # global events (outside device calls) are simply graphed - if(name not in testrun.ttemp): - testrun.ttemp[name] = [] - if(isbegin): - # create a new list entry - testrun.ttemp[name].append(\ - {'begin': t.time, 'end': t.time}) - else: - if(len(testrun.ttemp[name]) > 0): - # if an antry exists, assume this is its end - testrun.ttemp[name][-1]['end'] = t.time - elif(phase == 'post_resume'): - # post resume events can just have ends - testrun.ttemp[name].append({ - 'begin': data.dmesg[phase]['start'], - 'end': t.time}) + # skip trace events inside devices calls + if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)): + continue + # global events (outside device calls) are graphed + if(name not in testrun.ttemp): + testrun.ttemp[name] = [] + if(isbegin): + # create a new list entry + testrun.ttemp[name].append(\ + {'begin': t.time, 'end': t.time, 'pid': pid}) else: - if(isbegin): - data.addIntraDevTraceEvent('', name, pid, t.time) - else: - data.capIntraDevTraceEvent('', name, pid, t.time) + if(len(testrun.ttemp[name]) > 0): + # if an entry exists, assume this is its end + testrun.ttemp[name][-1]['end'] = t.time + elif(phase == 'post_resume'): + # post resume events can just have ends + testrun.ttemp[name].append({ + 'begin': data.dmesg[phase]['start'], + 'end': t.time}) # device callback start elif(t.type == 'device_pm_callback_start'): m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ @@ -1495,75 +2302,127 @@ def parseTraceLog(): dev = list[n] dev['length'] = t.time - dev['start'] dev['end'] = t.time + # kprobe event processing + elif(t.fkprobe): + kprobename = t.type + kprobedata = t.name + key = (kprobename, pid) + # displayname is generated from kprobe data + displayname = '' + if(t.fcall): + displayname = sysvals.kprobeDisplayName(kprobename, kprobedata) + if not displayname: + continue + if(key not in tp.ktemp): + tp.ktemp[key] = [] + tp.ktemp[key].append({ + 'pid': pid, + 'begin': t.time, + 'end': t.time, + 'name': displayname, + 'cdata': kprobedata, + 'proc': m_proc, + }) + elif(t.freturn): + if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1: + continue + e = tp.ktemp[key][-1] + if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001: + tp.ktemp[key].pop() + else: + e['end'] = t.time + e['rdata'] = kprobedata # callgraph processing elif sysvals.usecallgraph: - # this shouldn't happen, but JIC, ignore callgraph data post-res - if(phase == 'post_resume'): - continue # create a callgraph object for the data - if(pid not in testrun.ftemp): - testrun.ftemp[pid] = [] - testrun.ftemp[pid].append(FTraceCallGraph()) + key = (m_proc, pid) + if(key not in testrun.ftemp): + testrun.ftemp[key] = [] + testrun.ftemp[key].append(FTraceCallGraph(pid)) # when the call is finished, see which device matches it - cg = testrun.ftemp[pid][-1] - if(cg.addLine(t, m)): - testrun.ftemp[pid].append(FTraceCallGraph()) + cg = testrun.ftemp[key][-1] + if(cg.addLine(t)): + testrun.ftemp[key].append(FTraceCallGraph(pid)) tf.close() + if sysvals.suspendmode == 'command': + for test in testruns: + for p in test.data.phases: + if p == 'resume_complete': + test.data.dmesg[p]['start'] = test.data.start + test.data.dmesg[p]['end'] = test.data.end + else: + test.data.dmesg[p]['start'] = test.data.start + test.data.dmesg[p]['end'] = test.data.start + test.data.tSuspended = test.data.start + test.data.tResumed = test.data.start + test.data.tLow = 0 + test.data.fwValid = False + for test in testruns: # add the traceevent data to the device hierarchy if(sysvals.usetraceevents): + # add actual trace funcs for name in test.ttemp: for event in test.ttemp[name]: - begin = event['begin'] - end = event['end'] - # if event starts before timeline start, expand timeline - if(begin < test.data.start): - test.data.setStart(begin) - # if event ends after timeline end, expand the timeline - if(end > test.data.end): - test.data.setEnd(end) - test.data.newActionGlobal(name, begin, end) - - # add the callgraph data to the device hierarchy - borderphase = { - 'dpm_prepare': 'suspend_prepare', - 'dpm_complete': 'resume_complete' - } - for pid in test.ftemp: - for cg in test.ftemp[pid]: - if len(cg.list) < 2: + test.data.newActionGlobal(name, event['begin'], event['end'], event['pid']) + # add the kprobe based virtual tracefuncs as actual devices + for key in tp.ktemp: + name, pid = key + if name not in sysvals.tracefuncs: continue - if(not cg.sanityCheck()): - id = 'task %s cpu %s' % (pid, m.group('cpu')) - vprint('Sanity check failed for '+\ - id+', ignoring this callback') + for e in tp.ktemp[key]: + kb, ke = e['begin'], e['end'] + if kb == ke or not test.data.isInsideTimeline(kb, ke): + continue + test.data.newActionGlobal(e['name'], kb, ke, pid) + # add config base kprobes and dev kprobes + for key in tp.ktemp: + name, pid = key + if name in sysvals.tracefuncs: continue - callstart = cg.start - callend = cg.end - if(cg.list[0].name in borderphase): - p = borderphase[cg.list[0].name] - list = test.data.dmesg[p]['list'] - for devname in list: - dev = list[devname] - if(pid == dev['pid'] and - callstart <= dev['start'] and - callend >= dev['end']): - dev['ftrace'] = cg.slice(dev['start'], dev['end']) - continue - if(cg.list[0].name != 'dpm_run_callback'): - continue - for p in test.data.phases: - if(test.data.dmesg[p]['start'] <= callstart and - callstart <= test.data.dmesg[p]['end']): - list = test.data.dmesg[p]['list'] - for devname in list: - dev = list[devname] - if(pid == dev['pid'] and - callstart <= dev['start'] and - callend >= dev['end']): - dev['ftrace'] = cg - break + for e in tp.ktemp[key]: + kb, ke = e['begin'], e['end'] + if kb == ke or not test.data.isInsideTimeline(kb, ke): + continue + color = sysvals.kprobeColor(e['name']) + if name not in sysvals.dev_tracefuncs: + # config base kprobe + test.data.newActionGlobal(e['name'], kb, ke, -2, color) + elif sysvals.usedevsrc: + # dev kprobe + data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb, + ke, e['cdata'], e['rdata']) + if sysvals.usecallgraph: + # add the callgraph data to the device hierarchy + sortlist = dict() + for key in test.ftemp: + proc, pid = key + for cg in test.ftemp[key]: + if len(cg.list) < 1 or cg.invalid: + continue + if(not cg.postProcess()): + id = 'task %s' % (pid) + vprint('Sanity check failed for '+\ + id+', ignoring this callback') + continue + # match cg data to devices + if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, test.data): + sortkey = '%f%f%d' % (cg.start, cg.end, pid) + sortlist[sortkey] = cg + # create blocks for orphan cg data + for sortkey in sorted(sortlist): + cg = sortlist[sortkey] + name = cg.list[0].name + if sysvals.isCallgraphFunc(name): + vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name)) + cg.newActionFromFunction(test.data) + + if sysvals.suspendmode == 'command': + if(sysvals.verbose): + for data in testdata: + data.printDetails() + return testdata # fill in any missing phases for data in testdata: @@ -1587,14 +2446,52 @@ def parseTraceLog(): if(sysvals.verbose): data.printDetails() - # add the time in between the tests as a new phase so we can see it - if(len(testdata) > 1): - t1e = testdata[0].getEnd() - t2s = testdata[-1].getStart() - testdata[-1].newPhaseWithSingleAction('user mode', \ - 'user mode', t1e, t2s, '#FF9966') return testdata +# Function: loadRawKernelLog +# Description: +# Load a raw kernel log that wasn't created by this tool, it might be +# possible to extract a valid suspend/resume log +def loadRawKernelLog(dmesgfile): + global sysvals + + stamp = {'time': '', 'host': '', 'mode': 'mem', 'kernel': ''} + stamp['time'] = datetime.now().strftime('%B %d %Y, %I:%M:%S %p') + stamp['host'] = sysvals.hostname + + testruns = [] + data = 0 + lf = open(dmesgfile, 'r') + for line in lf: + line = line.replace('\r\n', '') + idx = line.find('[') + if idx > 1: + line = line[idx:] + m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + if(not m): + continue + msg = m.group("msg") + m = re.match('PM: Syncing filesystems.*', msg) + if(m): + if(data): + testruns.append(data) + data = Data(len(testruns)) + data.stamp = stamp + if(data): + m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) + if(m): + stamp['kernel'] = m.group('k') + m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg) + if(m): + stamp['mode'] = m.group('m') + data.dmesgtext.append(line) + if(data): + testruns.append(data) + sysvals.stamp = stamp + sysvals.suspendmode = stamp['mode'] + lf.close() + return testruns + # Function: loadKernelLog # Description: # [deprecated for kernel 3.15.0 or newer] @@ -1607,9 +2504,10 @@ def loadKernelLog(): vprint('Analyzing the dmesg data...') if(os.path.exists(sysvals.dmesgfile) == False): - doError('%s doesnt exist' % sysvals.dmesgfile, False) + doError('%s does not exist' % sysvals.dmesgfile, False) - # there can be multiple test runs in a single file delineated by stamps + # there can be multiple test runs in a single file + tp = TestProps() testruns = [] data = 0 lf = open(sysvals.dmesgfile, 'r') @@ -1620,35 +2518,43 @@ def loadKernelLog(): line = line[idx:] m = re.match(sysvals.stampfmt, line) if(m): - if(data): - testruns.append(data) - data = Data(len(testruns)) - parseStamp(m, data) - continue - if(not data): + tp.stamp = line continue m = re.match(sysvals.firmwarefmt, line) if(m): - data.fwSuspend = int(m.group('s')) - data.fwResume = int(m.group('r')) - if(data.fwSuspend > 0 or data.fwResume > 0): - data.fwValid = True + tp.fwdata.append((int(m.group('s')), int(m.group('r')))) continue m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) - if(m): - data.dmesgtext.append(line) - if(re.match('ACPI: resume from mwait', m.group('msg'))): - print('NOTE: This suspend appears to be freeze rather than'+\ - ' %s, it will be treated as such' % sysvals.suspendmode) - sysvals.suspendmode = 'freeze' - else: - vprint('ignoring dmesg line: %s' % line.replace('\n', '')) - testruns.append(data) + if(not m): + continue + msg = m.group("msg") + if(re.match('PM: Syncing filesystems.*', msg)): + if(data): + testruns.append(data) + data = Data(len(testruns)) + parseStamp(tp.stamp, data) + if len(tp.fwdata) > data.testnumber: + data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber] + if(data.fwSuspend > 0 or data.fwResume > 0): + data.fwValid = True + if(re.match('ACPI: resume from mwait', msg)): + print('NOTE: This suspend appears to be freeze rather than'+\ + ' %s, it will be treated as such' % sysvals.suspendmode) + sysvals.suspendmode = 'freeze' + if(not data): + continue + data.dmesgtext.append(line) + if(data): + testruns.append(data) lf.close() - if(not data): - print('ERROR: analyze_suspend header missing from dmesg log') - sys.exit() + if(len(testruns) < 1): + # bad log, but see if you can extract something meaningful anyway + testruns = loadRawKernelLog(sysvals.dmesgfile) + + if(len(testruns) < 1): + doError(' dmesg log is completely unreadable: %s' \ + % sysvals.dmesgfile, False) # fix lines with same timestamp/function with the call and return swapped for data in testruns: @@ -1865,7 +2771,8 @@ def parseKernelLog(data): actions[a] = [] actions[a].append({'begin': ktime, 'end': ktime}) if(re.match(at[a]['emsg'], msg)): - actions[a][-1]['end'] = ktime + if(a in actions): + actions[a][-1]['end'] = ktime # now look for CPU on/off events if(re.match('Disabling non-boot CPUs .*', msg)): # start of first cpu suspend @@ -1912,15 +2819,7 @@ def parseKernelLog(data): # fill in any actions we've found for name in actions: for event in actions[name]: - begin = event['begin'] - end = event['end'] - # if event starts before timeline start, expand timeline - if(begin < data.start): - data.setStart(begin) - # if event ends after timeline end, expand the timeline - if(end > data.end): - data.setEnd(end) - data.newActionGlobal(name, begin, end) + data.newActionGlobal(name, event['begin'], event['end']) if(sysvals.verbose): data.printDetails() @@ -1929,92 +2828,6 @@ def parseKernelLog(data): data.fixupInitcallsThatDidntReturn() return True -# Function: setTimelineRows -# Description: -# Organize the timeline entries into the smallest -# number of rows possible, with no entry overlapping -# Arguments: -# list: the list of devices/actions for a single phase -# sortedkeys: cronologically sorted key list to use -# Output: -# The total number of rows needed to display this phase of the timeline -def setTimelineRows(list, sortedkeys): - - # clear all rows and set them to undefined - remaining = len(list) - rowdata = dict() - row = 0 - for item in list: - list[item]['row'] = -1 - - # try to pack each row with as many ranges as possible - while(remaining > 0): - if(row not in rowdata): - rowdata[row] = [] - for item in sortedkeys: - if(list[item]['row'] < 0): - s = list[item]['start'] - e = list[item]['end'] - valid = True - for ritem in rowdata[row]: - rs = ritem['start'] - re = ritem['end'] - if(not (((s <= rs) and (e <= rs)) or - ((s >= re) and (e >= re)))): - valid = False - break - if(valid): - rowdata[row].append(list[item]) - list[item]['row'] = row - remaining -= 1 - row += 1 - return row - -# Function: createTimeScale -# Description: -# Create the timescale header for the html timeline -# Arguments: -# t0: start time (suspend begin) -# tMax: end time (resume end) -# tSuspend: time when suspend occurs, i.e. the zero time -# Output: -# The html code needed to display the time scale -def createTimeScale(t0, tMax, tSuspended): - timescale = '<div class="t" style="right:{0}%">{1}</div>\n' - output = '<div id="timescale">\n' - - # set scale for timeline - tTotal = tMax - t0 - tS = 0.1 - if(tTotal <= 0): - return output - if(tTotal > 4): - tS = 1 - if(tSuspended < 0): - for i in range(int(tTotal/tS)+1): - pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal)) - if(i > 0): - val = '%0.fms' % (float(i)*tS*1000) - else: - val = '' - output += timescale.format(pos, val) - else: - tSuspend = tSuspended - t0 - divTotal = int(tTotal/tS) + 1 - divSuspend = int(tSuspend/tS) - s0 = (tSuspend - tS*divSuspend)*100/tTotal - for i in range(divTotal): - pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0) - if((i == 0) and (s0 < 3)): - val = '' - elif(i == divSuspend): - val = 'S/R' - else: - val = '%0.fms' % (float(i-divSuspend)*tS*1000) - output += timescale.format(pos, val) - output += '</div>\n' - return output - # Function: createHTMLSummarySimple # Description: # Create summary html file for a series of tests @@ -2146,6 +2959,32 @@ def createHTMLSummarySimple(testruns, htmlfile): hf.write('</body>\n</html>\n') hf.close() +def htmlTitle(): + global sysvals + modename = { + 'freeze': 'Freeze (S0)', + 'standby': 'Standby (S1)', + 'mem': 'Suspend (S3)', + 'disk': 'Hibernate (S4)' + } + kernel = sysvals.stamp['kernel'] + host = sysvals.hostname[0].upper()+sysvals.hostname[1:] + mode = sysvals.suspendmode + if sysvals.suspendmode in modename: + mode = modename[sysvals.suspendmode] + return host+' '+mode+' '+kernel + +def ordinal(value): + suffix = 'th' + if value < 10 or value > 19: + if value % 10 == 1: + suffix = 'st' + elif value % 10 == 2: + suffix = 'nd' + elif value % 10 == 3: + suffix = 'rd' + return '%d%s' % (value, suffix) + # Function: createHTML # Description: # Create the output html file from the resident test data @@ -2156,6 +2995,10 @@ def createHTMLSummarySimple(testruns, htmlfile): def createHTML(testruns): global sysvals + if len(testruns) < 1: + print('ERROR: Not enough test data to build a timeline') + return + for data in testruns: data.normalizeTime(testruns[-1].tSuspended) @@ -2163,16 +3006,18 @@ def createHTML(testruns): if len(testruns) > 1: x2changes = ['1', 'relative'] # html function templates + headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0] html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n' html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n' html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n' - html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n' - html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n' - html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n' + html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;">\n' + html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n' + html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{5}</div>\n' + html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n' html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n' - html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n' + html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n' html_timetotal = '<table class="time1">\n<tr>'\ '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\ '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\ @@ -2182,6 +3027,10 @@ def createHTML(testruns): '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\ '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\ '</tr>\n</table>\n' + html_timetotal3 = '<table class="time1">\n<tr>'\ + '<td class="green">Execution Time: <b>{0} ms</b></td>'\ + '<td class="yellow">Command: <b>{1}</b></td>'\ + '</tr>\n</table>\n' html_timegroups = '<table class="time2">\n<tr>'\ '<td class="green">{4}Kernel Suspend: {0} ms</td>'\ '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\ @@ -2189,12 +3038,21 @@ def createHTML(testruns): '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\ '</tr>\n</table>\n' + # html format variables + rowheight = 30 + devtextS = '14px' + devtextH = '30px' + hoverZ = 'z-index:10;' + + if sysvals.usedevsrc: + hoverZ = '' + # device timeline vprint('Creating Device Timeline...') - devtl = Timeline() + + devtl = Timeline(rowheight) # Generate the header for this timeline - textnum = ['First', 'Second'] for data in testruns: tTotal = data.end - data.start tEnd = data.dmesg['resume_complete']['end'] @@ -2203,7 +3061,17 @@ def createHTML(testruns): sys.exit() if(data.tLow > 0): low_time = '%.0f'%(data.tLow*1000) - if data.fwValid: + if sysvals.suspendmode == 'command': + run_time = '%.0f'%((data.end-data.start)*1000) + if sysvals.testcommand: + testdesc = sysvals.testcommand + else: + testdesc = 'unknown' + if(len(testruns) > 1): + testdesc = ordinal(data.testnumber+1)+' '+testdesc + thtml = html_timetotal3.format(run_time, testdesc) + devtl.html['header'] += thtml + elif data.fwValid: suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \ (data.fwSuspend/1000000.0)) resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \ @@ -2211,7 +3079,7 @@ def createHTML(testruns): testdesc1 = 'Total' testdesc2 = '' if(len(testruns) > 1): - testdesc1 = testdesc2 = textnum[data.testnumber] + testdesc1 = testdesc2 = ordinal(data.testnumber+1) testdesc2 += ' ' if(data.tLow == 0): thtml = html_timetotal.format(suspend_time, \ @@ -2219,28 +3087,28 @@ def createHTML(testruns): else: thtml = html_timetotal2.format(suspend_time, low_time, \ resume_time, testdesc1) - devtl.html['timeline'] += thtml + devtl.html['header'] += thtml sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \ data.getStart())*1000) sftime = '%.3f'%(data.fwSuspend / 1000000.0) rftime = '%.3f'%(data.fwResume / 1000000.0) - rktime = '%.3f'%((data.getEnd() - \ + rktime = '%.3f'%((data.dmesg['resume_complete']['end'] - \ data.dmesg['resume_machine']['start'])*1000) - devtl.html['timeline'] += html_timegroups.format(sktime, \ + devtl.html['header'] += html_timegroups.format(sktime, \ sftime, rftime, rktime, testdesc2) else: suspend_time = '%.0f'%((data.tSuspended-data.start)*1000) resume_time = '%.0f'%((tEnd-data.tSuspended)*1000) testdesc = 'Kernel' if(len(testruns) > 1): - testdesc = textnum[data.testnumber]+' '+testdesc + testdesc = ordinal(data.testnumber+1)+' '+testdesc if(data.tLow == 0): thtml = html_timetotal.format(suspend_time, \ resume_time, testdesc) else: thtml = html_timetotal2.format(suspend_time, low_time, \ resume_time, testdesc) - devtl.html['timeline'] += thtml + devtl.html['header'] += thtml # time scale for potentially multiple datasets t0 = testruns[0].start @@ -2249,153 +3117,241 @@ def createHTML(testruns): tTotal = tMax - t0 # determine the maximum number of rows we need to draw - timelinerows = 0 for data in testruns: - for phase in data.dmesg: - list = data.dmesg[phase]['list'] - rows = setTimelineRows(list, list) - data.dmesg[phase]['row'] = rows - if(rows > timelinerows): - timelinerows = rows - - # calculate the timeline height and create bounding box, add buttons - devtl.setRows(timelinerows + 1) - devtl.html['timeline'] += html_devlist1 - if len(testruns) > 1: - devtl.html['timeline'] += html_devlist2 + data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen) + for group in data.devicegroups: + devlist = [] + for phase in group: + for devname in data.tdevlist[phase]: + devlist.append((phase,devname)) + devtl.getPhaseRows(data.dmesg, devlist) + devtl.calcTotalRows() + + # create bounding box, add buttons + if sysvals.suspendmode != 'command': + devtl.html['timeline'] += html_devlist1 + if len(testruns) > 1: + devtl.html['timeline'] += html_devlist2 devtl.html['timeline'] += html_zoombox devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) - # draw the colored boxes for each of the phases - for data in testruns: - for b in data.dmesg: - phase = data.dmesg[b] - length = phase['end']-phase['start'] - left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) - width = '%.3f' % ((length*100.0)/tTotal) - devtl.html['timeline'] += html_phase.format(left, width, \ - '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \ - data.dmesg[b]['color'], '') + # draw the full timeline + phases = {'suspend':[],'resume':[]} + for phase in data.dmesg: + if 'resume' in phase: + phases['resume'].append(phase) + else: + phases['suspend'].append(phase) - # draw the time scale, try to make the number of labels readable - devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended) - devtl.html['timeline'] += devtl.html['scale'] + # draw each test run chronologically for data in testruns: - for b in data.dmesg: - phaselist = data.dmesg[b]['list'] - for d in phaselist: - name = d - drv = '' - dev = phaselist[d] - if(d in sysvals.altdevname): - name = sysvals.altdevname[d] - if('drv' in dev and dev['drv']): - drv = ' {%s}' % dev['drv'] - height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] - top = '%.3f' % ((dev['row']*height) + devtl.scaleH) - left = '%.3f' % (((dev['start']-t0)*100)/tTotal) - width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal) - length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) - color = 'rgba(204,204,204,0.5)' - devtl.html['timeline'] += html_device.format(dev['id'], \ - d+drv+length+b, left, top, '%.3f'%height, width, name+drv) - - # draw any trace events found - for data in testruns: - for b in data.dmesg: - phaselist = data.dmesg[b]['list'] - for name in phaselist: - dev = phaselist[name] - if('traceevents' in dev): - vprint('Debug trace events found for device %s' % name) - vprint('%20s %20s %10s %8s' % ('action', \ + # if nore than one test, draw a block to represent user mode + if(data.testnumber > 0): + m0 = testruns[data.testnumber-1].end + mMax = testruns[data.testnumber].start + mTotal = mMax - m0 + name = 'usermode%d' % data.testnumber + top = '%d' % devtl.scaleH + left = '%f' % (((m0-t0)*100.0)/tTotal) + width = '%f' % ((mTotal*100.0)/tTotal) + title = 'user mode (%0.3f ms) ' % (mTotal*1000) + devtl.html['timeline'] += html_device.format(name, \ + title, left, top, '%d'%devtl.bodyH, width, '', '', '') + # now draw the actual timeline blocks + for dir in phases: + # draw suspend and resume blocks separately + bname = '%s%d' % (dir[0], data.testnumber) + if dir == 'suspend': + m0 = testruns[data.testnumber].start + mMax = testruns[data.testnumber].tSuspended + mTotal = mMax - m0 + left = '%f' % (((m0-t0)*100.0)/tTotal) + else: + m0 = testruns[data.testnumber].tSuspended + mMax = testruns[data.testnumber].end + mTotal = mMax - m0 + left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal) + # if a timeline block is 0 length, skip altogether + if mTotal == 0: + continue + width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal) + devtl.html['timeline'] += html_tblock.format(bname, left, width) + for b in sorted(phases[dir]): + # draw the phase color background + phase = data.dmesg[b] + length = phase['end']-phase['start'] + left = '%f' % (((phase['start']-m0)*100.0)/mTotal) + width = '%f' % ((length*100.0)/mTotal) + devtl.html['timeline'] += html_phase.format(left, width, \ + '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ + data.dmesg[b]['color'], '') + # draw the devices for this phase + phaselist = data.dmesg[b]['list'] + for d in data.tdevlist[b]: + name = d + drv = '' + dev = phaselist[d] + xtraclass = '' + xtrainfo = '' + xtrastyle = '' + if 'htmlclass' in dev: + xtraclass = dev['htmlclass'] + xtrainfo = dev['htmlclass'] + if 'color' in dev: + xtrastyle = 'background-color:%s;' % dev['color'] + if(d in sysvals.devprops): + name = sysvals.devprops[d].altName(d) + xtraclass = sysvals.devprops[d].xtraClass() + xtrainfo = sysvals.devprops[d].xtraInfo() + if('drv' in dev and dev['drv']): + drv = ' {%s}' % dev['drv'] + rowheight = devtl.phaseRowHeight(b, dev['row']) + rowtop = devtl.phaseRowTop(b, dev['row']) + top = '%.3f' % (rowtop + devtl.scaleH) + left = '%f' % (((dev['start']-m0)*100)/mTotal) + width = '%f' % (((dev['end']-dev['start'])*100)/mTotal) + length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) + if sysvals.suspendmode == 'command': + title = name+drv+xtrainfo+length+'cmdexec' + else: + title = name+drv+xtrainfo+length+b + devtl.html['timeline'] += html_device.format(dev['id'], \ + title, left, top, '%.3f'%rowheight, width, \ + d+drv, xtraclass, xtrastyle) + if('src' not in dev): + continue + # draw any trace events for this device + vprint('Debug trace events found for device %s' % d) + vprint('%20s %20s %10s %8s' % ('title', \ 'name', 'time(ms)', 'length(ms)')) - for e in dev['traceevents']: - vprint('%20s %20s %10.3f %8.3f' % (e.action, \ - e.name, e.time*1000, e.length*1000)) - height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] - top = '%.3f' % ((dev['row']*height) + devtl.scaleH) - left = '%.3f' % (((e.time-t0)*100)/tTotal) - width = '%.3f' % (e.length*100/tTotal) + for e in dev['src']: + vprint('%20s %20s %10.3f %8.3f' % (e.title, \ + e.text, e.time*1000, e.length*1000)) + height = devtl.rowH + top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH)) + left = '%f' % (((e.time-m0)*100)/mTotal) + width = '%f' % (e.length*100/mTotal) color = 'rgba(204,204,204,0.5)' devtl.html['timeline'] += \ - html_traceevent.format(e.action+' '+e.name, \ + html_traceevent.format(e.title, \ left, top, '%.3f'%height, \ - width, e.color, '') + width, e.text) + # draw the time scale, try to make the number of labels readable + devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir) + devtl.html['timeline'] += '</div>\n' # timeline is finished devtl.html['timeline'] += '</div>\n</div>\n' # draw a legend which describes the phases by color - data = testruns[-1] - devtl.html['legend'] = '<div class="legend">\n' - pdelta = 100.0/len(data.phases) - pmargin = pdelta / 4.0 - for phase in data.phases: - order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) - name = string.replace(phase, '_', ' ') - devtl.html['legend'] += html_legend.format(order, \ - data.dmesg[phase]['color'], name) - devtl.html['legend'] += '</div>\n' + if sysvals.suspendmode != 'command': + data = testruns[-1] + devtl.html['legend'] = '<div class="legend">\n' + pdelta = 100.0/len(data.phases) + pmargin = pdelta / 4.0 + for phase in data.phases: + tmp = phase.split('_') + id = tmp[0][0] + if(len(tmp) > 1): + id += tmp[1][0] + order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) + name = string.replace(phase, '_', ' ') + devtl.html['legend'] += html_legend.format(order, \ + data.dmesg[phase]['color'], name, id) + devtl.html['legend'] += '</div>\n' hf = open(sysvals.htmlfile, 'w') - thread_height = 0 + + if not sysvals.cgexp: + cgchk = 'checked' + cgnchk = 'not(:checked)' + else: + cgchk = 'not(:checked)' + cgnchk = 'checked' # write the html header first (html head, css code, up to body start) html_header = '<!DOCTYPE html>\n<html>\n<head>\n\ <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ - <title>AnalyzeSuspend</title>\n\ + <title>'+htmlTitle()+'</title>\n\ <style type=\'text/css\'>\n\ - body {overflow-y: scroll;}\n\ - .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\ - .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\ - .callgraph article * {padding-left: 28px;}\n\ - h1 {color:black;font: bold 30px Times;}\n\ - t0 {color:black;font: bold 30px Times;}\n\ - t1 {color:black;font: 30px Times;}\n\ - t2 {color:black;font: 25px Times;}\n\ - t3 {color:black;font: 20px Times;white-space:nowrap;}\n\ - t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\ + body {overflow-y:scroll;}\n\ + .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\ + .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\ + .callgraph article * {padding-left:28px;}\n\ + h1 {color:black;font:bold 30px Times;}\n\ + t0 {color:black;font:bold 30px Times;}\n\ + t1 {color:black;font:30px Times;}\n\ + t2 {color:black;font:25px Times;}\n\ + t3 {color:black;font:20px Times;white-space:nowrap;}\n\ + t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\ + cS {color:blue;font:bold 11px Times;}\n\ + cR {color:red;font:bold 11px Times;}\n\ table {width:100%;}\n\ .gray {background-color:rgba(80,80,80,0.1);}\n\ .green {background-color:rgba(204,255,204,0.4);}\n\ .purple {background-color:rgba(128,0,128,0.2);}\n\ .yellow {background-color:rgba(255,255,204,0.4);}\n\ - .time1 {font: 22px Arial;border:1px solid;}\n\ - .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ - td {text-align: center;}\n\ + .time1 {font:22px Arial;border:1px solid;}\n\ + .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ + td {text-align:center;}\n\ r {color:#500000;font:15px Tahoma;}\n\ n {color:#505050;font:15px Tahoma;}\n\ - .tdhl {color: red;}\n\ - .hide {display: none;}\n\ - .pf {display: none;}\n\ - .pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ - .pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ - .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\ - .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\ - .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\ - .thread {position: absolute; height: '+'%.3f'%thread_height+'%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\ - .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\ - .hover {background-color:white;border:1px solid red;z-index:10;}\n\ - .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\ - .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\ + .tdhl {color:red;}\n\ + .hide {display:none;}\n\ + .pf {display:none;}\n\ + .pf:'+cgchk+' + label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ + .pf:'+cgnchk+' ~ label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\ + .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\ + .zoombox {position:relative;width:100%;overflow-x:scroll;}\n\ + .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\ + .thread {position:absolute;height:0%;overflow:hidden;line-height:'+devtextH+';font-size:'+devtextS+';border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\ + .thread.sync {background-color:'+sysvals.synccolor+';}\n\ + .thread.bg {background-color:'+sysvals.kprobecolor+';}\n\ + .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\ + .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\ + .hover.sync {background-color:white;}\n\ + .hover.bg {background-color:white;}\n\ + .traceevent {position:absolute;font-size:10px;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,rgba(204,204,204,1),rgba(150,150,150,1));}\n\ + .traceevent:hover {background:white;}\n\ + .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\ .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\ - .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\ - .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\ - .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\ + .t {z-index:2;position:absolute;pointer-events:none;top:0%;height:100%;border-right:1px solid black;}\n\ + .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\ + .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\ button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ + .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\ .devlist {position:'+x2changes[1]+';width:190px;}\n\ - #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\ + a:link {color:white;text-decoration:none;}\n\ + a:visited {color:white;}\n\ + a:hover {color:white;}\n\ + a:active {color:white;}\n\ + .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\ + #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\ + .tblock {position:absolute;height:100%;}\n\ + .bg {z-index:1;}\n\ </style>\n</head>\n<body>\n' - hf.write(html_header) + + # 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: + hf.write(html_header) # write the test title and general info header if(sysvals.stamp['time'] != ""): + hf.write(headline_version) + if sysvals.addlogs and sysvals.dmesgfile: + hf.write('<button id="showdmesg" class="logbtn">dmesg</button>') + if sysvals.addlogs and sysvals.ftracefile: + hf.write('<button id="showftrace" class="logbtn">ftrace</button>') hf.write(headline_stamp.format(sysvals.stamp['host'], sysvals.stamp['kernel'], sysvals.stamp['mode'], \ sysvals.stamp['time'])) # write the device timeline + hf.write(devtl.html['header']) hf.write(devtl.html['timeline']) hf.write(devtl.html['legend']) hf.write('<div id="devicedetailtitle"></div>\n') @@ -2410,12 +3366,15 @@ def createHTML(testruns): width = '%.3f' % ((length*100.0)/tTotal) hf.write(html_phaselet.format(b, left, width, \ data.dmesg[b]['color'])) + if sysvals.suspendmode == 'command': + hf.write(html_phaselet.format('cmdexec', '0', '0', \ + data.dmesg['resume_complete']['color'])) hf.write('</div>\n') hf.write('</div>\n') # write the ftrace data (callgraph) data = testruns[-1] - if(sysvals.usecallgraph): + if(sysvals.usecallgraph and not sysvals.embedded): hf.write('<section id="callgraphs" class="callgraph">\n') # write out the ftrace data converted to html html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n' @@ -2428,22 +3387,29 @@ def createHTML(testruns): for devname in data.sortedDevices(p): if('ftrace' not in list[devname]): continue - name = devname - if(devname in sysvals.altdevname): - name = sysvals.altdevname[devname] devid = list[devname]['id'] cg = list[devname]['ftrace'] - flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \ - ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000) + clen = (cg.end - cg.start) * 1000 + if clen < sysvals.mincglen: + continue + fmt = '<r>(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')</r>' + flen = fmt % (clen, cg.start, cg.end) + name = devname + if(devname in sysvals.devprops): + name = sysvals.devprops[devname].altName(devname) + if sysvals.suspendmode == 'command': + ftitle = name + else: + ftitle = name+' '+p hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \ - num, name+' '+p, flen)) + num, ftitle, flen)) num += 1 for line in cg.list: if(line.length < 0.000000001): flen = '' else: - flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \ - line.time*1000) + fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>' + flen = fmt % (line.length*1000, line.time) if(line.freturn and line.fcall): hf.write(html_func_leaf.format(line.name, flen)) elif(line.freturn): @@ -2453,9 +3419,40 @@ def createHTML(testruns): num += 1 hf.write(html_func_end) hf.write('\n\n </section>\n') - # write the footer and close - addScriptCode(hf, testruns) - hf.write('</body>\n</html>\n') + + # add the dmesg log as a hidden div + if sysvals.addlogs and sysvals.dmesgfile: + hf.write('<div id="dmesglog" style="display:none;">\n') + lf = open(sysvals.dmesgfile, 'r') + for line in lf: + hf.write(line) + lf.close() + hf.write('</div>\n') + # add the ftrace log as a hidden div + if sysvals.addlogs and sysvals.ftracefile: + hf.write('<div id="ftracelog" style="display:none;">\n') + lf = open(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') hf.close() return True @@ -2466,8 +3463,8 @@ def createHTML(testruns): # hf: the open html file pointer # testruns: array of Data objects from parseKernelLog or parseTraceLog def addScriptCode(hf, testruns): - t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000 - tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000 + t0 = testruns[0].start * 1000 + tMax = testruns[-1].end * 1000 # create an array in javascript memory with the device details detail = ' var devtable = [];\n' for data in testruns: @@ -2477,8 +3474,43 @@ def addScriptCode(hf, testruns): # add the code which will manipulate the data in the browser script_code = \ '<script type="text/javascript">\n'+detail+\ + ' var resolution = -1;\n'\ + ' function redrawTimescale(t0, tMax, tS) {\n'\ + ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cR><-R</cR></div>\';\n'\ + ' var tTotal = tMax - t0;\n'\ + ' var list = document.getElementsByClassName("tblock");\n'\ + ' for (var i = 0; i < list.length; i++) {\n'\ + ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\ + ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\ + ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\ + ' var mMax = m0 + mTotal;\n'\ + ' var html = "";\n'\ + ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\ + ' if(divTotal > 1000) continue;\n'\ + ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\ + ' var pos = 0.0, val = 0.0;\n'\ + ' for (var j = 0; j < divTotal; j++) {\n'\ + ' var htmlline = "";\n'\ + ' if(list[i].id[5] == "r") {\n'\ + ' pos = 100 - (((j)*tS*100)/mTotal);\n'\ + ' val = (j)*tS;\n'\ + ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\ + ' if(j == 0)\n'\ + ' htmlline = rline;\n'\ + ' } else {\n'\ + ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\ + ' val = (j-divTotal+1)*tS;\n'\ + ' if(j == divTotal - 1)\n'\ + ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S-></cS></div>\';\n'\ + ' else\n'\ + ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\ + ' }\n'\ + ' html += htmlline;\n'\ + ' }\n'\ + ' timescale.innerHTML = html;\n'\ + ' }\n'\ + ' }\n'\ ' function zoomTimeline() {\n'\ - ' var timescale = document.getElementById("timescale");\n'\ ' var dmesg = document.getElementById("dmesg");\n'\ ' var zoombox = document.getElementById("dmesgzoombox");\n'\ ' var val = parseFloat(dmesg.style.width);\n'\ @@ -2486,7 +3518,7 @@ def addScriptCode(hf, testruns): ' var sh = window.outerWidth / 2;\n'\ ' if(this.id == "zoomin") {\n'\ ' newval = val * 1.2;\n'\ - ' if(newval > 40000) newval = 40000;\n'\ + ' if(newval > 910034) newval = 910034;\n'\ ' dmesg.style.width = newval+"%";\n'\ ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\ ' } else if (this.id == "zoomout") {\n'\ @@ -2498,19 +3530,17 @@ def addScriptCode(hf, testruns): ' zoombox.scrollLeft = 0;\n'\ ' dmesg.style.width = "100%";\n'\ ' }\n'\ - ' var html = "";\n'\ + ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\ ' var t0 = bounds[0];\n'\ ' var tMax = bounds[1];\n'\ ' var tTotal = tMax - t0;\n'\ ' var wTotal = tTotal * 100.0 / newval;\n'\ - ' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\ - ' if(tS < 1) tS = 1;\n'\ - ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\ - ' var pos = (tMax - s) * 100.0 / tTotal;\n'\ - ' var name = (s == 0)?"S/R":(s+"ms");\n'\ - ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\ - ' }\n'\ - ' timescale.innerHTML = html;\n'\ + ' var idx = 7*window.innerWidth/1100;\n'\ + ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\ + ' if(i >= tS.length) i = tS.length - 1;\n'\ + ' if(tS[i] == resolution) return;\n'\ + ' resolution = tS[i];\n'\ + ' redrawTimescale(t0, tMax, tS[i]);\n'\ ' }\n'\ ' function deviceHover() {\n'\ ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\ @@ -2523,12 +3553,13 @@ def addScriptCode(hf, testruns): ' cpu = parseInt(name.slice(8));\n'\ ' for (var i = 0; i < dev.length; i++) {\n'\ ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\ + ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\ ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ ' (name == dname))\n'\ ' {\n'\ - ' dev[i].className = "thread hover";\n'\ + ' dev[i].className = "hover "+cname;\n'\ ' } else {\n'\ - ' dev[i].className = "thread";\n'\ + ' dev[i].className = cname;\n'\ ' }\n'\ ' }\n'\ ' }\n'\ @@ -2536,7 +3567,7 @@ def addScriptCode(hf, testruns): ' var dmesg = document.getElementById("dmesg");\n'\ ' var dev = dmesg.getElementsByClassName("thread");\n'\ ' for (var i = 0; i < dev.length; i++) {\n'\ - ' dev[i].className = "thread";\n'\ + ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\ ' }\n'\ ' }\n'\ ' function deviceTitle(title, total, cpu) {\n'\ @@ -2547,7 +3578,7 @@ def addScriptCode(hf, testruns): ' total[2] = (total[2]+total[4])/2;\n'\ ' }\n'\ ' var devtitle = document.getElementById("devicedetailtitle");\n'\ - ' var name = title.slice(0, title.indexOf(" "));\n'\ + ' var name = title.slice(0, title.indexOf(" ("));\n'\ ' if(cpu >= 0) name = "CPU"+cpu;\n'\ ' var driver = "";\n'\ ' var tS = "<t2>(</t2>";\n'\ @@ -2579,6 +3610,8 @@ def addScriptCode(hf, testruns): ' var dev = dmesg.getElementsByClassName("thread");\n'\ ' var idlist = [];\n'\ ' var pdata = [[]];\n'\ + ' if(document.getElementById("devicedetail1"))\n'\ + ' pdata = [[], []];\n'\ ' var pd = pdata[0];\n'\ ' var total = [0.0, 0.0, 0.0];\n'\ ' for (var i = 0; i < dev.length; i++) {\n'\ @@ -2634,6 +3667,7 @@ def addScriptCode(hf, testruns): ' var cglist = document.getElementById("callgraphs");\n'\ ' if(!cglist) return;\n'\ ' var cg = cglist.getElementsByClassName("atop");\n'\ + ' if(cg.length < 10) return;\n'\ ' for (var i = 0; i < cg.length; i++) {\n'\ ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\ ' cg[i].style.display = "block";\n'\ @@ -2658,15 +3692,32 @@ def addScriptCode(hf, testruns): ' dt = devtable[1];\n'\ ' win.document.write(html+dt);\n'\ ' }\n'\ + ' function logWindow(e) {\n'\ + ' var name = e.target.id.slice(4);\n'\ + ' var win = window.open();\n'\ + ' var log = document.getElementById(name+"log");\n'\ + ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\ + ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\ + ' win.document.close();\n'\ + ' }\n'\ + ' function onClickPhase(e) {\n'\ + ' }\n'\ + ' window.addEventListener("resize", function () {zoomTimeline();});\n'\ ' window.addEventListener("load", function () {\n'\ ' var dmesg = document.getElementById("dmesg");\n'\ ' dmesg.style.width = "100%"\n'\ ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ - ' var devlist = document.getElementsByClassName("devlist");\n'\ - ' for (var i = 0; i < devlist.length; i++)\n'\ - ' devlist[i].onclick = devListWindow;\n'\ + ' var list = document.getElementsByClassName("square");\n'\ + ' for (var i = 0; i < list.length; i++)\n'\ + ' list[i].onclick = onClickPhase;\n'\ + ' var list = document.getElementsByClassName("logbtn");\n'\ + ' for (var i = 0; i < list.length; i++)\n'\ + ' list[i].onclick = logWindow;\n'\ + ' list = document.getElementsByClassName("devlist");\n'\ + ' for (var i = 0; i < list.length; i++)\n'\ + ' list[i].onclick = devListWindow;\n'\ ' var dev = dmesg.getElementsByClassName("thread");\n'\ ' for (var i = 0; i < dev.length; i++) {\n'\ ' dev[i].onclick = deviceDetail;\n'\ @@ -2685,141 +3736,87 @@ def addScriptCode(hf, testruns): def executeSuspend(): global sysvals - detectUSB(False) t0 = time.time()*1000 tp = sysvals.tpath + fwdata = [] + # mark the start point in the kernel ring buffer just as we start + sysvals.initdmesg() + # start ftrace + if(sysvals.usecallgraph or sysvals.usetraceevents): + print('START TRACING') + sysvals.fsetVal('1', 'tracing_on') # execute however many s/r runs requested for count in range(1,sysvals.execcount+1): - # clear the kernel ring buffer just as we start - os.system('dmesg -C') - # enable callgraph ftrace only for the second run - if(sysvals.usecallgraph and count == 2): - # set trace type - os.system('echo function_graph > '+tp+'current_tracer') - os.system('echo "" > '+tp+'set_ftrace_filter') - # set trace format options - os.system('echo funcgraph-abstime > '+tp+'trace_options') - os.system('echo funcgraph-proc > '+tp+'trace_options') - # focus only on device suspend and resume - os.system('cat '+tp+'available_filter_functions | '+\ - 'grep dpm_run_callback > '+tp+'set_graph_function') # if this is test2 and there's a delay, start here if(count > 1 and sysvals.x2delay > 0): tN = time.time()*1000 while (tN - t0) < sysvals.x2delay: tN = time.time()*1000 time.sleep(0.001) - # start ftrace - if(sysvals.usecallgraph or sysvals.usetraceevents): - print('START TRACING') - os.system('echo 1 > '+tp+'tracing_on') # initiate suspend if(sysvals.usecallgraph or sysvals.usetraceevents): - os.system('echo SUSPEND START > '+tp+'trace_marker') - if(sysvals.rtcwake): - print('SUSPEND START') - print('will autoresume in %d seconds' % sysvals.rtcwaketime) - sysvals.rtcWakeAlarm() + sysvals.fsetVal('SUSPEND START', 'trace_marker') + if sysvals.suspendmode == 'command': + print('COMMAND START') + if(sysvals.rtcwake): + print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) + sysvals.rtcWakeAlarmOn() + os.system(sysvals.testcommand) else: - print('SUSPEND START (press a key to resume)') - pf = open(sysvals.powerfile, 'w') - pf.write(sysvals.suspendmode) - # execution will pause here - pf.close() + if(sysvals.rtcwake): + print('SUSPEND START') + print('will autoresume in %d seconds' % sysvals.rtcwaketime) + sysvals.rtcWakeAlarmOn() + else: + print('SUSPEND START (press a key to resume)') + pf = open(sysvals.powerfile, 'w') + pf.write(sysvals.suspendmode) + # execution will pause here + try: + pf.close() + except: + pass t0 = time.time()*1000 + if(sysvals.rtcwake): + sysvals.rtcWakeAlarmOff() # return from suspend print('RESUME COMPLETE') if(sysvals.usecallgraph or sysvals.usetraceevents): - os.system('echo RESUME COMPLETE > '+tp+'trace_marker') - # see if there's firmware timing data to be had - t = sysvals.postresumetime - if(t > 0): - print('Waiting %d seconds for POST-RESUME trace events...' % t) - time.sleep(t) - # stop ftrace - if(sysvals.usecallgraph or sysvals.usetraceevents): - os.system('echo 0 > '+tp+'tracing_on') - print('CAPTURING TRACE') - writeDatafileHeader(sysvals.ftracefile) - os.system('cat '+tp+'trace >> '+sysvals.ftracefile) - os.system('echo "" > '+tp+'trace') - # grab a copy of the dmesg output - print('CAPTURING DMESG') - writeDatafileHeader(sysvals.dmesgfile) - os.system('dmesg -c >> '+sysvals.dmesgfile) - -def writeDatafileHeader(filename): + sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') + if(sysvals.suspendmode == 'mem'): + fwdata.append(getFPDT(False)) + # look for post resume events after the last test run + t = sysvals.postresumetime + if(t > 0): + print('Waiting %d seconds for POST-RESUME trace events...' % t) + time.sleep(t) + # stop ftrace + if(sysvals.usecallgraph or sysvals.usetraceevents): + sysvals.fsetVal('0', 'tracing_on') + print('CAPTURING TRACE') + writeDatafileHeader(sysvals.ftracefile, fwdata) + os.system('cat '+tp+'trace >> '+sysvals.ftracefile) + sysvals.fsetVal('', 'trace') + devProps() + # grab a copy of the dmesg output + print('CAPTURING DMESG') + writeDatafileHeader(sysvals.dmesgfile, fwdata) + sysvals.getdmesg() + +def writeDatafileHeader(filename, fwdata): global sysvals - fw = getFPDT(False) prt = sysvals.postresumetime fp = open(filename, 'a') fp.write(sysvals.teststamp+'\n') - if(fw): - fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) + if(sysvals.suspendmode == 'mem'): + for fw in fwdata: + if(fw): + fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) if(prt > 0): fp.write('# post resume time %u\n' % prt) fp.close() -# Function: executeAndroidSuspend -# Description: -# Execute system suspend through the sysfs interface -# on a remote android device, then transfer the output -# dmesg and ftrace files to the local output directory. -def executeAndroidSuspend(): - global sysvals - - # check to see if the display is currently off - tp = sysvals.tpath - out = os.popen(sysvals.adb+\ - ' shell dumpsys power | grep mScreenOn').read().strip() - # if so we need to turn it on so we can issue a new suspend - if(out.endswith('false')): - print('Waking the device up for the test...') - # send the KEYPAD_POWER keyevent to wake it up - os.system(sysvals.adb+' shell input keyevent 26') - # wait a few seconds so the user can see the device wake up - time.sleep(3) - # execute however many s/r runs requested - for count in range(1,sysvals.execcount+1): - # clear the kernel ring buffer just as we start - os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1') - # start ftrace - if(sysvals.usetraceevents): - print('START TRACING') - os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'") - # initiate suspend - for count in range(1,sysvals.execcount+1): - if(sysvals.usetraceevents): - os.system(sysvals.adb+\ - " shell 'echo SUSPEND START > "+tp+"trace_marker'") - print('SUSPEND START (press a key on the device to resume)') - os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\ - " > "+sysvals.powerfile+"'") - # execution will pause here, then adb will exit - while(True): - check = os.popen(sysvals.adb+\ - ' shell pwd 2>/dev/null').read().strip() - if(len(check) > 0): - break - time.sleep(1) - if(sysvals.usetraceevents): - os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\ - "trace_marker'") - # return from suspend - print('RESUME COMPLETE') - # stop ftrace - if(sysvals.usetraceevents): - os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'") - print('CAPTURING TRACE') - os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile) - os.system(sysvals.adb+' shell cat '+tp+\ - 'trace >> '+sysvals.ftracefile) - # grab a copy of the dmesg output - print('CAPTURING DMESG') - os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile) - os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile) - # Function: setUSBDevicesAuto # Description: # Set the autosuspend control parameter of all USB devices to auto @@ -2829,7 +3826,7 @@ def executeAndroidSuspend(): def setUSBDevicesAuto(): global sysvals - rootCheck() + 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): @@ -2874,9 +3871,7 @@ def ms2nice(val): # Description: # Detect all the USB hosts and devices currently connected and add # a list of USB device names to sysvals for better timeline readability -# Arguments: -# output: True to output the info to stdout, False otherwise -def detectUSB(output): +def detectUSB(): global sysvals field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} @@ -2887,18 +3882,18 @@ def detectUSB(output): 'runtime_suspended_time':'', 'active_duration':'', 'connected_duration':''} - if(output): - 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('---------------------------------------------------------------------------------------------') + + 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('---------------------------------------------------------------------------------------------') for dirname, dirnames, filenames in os.walk('/sys/devices'): if(re.match('.*/usb[0-9]*.*', dirname) and @@ -2907,35 +3902,149 @@ def detectUSB(output): field[i] = os.popen('cat %s/%s 2>/dev/null' % \ (dirname, i)).read().replace('\n', '') name = dirname.split('/')[-1] - if(len(field['product']) > 0): - sysvals.altdevname[name] = \ - '%s [%s]' % (field['product'], name) + for i in power: + power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \ + (dirname, i)).read().replace('\n', '') + if(re.match('usb[0-9]*', name)): + first = '%-8s' % name else: - sysvals.altdevname[name] = \ - '%s:%s [%s]' % (field['idVendor'], \ - field['idProduct'], name) - if(output): - for i in power: - power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \ - (dirname, i)).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']))) + 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']))) + +# Function: devProps +# Description: +# Retrieve a list of properties for all devices in the trace log +def devProps(data=0): + global sysvals + props = dict() + + if data: + idx = data.index(': ') + 2 + if idx >= len(data): + return + devlist = data[idx:].split(';') + for dev in devlist: + f = dev.split(',') + if len(f) < 3: + continue + dev = f[0] + props[dev] = DevProps() + props[dev].altname = f[1] + if int(f[2]): + props[dev].async = True + else: + props[dev].async = False + sysvals.devprops = props + if sysvals.suspendmode == 'command' and 'testcommandstring' in props: + sysvals.testcommand = props['testcommandstring'].altname + return + + if(os.path.exists(sysvals.ftracefile) == False): + doError('%s does not exist' % sysvals.ftracefile, False) + + # first get the list of devices we need properties for + msghead = 'Additional data added by AnalyzeSuspend' + alreadystamped = False + tp = TestProps() + tf = open(sysvals.ftracefile, 'r') + for line in tf: + if msghead in line: + alreadystamped = True + continue + # determine the trace data type (required for further parsing) + m = re.match(sysvals.tracertypefmt, line) + if(m): + tp.setTracerType(m.group('t')) + continue + # parse only valid lines, if this is not one move on + m = re.match(tp.ftrace_line_fmt, line) + if(not m or 'device_pm_callback_start' not in line): + continue + m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg')); + if(not m): + continue + drv, dev, par = m.group('drv'), m.group('d'), m.group('p') + if dev not in props: + props[dev] = DevProps() + tf.close() + + 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: + fp.write(out+'\n') + sysvals.devprops = props + return + + # now get the syspath for each of our target devices + for dirname, dirnames, filenames in os.walk('/sys/devices'): + if(re.match('.*/power', dirname) and 'async' in filenames): + dev = dirname.split('/')[-2] + if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)): + props[dev].syspath = dirname[:-6] + + # now fill in the properties for our target devices + for dev in props: + dirname = props[dev].syspath + if not dirname or not os.path.exists(dirname): + continue + with open(dirname+'/power/async') as fp: + text = fp.read() + props[dev].async = False + if 'enabled' in text: + props[dev].async = True + fields = os.listdir(dirname) + if 'product' in fields: + with open(dirname+'/product') as fp: + props[dev].altname = fp.read() + elif 'name' in fields: + with open(dirname+'/name') as fp: + props[dev].altname = fp.read() + elif 'model' in fields: + with open(dirname+'/model') as fp: + props[dev].altname = fp.read() + elif 'description' in fields: + with open(dirname+'/description') as fp: + props[dev].altname = fp.read() + elif 'id' in fields: + with open(dirname+'/id') as fp: + props[dev].altname = fp.read() + elif 'idVendor' in fields and 'idProduct' in fields: + idv, idp = '', '' + with open(dirname+'/idVendor') as fp: + idv = fp.read().strip() + with open(dirname+'/idProduct') as fp: + idp = fp.read().strip() + props[dev].altname = '%s:%s' % (idv, idp) + + if props[dev].altname: + out = props[dev].altname.strip().replace('\n', ' ') + out = out.replace(',', ' ') + out = out.replace(';', ' ') + props[dev].altname = out + + # and now write the data to the ftrace file + if not alreadystamped: + out = '#\n# '+msghead+'\n# Device Properties: ' + for dev in sorted(props): + out += props[dev].out(dev) + with open(sysvals.ftracefile, 'a') as fp: + fp.write(out+'\n') + + sysvals.devprops = props # Function: getModes # Description: @@ -2945,15 +4054,10 @@ def detectUSB(output): def getModes(): global sysvals modes = '' - if(not sysvals.android): - if(os.path.exists(sysvals.powerfile)): - fp = open(sysvals.powerfile, 'r') - modes = string.split(fp.read()) - fp.close() - else: - line = os.popen(sysvals.adb+' shell cat '+\ - sysvals.powerfile).read().strip() - modes = string.split(line) + if(os.path.exists(sysvals.powerfile)): + fp = open(sysvals.powerfile, 'r') + modes = string.split(fp.read()) + fp.close() return modes # Function: getFPDT @@ -2971,22 +4075,22 @@ def getFPDT(output): prectype[0] = 'Basic S3 Resume Performance Record' prectype[1] = 'Basic S3 Suspend Performance Record' - rootCheck() + rootCheck(True) if(not os.path.exists(sysvals.fpdtpath)): if(output): - doError('file doesnt exist: %s' % sysvals.fpdtpath, False) + doError('file does not exist: %s' % sysvals.fpdtpath, False) return False if(not os.access(sysvals.fpdtpath, os.R_OK)): if(output): - doError('file isnt readable: %s' % sysvals.fpdtpath, False) + doError('file is not readable: %s' % sysvals.fpdtpath, False) return False if(not os.path.exists(sysvals.mempath)): if(output): - doError('file doesnt exist: %s' % sysvals.mempath, False) + doError('file does not exist: %s' % sysvals.mempath, False) return False if(not os.access(sysvals.mempath, os.R_OK)): if(output): - doError('file isnt readable: %s' % sysvals.mempath, False) + doError('file is not readable: %s' % sysvals.mempath, False) return False fp = open(sysvals.fpdtpath, 'rb') @@ -3027,15 +4131,19 @@ def getFPDT(output): while(i < len(records)): header = struct.unpack('HBB', records[i:i+4]) if(header[0] not in rectype): + i += header[1] continue if(header[1] != 16): + i += header[1] continue addr = struct.unpack('Q', records[i+8:i+16])[0] try: fp.seek(addr) first = fp.read(8) except: - doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False) + if(output): + print('Bad address 0x%x in %s' % (addr, sysvals.mempath)) + return [0, 0] rechead = struct.unpack('4sI', first) recdata = fp.read(rechead[1]-8) if(rechead[0] == 'FBPT'): @@ -3090,89 +4198,60 @@ def getFPDT(output): # print the results to the terminal # Output: # True if the test will work, False if not -def statusCheck(): +def statusCheck(probecheck=False): global sysvals status = True - if(sysvals.android): - print('Checking the android system ...') - else: - print('Checking this system (%s)...' % platform.node()) - - # check if adb is connected to a device - if(sysvals.android): - res = 'NO' - out = os.popen(sysvals.adb+' get-state').read().strip() - if(out == 'device'): - res = 'YES' - print(' is android device connected: %s' % res) - if(res != 'YES'): - print(' Please connect the device before using this tool') - return False + print('Checking this system (%s)...' % platform.node()) # check we have root access - res = 'NO (No features of this tool will work!)' - if(sysvals.android): - out = os.popen(sysvals.adb+' shell id').read().strip() - if('root' in out): - res = 'YES' - else: - if(os.environ['USER'] == 'root'): - res = 'YES' + res = sysvals.colorText('NO (No features of this tool will work!)') + if(rootCheck(False)): + res = 'YES' print(' have root access: %s' % res) if(res != 'YES'): - if(sysvals.android): - print(' Try running "adb root" to restart the daemon as root') - else: - print(' Try running this script with sudo') + print(' Try running this script with sudo') return False # check sysfs is mounted - res = 'NO (No features of this tool will work!)' - if(sysvals.android): - out = os.popen(sysvals.adb+' shell ls '+\ - sysvals.powerfile).read().strip() - if(out == sysvals.powerfile): - res = 'YES' - else: - if(os.path.exists(sysvals.powerfile)): - res = 'YES' + res = sysvals.colorText('NO (No features of this tool will work!)') + if(os.path.exists(sysvals.powerfile)): + res = 'YES' print(' is sysfs mounted: %s' % res) if(res != 'YES'): return False # check target mode is a valid mode - res = 'NO' - modes = getModes() - if(sysvals.suspendmode in modes): - res = 'YES' - else: - status = False - print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) - if(res == 'NO'): - print(' valid power modes are: %s' % modes) - print(' please choose one with -m') - - # check if the tool can unlock the device - if(sysvals.android): - res = 'YES' - out1 = os.popen(sysvals.adb+\ - ' shell dumpsys power | grep mScreenOn').read().strip() - out2 = os.popen(sysvals.adb+\ - ' shell input').read().strip() - if(not out1.startswith('mScreenOn') or not out2.startswith('usage')): - res = 'NO (wake the android device up before running the test)' - print(' can I unlock the screen: %s' % res) + if sysvals.suspendmode != 'command': + res = sysvals.colorText('NO') + modes = getModes() + if(sysvals.suspendmode in modes): + res = 'YES' + else: + status = False + print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) + if(res == 'NO'): + print(' valid power modes are: %s' % modes) + print(' please choose one with -m') # check if ftrace is available - res = 'NO' - ftgood = verifyFtrace() + res = sysvals.colorText('NO') + ftgood = sysvals.verifyFtrace() if(ftgood): res = 'YES' elif(sysvals.usecallgraph): status = False print(' is ftrace supported: %s' % res) + # check if kprobes are available + res = sysvals.colorText('NO') + sysvals.usekprobes = sysvals.verifyKprobes() + if(sysvals.usekprobes): + res = 'YES' + else: + sysvals.usedevsrc = False + print(' are kprobes supported: %s' % res) + # what data source are we using res = 'DMESG' if(ftgood): @@ -3180,14 +4259,8 @@ def statusCheck(): sysvals.usetraceevents = False for e in sysvals.traceevents: check = False - if(sysvals.android): - out = os.popen(sysvals.adb+' shell ls -d '+\ - sysvals.epath+e).read().strip() - if(out == sysvals.epath+e): - check = True - else: - if(os.path.exists(sysvals.epath+e)): - check = True + if(os.path.exists(sysvals.epath+e)): + check = True if(not check): sysvals.usetraceeventsonly = False if(e == 'suspend_resume' and check): @@ -3199,13 +4272,48 @@ def statusCheck(): print(' timeline data source: %s' % res) # check if rtcwake - res = 'NO' + res = sysvals.colorText('NO') if(sysvals.rtcpath != ''): res = 'YES' elif(sysvals.rtcwake): status = False print(' is rtcwake supported: %s' % res) + if not probecheck: + return status + + if (sysvals.usecallgraph and len(sysvals.debugfuncs) > 0) or len(sysvals.kprobes) > 0: + sysvals.initFtrace(True) + + # verify callgraph debugfuncs + if sysvals.usecallgraph and len(sysvals.debugfuncs) > 0: + print(' verifying these ftrace callgraph functions work:') + sysvals.setFtraceFilterFunctions(sysvals.debugfuncs) + fp = open(sysvals.tpath+'set_graph_function', 'r') + flist = fp.read().split('\n') + fp.close() + for func in sysvals.debugfuncs: + res = sysvals.colorText('NO') + if func in flist: + res = 'YES' + else: + for i in flist: + if ' [' in i and func == i.split(' ')[0]: + res = 'YES' + break + print(' %s: %s' % (func, res)) + + # verify kprobes + if len(sysvals.kprobes) > 0: + print(' verifying these kprobes work:') + for name in sorted(sysvals.kprobes): + if name in sysvals.tracefuncs: + continue + res = sysvals.colorText('NO') + if sysvals.testKprobe(sysvals.kprobes[name]): + res = 'YES' + print(' %s: %s' % (name, res)) + return status # Function: doError @@ -3226,7 +4334,7 @@ def doError(msg, help): # Arguments: # msg: the warning message to print # file: If not empty, a filename to request be sent to the owner for debug -def doWarning(msg, file): +def doWarning(msg, file=''): print('/* %s */') % msg if(file): print('/* For a fix, please send this'+\ @@ -3235,18 +4343,25 @@ def doWarning(msg, file): # Function: rootCheck # Description: # quick check to see if we have root access -def rootCheck(): - if(os.environ['USER'] != 'root'): - doError('This script must be run as root', False) +def rootCheck(fatal): + global sysvals + if(os.access(sysvals.powerfile, os.W_OK)): + return True + if fatal: + doError('This command must be run as root', False) + return False # Function: getArgInt # Description: # pull out an integer argument from the command line with checks -def getArgInt(name, args, min, max): - try: - arg = args.next() - except: - doError(name+': no argument supplied', True) +def getArgInt(name, args, min, max, main=True): + if main: + try: + arg = args.next() + except: + doError(name+': no argument supplied', True) + else: + arg = args try: val = int(arg) except: @@ -3255,6 +4370,25 @@ def getArgInt(name, args, min, max): doError(name+': value should be between %d and %d' % (min, max), True) return val +# Function: getArgFloat +# Description: +# pull out a float argument from the command line with checks +def getArgFloat(name, args, min, max, main=True): + if main: + try: + arg = args.next() + except: + doError(name+': no argument supplied', True) + else: + arg = args + try: + val = float(arg) + except: + doError(name+': non-numerical value given', True) + if(val < min or val > max): + doError(name+': value should be between %f and %f' % (min, max), True) + return val + # Function: rerunTest # Description: # generate an output from an existing set of ftrace/dmesg logs @@ -3282,15 +4416,12 @@ def rerunTest(): # Function: runTest # Description: # execute a suspend/resume, gather the logs, and generate the output -def runTest(subdir): +def runTest(subdir, testpath=''): global sysvals # prepare for the test - if(not sysvals.android): - initFtrace() - else: - initFtraceAndroid() - sysvals.initTestOutput(subdir) + sysvals.initFtrace() + sysvals.initTestOutput(subdir, testpath) vprint('Output files:\n %s' % sysvals.dmesgfile) if(sysvals.usecallgraph or @@ -3300,10 +4431,8 @@ def runTest(subdir): vprint(' %s' % sysvals.htmlfile) # execute the test - if(not sysvals.android): - executeSuspend() - else: - executeAndroidSuspend() + executeSuspend() + sysvals.cleanupFtrace() # analyze the data and create the html output print('PROCESSING DATA') @@ -3367,6 +4496,153 @@ def runSummary(subdir, output): createHTMLSummarySimple(testruns, subdir+'/summary.html') +# 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: + return True + return False + +# Function: configFromFile +# Description: +# Configure the script via the info in a config file +def configFromFile(file): + global sysvals + Config = ConfigParser.ConfigParser() + + ignorekprobes = False + Config.read(file) + sections = Config.sections() + 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.addlogs = checkArgBool(value) + elif(opt.lower() == 'dev'): + sysvals.usedevsrc = checkArgBool(value) + elif(opt.lower() == 'ignorekprobes'): + ignorekprobes = checkArgBool(value) + elif(opt.lower() == 'x2'): + if checkArgBool(value): + sysvals.execcount = 2 + elif(opt.lower() == 'callgraph'): + sysvals.usecallgraph = checkArgBool(value) + elif(opt.lower() == 'callgraphfunc'): + sysvals.debugfuncs = [] + if value: + value = value.split(',') + for i in value: + sysvals.debugfuncs.append(i.strip()) + elif(opt.lower() == 'expandcg'): + sysvals.cgexp = checkArgBool(value) + elif(opt.lower() == 'srgap'): + if checkArgBool(value): + sysvals.srgap = 5 + elif(opt.lower() == 'mode'): + sysvals.suspendmode = value + elif(opt.lower() == 'command'): + sysvals.testcommand = value + elif(opt.lower() == 'x2delay'): + sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False) + elif(opt.lower() == 'postres'): + sysvals.postresumetime = getArgInt('-postres', value, 0, 3600, False) + elif(opt.lower() == 'rtcwake'): + 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() == 'mincg'): + sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False) + elif(opt.lower() == 'kprobecolor'): + try: + val = int(value, 16) + sysvals.kprobecolor = '#'+value + except: + sysvals.kprobecolor = value + elif(opt.lower() == 'synccolor'): + try: + val = int(value, 16) + sysvals.synccolor = '#'+value + except: + sysvals.synccolor = value + elif(opt.lower() == 'output-dir'): + args = dict() + n = datetime.now() + args['date'] = n.strftime('%y%m%d') + args['time'] = n.strftime('%H%M%S') + args['hostname'] = sysvals.hostname + sysvals.outdir = value.format(**args) + + if sysvals.suspendmode == 'command' and not sysvals.testcommand: + doError('No command supplied for mode "command"', False) + if sysvals.usedevsrc and sysvals.usecallgraph: + doError('dev and callgraph cannot both be true', False) + if sysvals.usecallgraph and sysvals.execcount > 1: + doError('-x2 is not compatible with -f', False) + + if ignorekprobes: + return + + kprobes = dict() + archkprobe = 'Kprobe_'+platform.machine() + if archkprobe in sections: + for name in Config.options(archkprobe): + kprobes[name] = Config.get(archkprobe, name) + if 'Kprobe' in sections: + for name in Config.options('Kprobe'): + kprobes[name] = Config.get('Kprobe', name) + + for name in kprobes: + function = name + format = name + color = '' + args = dict() + data = kprobes[name].split() + i = 0 + for val in data: + # bracketted strings are special formatting, read them separately + if val[0] == '[' and val[-1] == ']': + for prop in val[1:-1].split(','): + p = prop.split('=') + if p[0] == 'color': + try: + color = int(p[1], 16) + color = '#'+p[1] + except: + color = p[1] + continue + # first real arg should be the format string + if i == 0: + format = val + # all other args are actual function args + else: + d = val.split('=') + args[d[0]] = d[1] + i += 1 + if not function or not format: + doError('Invalid kprobe: %s' % name, False) + for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format): + if arg not in args: + doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False) + if name in sysvals.kprobes: + doError('Duplicate kprobe found "%s"' % (name), False) + vprint('Adding KPROBE: %s %s %s %s' % (name, function, format, args)) + sysvals.kprobes[name] = { + 'name': name, + 'func': function, + 'format': format, + 'args': args, + 'mask': re.sub('{(?P<n>[a-z,A-Z,0-9]*)}', '.*', format) + } + if color: + sysvals.kprobes[name]['color'] = color + # Function: printHelp # Description: # print out the help text @@ -3375,7 +4651,7 @@ def printHelp(): modes = getModes() print('') - print('AnalyzeSuspend v%.1f' % sysvals.version) + print('AnalyzeSuspend v%s' % sysvals.version) print('Usage: sudo analyze_suspend.py <options>') print('') print('Description:') @@ -3396,27 +4672,38 @@ def printHelp(): print(' [general]') print(' -h Print this help text') print(' -v Print the current tool version') + print(' -config file Pull arguments and config options from a file') print(' -verbose Print extra information during execution and analysis') print(' -status Test to see if the system is enabled to run this tool') print(' -modes List available suspend modes') print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode) - print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)') + print(' -o subdir Override the output subdirectory') print(' [advanced]') + print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)') + print(' -addlogs Add the dmesg and ftrace logs to the html output') + print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will') + print(' be created in a new subdirectory with a summary page.') + print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)') + print(' -cmd {s} Instead of suspend/resume, run a command, e.g. "sync -d"') + print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)') + 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(' [debug]') print(' -f Use ftrace to create device callgraphs (default: disabled)') - print(' -filter "d1 d2 ..." Filter out all but this list of dev names') + print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') + print(' -flist Print the list of functions currently being captured in ftrace') + print(' -flistall Print all functions capable of being captured in ftrace') + print(' -fadd file Add functions to be graphed in the timeline from a list in a text file') + print(' -filter "d1 d2 ..." Filter out all but this list of device names') + print(' -dev Display common low level functions in the timeline') + print(' [post-resume task analysis]') print(' -x2 Run two suspend/resumes back to back (default: disabled)') print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)') print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)') - print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will') - print(' be created in a new subdirectory with a summary page.') print(' [utilities]') print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') print(' -usbtopo Print out the current USB topology with power info') print(' -usbauto Enable autosuspend for all connected USB devices') - print(' [android testing]') - print(' -adb binary Use the given adb binary to run the test on an android device.') - print(' The device should already be connected and with root access.') - print(' Commands will be executed on the device using "adb shell"') print(' [re-analyze data from previous runs]') print(' -ftrace ftracefile Create HTML output using ftrace input') print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)') @@ -3430,6 +4717,7 @@ if __name__ == '__main__': cmd = '' cmdarg = '' multitest = {'run': False, 'count': 0, 'delay': 0} + simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status'] # loop through the command line arguments args = iter(sys.argv[1:]) for arg in args: @@ -3438,58 +4726,85 @@ if __name__ == '__main__': val = args.next() except: doError('No mode supplied', True) + if val == 'command' and not sysvals.testcommand: + doError('No command supplied for mode "command"', True) sysvals.suspendmode = val - elif(arg == '-adb'): - try: - val = args.next() - except: - doError('No adb binary supplied', True) - if(not os.path.exists(val)): - doError('file doesnt exist: %s' % val, False) - if(not os.access(val, os.X_OK)): - doError('file isnt executable: %s' % val, False) - try: - check = os.popen(val+' version').read().strip() - except: - doError('adb version failed to execute', False) - if(not re.match('Android Debug Bridge .*', check)): - doError('adb version failed to execute', False) - sysvals.adb = val - sysvals.android = True + elif(arg in simplecmds): + cmd = arg[1:] + elif(arg == '-h'): + printHelp() + sys.exit() + elif(arg == '-v'): + print("Version %s" % sysvals.version) + sys.exit() elif(arg == '-x2'): - if(sysvals.postresumetime > 0): - doError('-x2 is not compatible with -postres', False) sysvals.execcount = 2 + if(sysvals.usecallgraph): + doError('-x2 is not compatible with -f', False) elif(arg == '-x2delay'): sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000) elif(arg == '-postres'): - if(sysvals.execcount != 1): - doError('-x2 is not compatible with -postres', False) sysvals.postresumetime = getArgInt('-postres', args, 0, 3600) elif(arg == '-f'): sysvals.usecallgraph = True - elif(arg == '-modes'): - cmd = 'modes' - elif(arg == '-fpdt'): - cmd = 'fpdt' - elif(arg == '-usbtopo'): - cmd = 'usbtopo' - elif(arg == '-usbauto'): - cmd = 'usbauto' - elif(arg == '-status'): - cmd = 'status' + if(sysvals.execcount > 1): + doError('-x2 is not compatible with -f', False) + if(sysvals.usedevsrc): + doError('-dev is not compatible with -f', False) + elif(arg == '-addlogs'): + sysvals.addlogs = True elif(arg == '-verbose'): sysvals.verbose = True - elif(arg == '-v'): - print("Version %.1f" % sysvals.version) - sys.exit() + elif(arg == '-dev'): + sysvals.usedevsrc = True + if(sysvals.usecallgraph): + doError('-dev is not compatible with -f', False) elif(arg == '-rtcwake'): sysvals.rtcwake = True sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600) + elif(arg == '-timeprec'): + sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6)) + elif(arg == '-mindev'): + sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0) + elif(arg == '-mincg'): + sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0) + elif(arg == '-cmd'): + try: + val = args.next() + except: + doError('No command string supplied', True) + sysvals.testcommand = val + sysvals.suspendmode = 'command' + elif(arg == '-expandcg'): + sysvals.cgexp = True + 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) + elif(arg == '-o'): + try: + val = args.next() + except: + doError('No subdirectory name supplied', True) + sysvals.outdir = val + elif(arg == '-config'): + try: + val = args.next() + except: + doError('No text file supplied', True) + if(os.path.exists(val) == False): + doError('%s does not exist' % val, False) + configFromFile(val) + elif(arg == '-fadd'): + try: + val = args.next() + except: + doError('No text file supplied', True) + if(os.path.exists(val) == False): + doError('%s does not exist' % val, False) + sysvals.addFtraceFilterFunctions(val) elif(arg == '-dmesg'): try: val = args.next() @@ -3498,17 +4813,16 @@ if __name__ == '__main__': sysvals.notestrun = True sysvals.dmesgfile = val if(os.path.exists(sysvals.dmesgfile) == False): - doError('%s doesnt exist' % sysvals.dmesgfile, False) + doError('%s does not exist' % sysvals.dmesgfile, False) elif(arg == '-ftrace'): try: val = args.next() except: doError('No ftrace file supplied', True) sysvals.notestrun = True - sysvals.usecallgraph = True sysvals.ftracefile = val if(os.path.exists(sysvals.ftracefile) == False): - doError('%s doesnt exist' % sysvals.ftracefile, False) + doError('%s does not exist' % sysvals.ftracefile, False) elif(arg == '-summary'): try: val = args.next() @@ -3518,35 +4832,35 @@ if __name__ == '__main__': cmdarg = val sysvals.notestrun = True if(os.path.isdir(val) == False): - doError('%s isnt accesible' % val, False) + doError('%s is not accesible' % val, False) elif(arg == '-filter'): try: val = args.next() except: doError('No devnames supplied', True) sysvals.setDeviceFilter(val) - elif(arg == '-h'): - printHelp() - sys.exit() else: doError('Invalid argument: '+arg, True) + # callgraph size cannot exceed device size + if sysvals.mincglen < sysvals.mindevlen: + sysvals.mincglen = sysvals.mindevlen + # just run a utility command and exit if(cmd != ''): if(cmd == 'status'): - statusCheck() + statusCheck(True) elif(cmd == 'fpdt'): - if(sysvals.android): - doError('cannot read FPDT on android device', False) getFPDT(True) elif(cmd == 'usbtopo'): - if(sysvals.android): - doError('cannot read USB topology '+\ - 'on an android device', False) - detectUSB(True) + detectUSB() elif(cmd == 'modes'): modes = getModes() print modes + elif(cmd == 'flist'): + sysvals.getFtraceFilterFunctions(True) + elif(cmd == 'flistall'): + sysvals.getFtraceFilterFunctions(False) elif(cmd == 'usbauto'): setUSBDevicesAuto() elif(cmd == 'summary'): @@ -3554,15 +4868,6 @@ if __name__ == '__main__': runSummary(cmdarg, True) sys.exit() - # run test on android device - if(sysvals.android): - if(sysvals.usecallgraph): - doError('ftrace (-f) is not yet supported '+\ - 'in the android kernel', False) - if(sysvals.notestrun): - doError('cannot analyze test files on the '+\ - 'android device', False) - # if instructed, re-analyze existing data files if(sysvals.notestrun): rerunTest() @@ -3574,18 +4879,20 @@ if __name__ == '__main__': sys.exit() if multitest['run']: - # run multiple tests in a separte subdirectory + # run multiple tests in a separate subdirectory s = 'x%d' % multitest['count'] - subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S') - os.mkdir(subdir) + if not sysvals.outdir: + sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S') + if not os.path.isdir(sysvals.outdir): + os.mkdir(sysvals.outdir) for i in range(multitest['count']): if(i != 0): print('Waiting %d seconds...' % (multitest['delay'])) time.sleep(multitest['delay']) print('TEST (%d/%d) START' % (i+1, multitest['count'])) - runTest(subdir) + runTest(sysvals.outdir) print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) - runSummary(subdir, False) + runSummary(sysvals.outdir, False) else: # run the test in the current directory - runTest(".") + runTest('.', sysvals.outdir) |