diff options
| author | Linus Torvalds <torvalds@linux-foundation.org> | 2018-04-03 20:45:39 +0300 |
|---|---|---|
| committer | Linus Torvalds <torvalds@linux-foundation.org> | 2018-04-03 20:45:39 +0300 |
| commit | f2d285669aae656dfeafa0bf25e86bbbc5d22329 (patch) | |
| tree | 4391c45051429c09199d7fd2ca6ca0dd142a5ed6 /tools/power/pm-graph | |
| parent | be5537542743f72c7cedddd145c17cf7706baa23 (diff) | |
| parent | 103cf0e5799ce024fd28dfab716d7111afe4b117 (diff) | |
| download | linux-f2d285669aae656dfeafa0bf25e86bbbc5d22329.tar.xz | |
Merge tag 'pm-4.17-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
Pull power management updates from Rafael Wysocki:
"These update the cpuidle poll state definition to reduce excessive
energy usage related to it, add new CPU ID to the RAPL power capping
driver, update the ACPI system suspend code to handle some special
cases better, extend the PM core's device links code slightly, add new
sysfs attribute for better suspend-to-idle diagnostics and easier
hibernation handling, update power management tools and clean up
cpufreq quite a bit.
Specifics:
- Modify the cpuidle poll state implementation to prevent CPUs from
staying in the loop in there for excessive times (Rafael Wysocki).
- Add Intel Cannon Lake chips support to the RAPL power capping
driver (Joe Konno).
- Add reference counting to the device links handling code in the PM
core (Lukas Wunner).
- Avoid reconfiguring GPEs on suspend-to-idle in the ACPI system
suspend code (Rafael Wysocki).
- Allow devices to be put into deeper low-power states via ACPI if
both _SxD and _SxW are missing (Daniel Drake).
- Reorganize the core ACPI suspend-to-idle wakeup code to avoid a
keyboard wakeup issue on Asus UX331UA (Chris Chiu).
- Prevent the PCMCIA library code from aborting suspend-to-idle due
to noirq suspend failures resulting from incorrect assumptions
(Rafael Wysocki).
- Add coupled cpuidle supprt to the Exynos3250 platform (Marek
Szyprowski).
- Add new sysfs file to make it easier to specify the image storage
location during hibernation (Mario Limonciello).
- Add sysfs files for collecting suspend-to-idle usage and time
statistics for CPU idle states (Rafael Wysocki).
- Update the pm-graph utilities (Todd Brandt).
- Reduce the kernel log noise related to reporting Low-power Idle
constraings by the ACPI system suspend code (Rafael Wysocki).
- Make it easier to distinguish dedicated wakeup IRQs in the
/proc/interrupts output (Tony Lindgren).
- Add the frequency table validation in cpufreq to the core and drop
it from a number of cpufreq drivers (Viresh Kumar).
- Drop "cooling-{min|max}-level" for CPU nodes from a couple of DT
bindings (Viresh Kumar).
- Clean up the CPU online error code path in the cpufreq core (Viresh
Kumar).
- Fix assorted issues in the SCPI, CPPC, mediatek and tegra186
cpufreq drivers (Arnd Bergmann, Chunyu Hu, George Cherian, Viresh
Kumar).
- Drop memory allocation error messages from a few places in cpufreq
and cpuildle drivers (Markus Elfring)"
* tag 'pm-4.17-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm: (56 commits)
ACPI / PM: Fix keyboard wakeup from suspend-to-idle on ASUS UX331UA
cpufreq: CPPC: Use transition_delay_us depending transition_latency
PM / hibernate: Change message when writing to /sys/power/resume
PM / hibernate: Make passing hibernate offsets more friendly
cpuidle: poll_state: Avoid invoking local_clock() too often
PM: cpuidle/suspend: Add s2idle usage and time state attributes
cpuidle: Enable coupled cpuidle support on Exynos3250 platform
cpuidle: poll_state: Add time limit to poll_idle()
cpufreq: tegra186: Don't validate the frequency table twice
cpufreq: speedstep: Don't validate the frequency table twice
cpufreq: sparc: Don't validate the frequency table twice
cpufreq: sh: Don't validate the frequency table twice
cpufreq: sfi: Don't validate the frequency table twice
cpufreq: scpi: Don't validate the frequency table twice
cpufreq: sc520: Don't validate the frequency table twice
cpufreq: s3c24xx: Don't validate the frequency table twice
cpufreq: qoirq: Don't validate the frequency table twice
cpufreq: pxa: Don't validate the frequency table twice
cpufreq: ppc_cbe: Don't validate the frequency table twice
cpufreq: powernow: Don't validate the frequency table twice
...
Diffstat (limited to 'tools/power/pm-graph')
18 files changed, 2575 insertions, 703 deletions
diff --git a/tools/power/pm-graph/Makefile b/tools/power/pm-graph/Makefile index 4e1e999e7b05..c1899cd72c80 100644 --- a/tools/power/pm-graph/Makefile +++ b/tools/power/pm-graph/Makefile @@ -7,11 +7,24 @@ all: install : uninstall install -d $(DESTDIR)$(PREFIX)/lib/pm-graph - install analyze_suspend.py $(DESTDIR)$(PREFIX)/lib/pm-graph - install analyze_boot.py $(DESTDIR)$(PREFIX)/lib/pm-graph + install sleepgraph.py $(DESTDIR)$(PREFIX)/lib/pm-graph + install bootgraph.py $(DESTDIR)$(PREFIX)/lib/pm-graph + install -d $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/cgskip.txt $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/freeze-callgraph.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/freeze.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/freeze-dev.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/standby-callgraph.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/standby.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/standby-dev.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/suspend-callgraph.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/suspend.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/suspend-dev.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config + install -m 644 config/suspend-x2-proc.cfg $(DESTDIR)$(PREFIX)/lib/pm-graph/config - ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_boot.py $(DESTDIR)$(PREFIX)/bin/bootgraph - ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_suspend.py $(DESTDIR)$(PREFIX)/bin/sleepgraph + install -d $(DESTDIR)$(PREFIX)/bin + ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/bootgraph.py $(DESTDIR)$(PREFIX)/bin/bootgraph + ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/sleepgraph.py $(DESTDIR)$(PREFIX)/bin/sleepgraph install -d $(DESTDIR)$(PREFIX)/share/man/man8 install bootgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8 @@ -24,9 +37,11 @@ uninstall : rm -f $(DESTDIR)$(PREFIX)/bin/bootgraph rm -f $(DESTDIR)$(PREFIX)/bin/sleepgraph - rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_boot.py - rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_suspend.py - rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/*.pyc + rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/config/* + if [ -d $(DESTDIR)$(PREFIX)/lib/pm-graph/config ] ; then \ + rmdir $(DESTDIR)$(PREFIX)/lib/pm-graph/config; \ + fi; + rm -f $(DESTDIR)$(PREFIX)/lib/pm-graph/* if [ -d $(DESTDIR)$(PREFIX)/lib/pm-graph ] ; then \ rmdir $(DESTDIR)$(PREFIX)/lib/pm-graph; \ fi; diff --git a/tools/power/pm-graph/bootgraph.8 b/tools/power/pm-graph/bootgraph.8 index dbdafcf546df..64d513f80a2a 100644 --- a/tools/power/pm-graph/bootgraph.8 +++ b/tools/power/pm-graph/bootgraph.8 @@ -37,6 +37,9 @@ Print the current tool version Add the dmesg log to the html output. It will be viewable by clicking a button in the timeline. .TP +\fB-result \fIfile\fR +Export a results table to a text file for parsing. +.TP \fB-o \fIname\fR Overrides the output subdirectory name when running a new test. Use {date}, {time}, {hostname} for current values. @@ -44,14 +47,14 @@ Use {date}, {time}, {hostname} for current values. e.g. boot-{hostname}-{date}-{time} .SS "advanced" .TP -\fB-f\fR -Use ftrace to add function detail (default: disabled) -.TP -\fB-callgraph\fR +\fB-f or -callgraph\fR Use ftrace to create initcall callgraphs (default: disabled). If -func is not used there will be one callgraph per initcall. This can produce very large outputs, i.e. 10MB - 100MB. .TP +\fB-fstat\fR +Use ftrace to add function detail (default: disabled) +.TP \fB-maxdepth \fIlevel\fR limit the callgraph trace depth to \fIlevel\fR (default: 2). This is the best way to limit the output size when using -callgraph. @@ -67,6 +70,13 @@ Reduce callgraph output in the timeline by limiting it to a list of calls. The argument can be a single function name or a comma delimited list. (default: none) .TP +\fB-cgskip \fIfile\fR +Reduce callgraph output in the timeline by skipping over uninteresting +functions in the trace, e.g. printk or console_unlock. The functions listed +in this file will show up as empty leaves in the callgraph with only the start/end +times displayed. +(default: none) +.TP \fB-timeprec \fIn\fR Number of significant digits in timestamps (0:S, 3:ms, [6:us]) .TP diff --git a/tools/power/pm-graph/analyze_boot.py b/tools/power/pm-graph/bootgraph.py index e83df141a597..abb4c38f029b 100755 --- a/tools/power/pm-graph/analyze_boot.py +++ b/tools/power/pm-graph/bootgraph.py @@ -32,7 +32,7 @@ import platform import shutil from datetime import datetime, timedelta from subprocess import call, Popen, PIPE -import analyze_suspend as aslib +import sleepgraph as aslib # ----------------- CLASSES -------------------- @@ -42,23 +42,18 @@ import analyze_suspend as aslib # store system values and test parameters class SystemValues(aslib.SystemValues): title = 'BootGraph' - version = '2.1' + version = '2.2' hostname = 'localhost' testtime = '' kernel = '' dmesgfile = '' ftracefile = '' htmlfile = 'bootgraph.html' - outfile = '' testdir = '' - testdirprefix = 'boot' - embedded = False - testlog = False - dmesglog = False - ftracelog = False + kparams = '' + result = '' useftrace = False usecallgraph = False - usedevsrc = True suspendmode = 'boot' max_graph_depth = 2 graph_filter = 'do_one_initcall' @@ -69,11 +64,6 @@ class SystemValues(aslib.SystemValues): bootloader = 'grub' blexec = [] def __init__(self): - if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): - self.embedded = True - self.dmesglog = True - self.outfile = os.environ['LOG_FILE'] - self.htmlfile = os.environ['LOG_FILE'] self.hostname = platform.node() self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S') if os.path.exists('/proc/version'): @@ -148,11 +138,18 @@ class SystemValues(aslib.SystemValues): cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0]) args = iter(sys.argv[1:]) for arg in args: - if arg in ['-h', '-v', '-cronjob', '-reboot']: + if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']: continue elif arg in ['-o', '-dmesg', '-ftrace', '-func']: args.next() continue + elif arg == '-result': + cmdline += ' %s "%s"' % (arg, os.path.abspath(args.next())) + continue + elif arg == '-cgskip': + file = self.configFile(args.next()) + cmdline += ' %s "%s"' % (arg, os.path.abspath(file)) + continue cmdline += ' '+arg if self.graph_filter != 'do_one_initcall': cmdline += ' -func "%s"' % self.graph_filter @@ -166,14 +163,6 @@ class SystemValues(aslib.SystemValues): print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n' print 'CMDLINE="%s"' % cmdline sys.exit() - def getExec(self, cmd): - dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin', - '/usr/local/sbin', '/usr/local/bin'] - for path in dirlist: - cmdfull = os.path.join(path, cmd) - if os.path.exists(cmdfull): - return cmdfull - return '' def blGrub(self): blcmd = '' for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']: @@ -199,6 +188,14 @@ class SystemValues(aslib.SystemValues): self.blGrub() else: doError('unknown boot loader: %s' % self.bootloader) + def writeDatafileHeader(self, filename): + self.kparams = open('/proc/cmdline', 'r').read().strip() + fp = open(filename, 'w') + fp.write(self.teststamp+'\n') + fp.write(self.sysstamp+'\n') + fp.write('# command | %s\n' % self.cmdline) + fp.write('# kparams | %s\n' % self.kparams) + fp.close() sysvals = SystemValues() @@ -249,7 +246,7 @@ class Data(aslib.Data): return name def deviceMatch(self, pid, cg): if cg.end - cg.start == 0: - return True + return '' for p in data.phases: list = self.dmesg[p]['list'] for devname in list: @@ -260,14 +257,25 @@ class Data(aslib.Data): if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0): dev['ftrace'] = cg self.do_one_initcall = True - return True + return devname else: if(cg.start > dev['start'] and cg.end < dev['end']): if 'ftraces' not in dev: dev['ftraces'] = [] dev['ftraces'].append(cg) - return True - return False + return devname + return '' + def printDetails(self): + sysvals.vprint('Timeline Details:') + sysvals.vprint(' Host: %s' % sysvals.hostname) + sysvals.vprint(' Kernel: %s' % sysvals.kernel) + sysvals.vprint(' Test time: %s' % sysvals.testtime) + sysvals.vprint(' Boot time: %s' % self.boottime) + for phase in self.phases: + dc = len(self.dmesg[phase]['list']) + sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase, + self.dmesg[phase]['start']*1000, + self.dmesg[phase]['end']*1000, dc)) # ----------------- FUNCTIONS -------------------- @@ -275,6 +283,8 @@ class Data(aslib.Data): # Description: # parse a kernel log for boot data def parseKernelLog(): + sysvals.vprint('Analyzing the dmesg data (%s)...' % \ + os.path.basename(sysvals.dmesgfile)) phase = 'kernel' data = Data(0) data.dmesg['kernel']['start'] = data.start = ktime = 0.0 @@ -298,6 +308,12 @@ def parseKernelLog(): elif re.match(tp.sysinfofmt, line): tp.sysinfo = line continue + elif re.match(tp.cmdlinefmt, line): + tp.cmdline = line + continue + elif re.match(tp.kparamsfmt, line): + tp.kparams = line + continue idx = line.find('[') if idx > 1: line = line[idx:] @@ -353,6 +369,17 @@ def parseKernelLog(): # Description: # Check if trace is available and copy to a temp file def parseTraceLog(data): + sysvals.vprint('Analyzing the ftrace data (%s)...' % \ + os.path.basename(sysvals.ftracefile)) + # if available, calculate cgfilter allowable ranges + cgfilter = [] + if len(sysvals.cgfilter) > 0: + for p in data.phases: + list = data.dmesg[p]['list'] + for i in sysvals.cgfilter: + if i in list: + cgfilter.append([list[i]['start']-0.0001, + list[i]['end']+0.0001]) # parse the trace log ftemp = dict() tp = aslib.TestProps() @@ -366,7 +393,16 @@ def parseTraceLog(data): continue m_time, m_proc, m_pid, m_msg, m_dur = \ m.group('time', 'proc', 'pid', 'msg', 'dur') - if float(m_time) > data.end: + t = float(m_time) + if len(cgfilter) > 0: + allow = False + for r in cgfilter: + if t >= r[0] and t < r[1]: + allow = True + break + if not allow: + continue + if t > data.end: break if(m_time and m_pid and m_msg): t = aslib.FTraceLine(m_time, m_msg, m_dur) @@ -378,24 +414,36 @@ def parseTraceLog(data): key = (m_proc, pid) if(key not in ftemp): ftemp[key] = [] - ftemp[key].append(aslib.FTraceCallGraph(pid)) + ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals)) cg = ftemp[key][-1] - if(cg.addLine(t)): - ftemp[key].append(aslib.FTraceCallGraph(pid)) + res = cg.addLine(t) + if(res != 0): + ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals)) + if(res == -1): + ftemp[key][-1].addLine(t) + tf.close() # add the callgraph data to the device hierarchy for key in ftemp: proc, pid = key for cg in ftemp[key]: - if len(cg.list) < 1 or cg.invalid: + if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0): continue if(not cg.postProcess()): print('Sanity check failed for %s-%d' % (proc, pid)) continue # match cg data to devices - if not data.deviceMatch(pid, cg): - print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid, cg.start, cg.end) + devname = data.deviceMatch(pid, cg) + if not devname: + kind = 'Orphan' + if cg.partial: + kind = 'Partial' + sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\ + (kind, cg.name, proc, pid, cg.start, cg.end)) + elif len(cg.list) > 1000000: + print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\ + (devname, len(cg.list)) # Function: retrieveLogs # Description: @@ -473,7 +521,7 @@ def createBootGraph(data): devtl = aslib.Timeline(100, 20) # write the test title and general info header - devtl.createHeader(sysvals) + devtl.createHeader(sysvals, sysvals.stamp) # Generate the header for this timeline t0 = data.start @@ -574,12 +622,9 @@ def createBootGraph(data): data.dmesg[phase]['color'], phase+'_mode', phase[0]) devtl.html += '</div>\n' - if(sysvals.outfile == sysvals.htmlfile): - hf = open(sysvals.htmlfile, 'a') - else: - hf = open(sysvals.htmlfile, 'w') + hf = open(sysvals.htmlfile, 'w') - # add the css if this is not an embedded run + # add the css extra = '\ .c1 {background:rgba(209,0,0,0.4);}\n\ .c2 {background:rgba(255,102,34,0.4);}\n\ @@ -597,8 +642,7 @@ def createBootGraph(data): .fstat td {text-align:left;width:35px;}\n\ .srccall {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\ .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n' - if(not sysvals.embedded): - aslib.addCSS(hf, sysvals, 1, False, extra) + aslib.addCSS(hf, sysvals, 1, False, extra) # write the device timeline hf.write(devtl.html) @@ -631,6 +675,9 @@ def createBootGraph(data): if(sysvals.usecallgraph): aslib.addCallgraphs(sysvals, hf, data) + # add the test log as a hidden div + if sysvals.testlog and sysvals.logmsg: + hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n') # add the dmesg log as a hidden div if sysvals.dmesglog: hf.write('<div id="dmesglog" style="display:none;">\n') @@ -639,14 +686,9 @@ def createBootGraph(data): hf.write(line) hf.write('</div>\n') - if(not sysvals.embedded): - # write the footer and close - aslib.addScriptCode(hf, [data]) - hf.write('</body>\n</html>\n') - else: - # embedded out will be loaded in a page, skip the js - hf.write('<div id=bounds style=display:none>%f,%f</div>' % \ - (data.start*1000, data.end*1000)) + # write the footer and close + aslib.addScriptCode(hf, [data]) + hf.write('</body>\n</html>\n') hf.close() return True @@ -780,6 +822,7 @@ def doError(msg, help=False): if help == True: printHelp() print 'ERROR: %s\n' % msg + sysvals.outputResult({'error':msg}) sys.exit() # Function: printHelp @@ -806,18 +849,21 @@ def printHelp(): print('Options:') print(' -h Print this help text') print(' -v Print the current tool version') + print(' -verbose Print extra information during execution and analysis') print(' -addlogs Add the dmesg log to the html output') + print(' -result fn Export a results table to a text file for parsing.') print(' -o name Overrides the output subdirectory name when running a new test') print(' default: boot-{date}-{time}') print(' [advanced]') - print(' -f Use ftrace to add function detail (default: disabled)') - print(' -callgraph Add callgraph detail, can be very large (default: disabled)') + print(' -fstat Use ftrace to add function detail and statistics (default: disabled)') + print(' -f/-callgraph Add callgraph detail, can be very large (default: disabled)') print(' -maxdepth N limit the callgraph data to N call levels (default: 2)') print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])') print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') print(' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)') print(' -cgfilter S Filter the callgraph output in the timeline') + print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)') print(' -bl name Use the following boot loader for kernel params (default: grub)') print(' -reboot Reboot the machine automatically and generate a new timeline') print(' -manual Show the steps to generate a new timeline manually (used with -reboot)') @@ -837,8 +883,13 @@ if __name__ == '__main__': # loop through the command line arguments cmd = '' testrun = True + switchoff = ['disable', 'off', 'false', '0'] simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl'] + cgskip = '' + if '-f' in sys.argv: + cgskip = sysvals.configFile('cgskip.txt') args = iter(sys.argv[1:]) + mdset = False for arg in args: if(arg == '-h'): printHelp() @@ -846,13 +897,17 @@ if __name__ == '__main__': elif(arg == '-v'): print("Version %s" % sysvals.version) sys.exit() + elif(arg == '-verbose'): + sysvals.verbose = True elif(arg in simplecmds): cmd = arg[1:] - elif(arg == '-f'): + elif(arg == '-fstat'): sysvals.useftrace = True - elif(arg == '-callgraph'): + elif(arg == '-callgraph' or arg == '-f'): sysvals.useftrace = True sysvals.usecallgraph = True + elif(arg == '-cgdump'): + sysvals.cgdump = True elif(arg == '-mincg'): sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0) elif(arg == '-cgfilter'): @@ -860,7 +915,18 @@ if __name__ == '__main__': val = args.next() except: doError('No callgraph functions supplied', True) - sysvals.setDeviceFilter(val) + sysvals.setCallgraphFilter(val) + elif(arg == '-cgskip'): + try: + val = args.next() + except: + doError('No file supplied', True) + if val.lower() in switchoff: + cgskip = '' + else: + cgskip = sysvals.configFile(val) + if(not cgskip): + doError('%s does not exist' % cgskip) elif(arg == '-bl'): try: val = args.next() @@ -872,6 +938,7 @@ if __name__ == '__main__': elif(arg == '-timeprec'): sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6)) elif(arg == '-maxdepth'): + mdset = True sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000) elif(arg == '-func'): try: @@ -902,8 +969,6 @@ if __name__ == '__main__': doError('No dmesg file supplied', True) if(os.path.exists(val) == False): doError('%s does not exist' % val) - if(sysvals.htmlfile == val or sysvals.outfile == val): - doError('Output filename collision') testrun = False sysvals.dmesgfile = val elif(arg == '-o'): @@ -912,6 +977,12 @@ if __name__ == '__main__': except: doError('No subdirectory name supplied', True) sysvals.testdir = sysvals.setOutputFolder(val) + elif(arg == '-result'): + try: + val = args.next() + except: + doError('No result file supplied', True) + sysvals.result = val elif(arg == '-reboot'): sysvals.reboot = True elif(arg == '-manual'): @@ -947,7 +1018,7 @@ if __name__ == '__main__': sysvals.getBootLoader() print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec) elif(cmd == 'sysinfo'): - sysvals.printSystemInfo() + sysvals.printSystemInfo(True) sys.exit() # reboot: update grub, setup a cronjob, and reboot @@ -963,6 +1034,10 @@ if __name__ == '__main__': sysvals.manualRebootRequired() sys.exit() + if sysvals.usecallgraph and cgskip: + sysvals.vprint('Using cgskip file: %s' % cgskip) + sysvals.setCallgraphBlacklist(cgskip) + # cronjob: remove the cronjob, grub changes, and disable ftrace if sysvals.iscronjob: updateCron(True) @@ -980,29 +1055,23 @@ if __name__ == '__main__': # process the log data if sysvals.dmesgfile: + if not mdset: + sysvals.max_graph_depth = 0 data = parseKernelLog() if(not data.valid): doError('No initcall data found in %s' % sysvals.dmesgfile) if sysvals.useftrace and sysvals.ftracefile: parseTraceLog(data) + if sysvals.cgdump: + data.debugPrint() + sys.exit() else: doError('dmesg file required') - print(' Host: %s' % sysvals.hostname) - print(' Test time: %s' % sysvals.testtime) - print(' Boot time: %s' % data.boottime) - print('Kernel Version: %s' % sysvals.kernel) - print(' Kernel start: %.3f' % (data.start * 1000)) - print('Usermode start: %.3f' % (data.tUserMode * 1000)) - print('Last Init Call: %.3f' % (data.end * 1000)) - - # handle embedded output logs - if(sysvals.outfile and sysvals.embedded): - fp = open(sysvals.outfile, 'w') - fp.write('pass %s initstart %.3f end %.3f boot %s\n' % - (data.valid, data.tUserMode*1000, data.end*1000, data.boottime)) - fp.close() - + sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) + sysvals.vprint('Command:\n %s' % sysvals.cmdline) + sysvals.vprint('Kernel parameters:\n %s' % sysvals.kparams) + data.printDetails() createBootGraph(data) # if running as root, change output dir owner to sudo_user @@ -1010,3 +1079,7 @@ if __name__ == '__main__': os.getuid() == 0 and 'SUDO_USER' in os.environ: cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True) + + sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000 + sysvals.stamp['lastinit'] = data.end * 1000 + sysvals.outputResult(sysvals.stamp) diff --git a/tools/power/pm-graph/config/cgskip.txt b/tools/power/pm-graph/config/cgskip.txt new file mode 100644 index 000000000000..e48d588fbfb4 --- /dev/null +++ b/tools/power/pm-graph/config/cgskip.txt @@ -0,0 +1,65 @@ +# ----------------------------------------------- +# CallGraph function skip list +# +# This file contains a list of functions which are +# meant to be skipped in the callgraph trace. It reduces +# the callgraph html file size by treating these functions +# as leaves with no child calls. It can be editted by +# adding or removing function symbol names. +# +# The sleepgraph tool automatically pulls this file in when +# it is found in the config folder. It can be ignored if +# the tool is called with "-cgskip off". +# ----------------------------------------------- + +# low level scheduling and timing +up +down_timeout +mutex_lock +down_read +complete_all +schedule_timeout +wake_up_process +msleep +__udelay +ktime_get + +# console calls +printk +dev_printk +console_unlock + +# memory handling +__kmalloc +__kmalloc_track_caller +kmem_cache_alloc +kmem_cache_alloc_trace +kmem_cache_free +kstrdup +kstrdup_const +kmalloc_slab +new_slab +__slab_alloc +__slab_free +raw_pci_read +pci_read +alloc_pages_current + +# debugfs and sysfs setup +debugfs_remove_recursive +debugfs_create_dir +debugfs_create_files +debugfs_create_dir +debugfs_get_inode +sysfs_add_file_mode_ns +sysfs_add_file +sysfs_create_dir_ns +sysfs_create_link +sysfs_create_group +sysfs_create_groups +sysfs_create_bin_file +dpm_sysfs_add +sysfs_create_file_ns +sysfs_merge_group +sysfs_add_link_to_group +sysfs_create_link_sd diff --git a/tools/power/pm-graph/config/custom-timeline-functions.cfg b/tools/power/pm-graph/config/custom-timeline-functions.cfg new file mode 100644 index 000000000000..4f80ad7d7275 --- /dev/null +++ b/tools/power/pm-graph/config/custom-timeline-functions.cfg @@ -0,0 +1,205 @@ +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config thisfile.txt +# + +[Settings] + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: mem + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: true + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: suspend-{hostname}-{date}-{time}-custom + +# Override default timeline entries +# Do not use the internal default functions for timeline entries (default: false) +# Set this to true if you intend to only use the ones defined in this config +override-timeline-functions: true + +# Override default dev timeline entries +# Do not use the internal default functions for dev timeline entries (default: false) +# Set this to true if you intend to only use the ones defined in this config +override-dev-timeline-functions: true + +[timeline_functions_x86_64] +# +# Function calls to display in the timeline alongside device callbacks. +# The tool has an internal set of these functions which should cover the +# whole of kernel execution, but you can append or override here. +# +# This is a list of kprobes which use both symbol data and function arg data. +# The function calls are displayed on the timeline alongside the device blocks. +# The args are pulled directly from the stack using this architecture's registers +# and stack formatting. Three pieces of info are required. The function name, +# a format string, and an argument list +# +# Entry format: +# +# function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple] +# +# Required Arguments: +# +# function: The symbol name for the function you want probed, this is the +# minimum required for an entry, it will show up as the function +# name with no arguments. +# +# example: _cpu_up: +# +# Optional Arguments: +# +# format: The format to display the data on the timeline in. Use braces to +# enclose the arg names. +# +# example: CPU_ON[{cpu}] +# +# color: The color of the entry block in the timeline. The default color is +# transparent, so the entry shares the phase color. The color is an +# html color string, either a word, or an RGB. +# +# example: [color=#CC00CC] +# +# arglist: A list of arguments from registers/stack addresses. See URL: +# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt +# +# example: cpu=%di:s32 +# +# Example: Display cpu resume in the timeline +# +# _cpu_up: CPU_ON[{cpu}] cpu=%di:s32 [color=orange] +# +_cpu_down: CPU_OFF[{cpu}] cpu=%di:s32 +_cpu_up: CPU_ON[{cpu}] cpu=%di:s32 +sys_sync: +pm_prepare_console: +pm_notifier_call_chain: +freeze_processes: +freeze_kernel_threads: +pm_restrict_gfp_mask: +acpi_suspend_begin: +suspend_console: +acpi_pm_prepare: +syscore_suspend: +arch_enable_nonboot_cpus_end: +syscore_resume: +acpi_pm_finish: +resume_console: +acpi_pm_end: +pm_restore_gfp_mask: +thaw_processes: +pm_restore_console: + +[dev_timeline_functions_x86_64] +# +# Dev mode function calls to display inside timeline entries +# +# This is a list of kprobes which use both symbol data and function arg data. +# The function calls are displayed on the timeline alongside the device blocks. +# The args are pulled directly from the stack using this architecture's registers +# and stack formatting. Three pieces of info are required. The function name, +# a format string, and an argument list +# +# Entry format: +# +# function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple] +# +# Required Arguments: +# +# function: The symbol name for the function you want probed, this is the +# minimum required for an entry, it will show up as the function +# name with no arguments. +# +# example: ata_eh_recover: +# +# Optional Arguments: +# +# format: The format to display the data on the timeline in. Use braces to +# enclose the arg names. +# +# example: ata{port}_port_reset +# +# color: The color of the entry block in the timeline. The default color is +# transparent, so the entry shares the phase color. The color is an +# html color string, either a word, or an RGB. +# +# example: [color=#CC00CC] +# +# arglist: A list of arguments from registers/stack addresses. See URL: +# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt +# +# example: port=+36(%di):s32 +# +# Example: Display ATA port reset as ataN_port_reset in the timeline +# +# ata_eh_recover: ata{port}_port_reset port=+36(%di):s32 +# +msleep: msleep time=%di:s32 +schedule_timeout_uninterruptible: schedule_timeout_uninterruptible timeout=%di:s32 +schedule_timeout: schedule_timeout timeout=%di:s32 +usleep_range: usleep_range min=%di:s32 max=%si:s32 +__const_udelay: udelay loops=%di:s32 +__mutex_lock_slowpath: mutex_lock_slowpath +ata_eh_recover: ata_eh_recover port=+36(%di):s32 +acpi_os_stall: +acpi_resume_power_resources: +acpi_ps_parse_aml: +ext4_sync_fs: +i915_gem_resume: +i915_restore_state: +intel_opregion_setup: +g4x_pre_enable_dp: +vlv_pre_enable_dp: +chv_pre_enable_dp: +g4x_enable_dp: +vlv_enable_dp: +intel_hpd_init: +intel_opregion_register: +intel_dp_detect: +intel_hdmi_detect: +intel_opregion_init: +intel_fbdev_set_suspend: diff --git a/tools/power/pm-graph/config/example.cfg b/tools/power/pm-graph/config/example.cfg new file mode 100644 index 000000000000..05b2efb9bb54 --- /dev/null +++ b/tools/power/pm-graph/config/example.cfg @@ -0,0 +1,133 @@ +# +# Generic S3 (Suspend to Mem) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/example.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: mem + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: suspend-{hostname}-{date}-{time} + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: true + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# Skip HTML generation +# Only capture the logs, don't generate the html timeline (default: false) +skiphtml: false + +# Sync filesystem before suspend +# run sync before the test, minimizes sys_sync call time (default: false) +sync: true + +# Runtime suspend enable/disable +# Enable/disable runtime suspend for all devices, restore all after test (default: no-action) +# rs: disable + +# Turn display on/off for test +# Switch the display on/off for the test using xset (default: no-action) +# display: on + +# Print results to text file +# Print the status of the test run in the given file (default: no-action) +result: result.txt + +# Gzip the log files to save space +# Gzip the generated log files, and read gzipped log files (default: false) +gzip: true + +# ---- Advanced Options ---- + +# Command to execute in lieu of suspend (default: "") +# command: echo mem > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Multiple test runs +# Run N tests D seconds apart, generates separate outputs with a summary (default: false) +# multi: 3 5 + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back and display in the same timeline (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 0.001 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Callgraph phase filter +# Only enable callgraphs for one phase, i.e. resume_noirq (default: all) +cgphase: suspend + +# Callgraph x2 test filter +# Only enable callgraphs test 0 or 1 when using -x2 (default: 1) +cgtest: 0 + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 6 + +# Device Filter +# show only devices whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb + +# Add kprobe functions to the timeline +# Add functions to the timeline from a text file (default: no-action) +# fadd: file.txt diff --git a/tools/power/pm-graph/config/freeze-callgraph.cfg b/tools/power/pm-graph/config/freeze-callgraph.cfg new file mode 100644 index 000000000000..f692821c4828 --- /dev/null +++ b/tools/power/pm-graph/config/freeze-callgraph.cfg @@ -0,0 +1,94 @@ +# +# Full Callgraph for S2 (Freeze) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/freeze-callgraph.cfg +# +# NOTE: the output of this test is very large (> 30MB) + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: freeze + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: freeze-{hostname}-{date}-{time}-cg + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of freeze (default: "") +# command: echo freeze > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: true + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 6 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/freeze-dev.cfg b/tools/power/pm-graph/config/freeze-dev.cfg new file mode 100644 index 000000000000..c4ad5cea3cbf --- /dev/null +++ b/tools/power/pm-graph/config/freeze-dev.cfg @@ -0,0 +1,93 @@ +# +# Dev S2 (Freeze) test - includes src calls / kernel threads +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/freeze-dev.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: freeze + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: freeze-{hostname}-{date}-{time}-dev + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of freeze (default: "") +# command: echo freeze > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: true + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/freeze.cfg b/tools/power/pm-graph/config/freeze.cfg new file mode 100644 index 000000000000..0b70e0b74527 --- /dev/null +++ b/tools/power/pm-graph/config/freeze.cfg @@ -0,0 +1,93 @@ +# +# Generic S2 (Freeze) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/freeze.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: freeze + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: freeze-{hostname}-{date}-{time} + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of freeze (default: "") +# command: echo freeze > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 0.001 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/standby-callgraph.cfg b/tools/power/pm-graph/config/standby-callgraph.cfg new file mode 100644 index 000000000000..f52a6b9d5c32 --- /dev/null +++ b/tools/power/pm-graph/config/standby-callgraph.cfg @@ -0,0 +1,94 @@ +# +# Full Callgraph for S1 (Standby) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/standby-callgraph.cfg +# +# NOTE: the output of this test is very large (> 30MB) + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: standby + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: standby-{hostname}-{date}-{time}-cg + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of standby (default: "") +# command: echo standby > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: true + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 6 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/standby-dev.cfg b/tools/power/pm-graph/config/standby-dev.cfg new file mode 100644 index 000000000000..a5498ece3def --- /dev/null +++ b/tools/power/pm-graph/config/standby-dev.cfg @@ -0,0 +1,93 @@ +# +# Dev S1 (Standby) test - includes src calls / kernel threads +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/standby-dev.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: standby + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: standby-{hostname}-{date}-{time}-dev + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of standby (default: "") +# command: echo standby > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: true + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/standby.cfg b/tools/power/pm-graph/config/standby.cfg new file mode 100644 index 000000000000..f0dd264dfeff --- /dev/null +++ b/tools/power/pm-graph/config/standby.cfg @@ -0,0 +1,93 @@ +# +# Generic S1 (Standby) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/standby.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: standby + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: standby-{hostname}-{date}-{time} + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of standby (default: "") +# command: echo standby > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 0.001 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/suspend-callgraph.cfg b/tools/power/pm-graph/config/suspend-callgraph.cfg new file mode 100644 index 000000000000..11b8cbc12d34 --- /dev/null +++ b/tools/power/pm-graph/config/suspend-callgraph.cfg @@ -0,0 +1,98 @@ +# +# Full Callgraph for S3 (Suspend to Mem) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/suspend.cfg +# +# NOTE: the output of this test is very large (> 30MB) + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: mem + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: suspend-{hostname}-{date}-{time}-cg + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of suspend (default: "") +# command: echo mem > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 0.001 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: true + +# Max graph depth +# limit the callgraph trace to this depth (default: 0 = all) +maxdepth: 5 + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 6 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/suspend-dev.cfg b/tools/power/pm-graph/config/suspend-dev.cfg new file mode 100644 index 000000000000..56f1d21cc79b --- /dev/null +++ b/tools/power/pm-graph/config/suspend-dev.cfg @@ -0,0 +1,93 @@ +# +# Dev S3 (Suspend to Mem) test - includes src calls / kernel threads +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/suspend-dev.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: mem + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: suspend-{hostname}-{date}-{time}-dev + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of suspend (default: "") +# command: echo mem > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: true + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/suspend-x2-proc.cfg b/tools/power/pm-graph/config/suspend-x2-proc.cfg new file mode 100644 index 000000000000..0ecca0ede138 --- /dev/null +++ b/tools/power/pm-graph/config/suspend-x2-proc.cfg @@ -0,0 +1,93 @@ +# +# Proc S3 (Suspend to Mem) x2 test - includes user processes +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/suspend-proc.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: mem + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: suspend-{hostname}-{date}-{time}-x2-proc + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of suspend (default: "") +# command: echo mem > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: true + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: true + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 1000 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 1000 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 1000 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 1 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/config/suspend.cfg b/tools/power/pm-graph/config/suspend.cfg new file mode 100644 index 000000000000..70d293231b06 --- /dev/null +++ b/tools/power/pm-graph/config/suspend.cfg @@ -0,0 +1,93 @@ +# +# Generic S3 (Suspend to Mem) test +# +# This is the configuration file for sleepgraph. It contains +# all the tool arguments so that they don't have to be given on the +# command line. It also includes advanced settings for functions +# and kprobes. It is run like this +# +# sudo ./sleepgraph.py -config config/suspend.cfg +# + +[Settings] + +# ---- General Options ---- + +# Verbosity +# print verbose messages (default: false) +verbose: false + +# Suspend Mode +# e.g. standby, mem, freeze, disk (default: mem) +mode: mem + +# Output Directory Format +# output folder for html, ftrace, and dmesg. Use {date} and {time} for current values +output-dir: suspend-{hostname}-{date}-{time} + +# Automatic Wakeup +# Use rtcwake to autoresume after X seconds, or off to disable (default: 15) +rtcwake: 15 + +# Add Logs +# add the dmesg and ftrace log to the html output (default: false) +addlogs: false + +# Suspend/Resume Gap +# insert a small visible gap between suspend and resume on the timeline (default: false) +srgap: false + +# ---- Advanced Options ---- + +# Command to execute in lieu of suspend (default: "") +# command: echo mem > /sys/power/state + +# Display user processes +# graph user processes and cpu usage in the timeline (default: false) +proc: false + +# Display function calls +# graph source functions in the timeline (default: false) +dev: false + +# Back to Back Suspend/Resume +# Run two suspend/resumes back to back (default: false) +x2: false + +# Back to Back Suspend Delay +# Time delay between the two test runs in ms (default: 0 ms) +x2delay: 0 + +# Pre Suspend Delay +# Include an N ms delay before (1st) suspend (default: 0 ms) +predelay: 0 + +# Post Resume Delay +# Include an N ms delay after (last) resume (default: 0 ms) +postdelay: 0 + +# Minimum Device Length +# graph only devices longer than min in the timeline (default: 0.001 ms) +mindev: 0.001 + +# ---- Debug Options ---- + +# Callgraph +# gather detailed ftrace callgraph data on all timeline events (default: false) +callgraph: false + +# Expand Callgraph +# pre-expand the callgraph data in the html output (default: disabled) +expandcg: false + +# Minimum Callgraph Length +# provide callgraph data for blocks longer than min (default: 0.001 ms) +mincg: 1 + +# Timestamp Precision +# Number of significant digits in timestamps (0:S, [3:ms], 6:us) +timeprec: 3 + +# Device Filter +# show only devs whose name/driver includes one of these strings +# devicefilter: _cpu_up,_cpu_down,i915,usb diff --git a/tools/power/pm-graph/sleepgraph.8 b/tools/power/pm-graph/sleepgraph.8 index fbe7bd3eae8e..18baaf6300c9 100644 --- a/tools/power/pm-graph/sleepgraph.8 +++ b/tools/power/pm-graph/sleepgraph.8 @@ -52,9 +52,32 @@ disable rtcwake and require a user keypress to resume. \fB-addlogs\fR Add the dmesg and ftrace logs to the html output. They will be viewable by clicking buttons in the timeline. +.TP +\fB-result \fIfile\fR +Export a results table to a text file for parsing. +.TP +\fB-sync\fR +Sync the filesystems before starting the test. This reduces the size of +the sys_sync call which happens in the suspend_prepare phase. +.TP +\fB-rs \fIenable/disable\fR +During test, enable/disable runtime suspend for all devices. The test is delayed +by 5 seconds to allow runtime suspend changes to occur. The settings are restored +after the test is complete. +.TP +\fB-display \fIon/off\fR +Turn the display on or off for the test using the xset command. This helps +maintain the consistecy of test data for better comparison. +.TP +\fB-skiphtml\fR +Run the test and capture the trace logs, but skip the timeline generation. .SS "advanced" .TP +\fB-gzip\fR +Gzip the trace and dmesg logs to save space. The tool can also read in gzipped +logs for processing. +.TP \fB-cmd \fIstr\fR Run the timeline over a custom suspend command, e.g. pm-suspend. By default the tool forces suspend via /sys/power/state so this allows testing over @@ -114,6 +137,18 @@ This reduces the html file size as there can be many tiny callgraphs which are barely visible in the timeline. The value is a float: e.g. 0.001 represents 1 us. .TP +\fB-cgfilter \fI"func1,func2,..."\fR +Reduce callgraph output in the timeline by limiting it to a list of calls. The +argument can be a single function name or a comma delimited list. +(default: none) +.TP +\fB-cgskip \fIfile\fR +Reduce callgraph timeline size by skipping over uninteresting functions +in the trace, e.g. printk or console_unlock. The functions listed +in this file will show up as empty leaves in the callgraph with only the start/end +times displayed. cgskip.txt is used automatically if found in the path, so +use "off" to disable completely (default: cgskip.txt) +.TP \fB-cgphase \fIp\fR Only show callgraph data for phase \fIp\fR (e.g. suspend_late). .TP @@ -122,6 +157,9 @@ In an x2 run, only show callgraph data for test \fIn\fR (e.g. 0 or 1). .TP \fB-timeprec \fIn\fR Number of significant digits in timestamps (0:S, [3:ms], 6:us). +.TP +\fB-bufsize \fIN\fR +Set trace buffer size to N kilo-bytes (default: all of free memory up to 3GB) .SH COMMANDS .TP @@ -144,11 +182,8 @@ Print out the contents of the ACPI Firmware Performance Data Table. \fB-sysinfo\fR Print out system info extracted from BIOS. Reads /dev/mem directly instead of going through dmidecode. .TP -\fB-usbtopo\fR -Print out the current USB topology with power info. -.TP -\fB-usbauto\fR -Enable autosuspend for all connected USB devices. +\fB-devinfo\fR +Print out the pm settings of all devices which support runtime suspend. .TP \fB-flist\fR Print the list of ftrace functions currently being captured. Functions @@ -198,7 +233,7 @@ Execute a mem suspend with a 15 second wakeup. Include the logs in the html. .PP Execute a standby with a 15 second wakeup. Change the output folder name. .IP -\f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{hostname}-{date}-{time}"\fR +\f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{host}-{date}-{time}"\fR .PP Execute a freeze with no wakeup (require keypress). Change output folder name. .IP diff --git a/tools/power/pm-graph/analyze_suspend.py b/tools/power/pm-graph/sleepgraph.py index 1b60fe203741..266409fb27ae 100755 --- a/tools/power/pm-graph/analyze_suspend.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -19,7 +19,7 @@ # Home Page # https://01.org/suspendresume # Source repo -# https://github.com/01org/pm-graph +# git@github.com:01org/pm-graph # # Description: # This tool is designed to assist kernel and OS developers in optimizing @@ -57,6 +57,7 @@ import platform from datetime import datetime import struct import ConfigParser +import gzip from threading import Thread from subprocess import call, Popen, PIPE @@ -68,8 +69,12 @@ from subprocess import call, Popen, PIPE # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '4.7' + version = '5.0' ansi = False + rs = 0 + display = 0 + gzip = False + sync = False verbose = False testlog = True dmesglog = False @@ -78,14 +83,19 @@ class SystemValues: mincglen = 0.0 cgphase = '' cgtest = -1 + cgskip = '' + multitest = {'run': False, 'count': 0, 'delay': 0} max_graph_depth = 0 callloopmaxgap = 0.0001 callloopmaxlen = 0.005 + bufsize = 0 cpucount = 0 memtotal = 204800 + memfree = 204800 srgap = 0 cgexp = False testdir = '' + outdir = '' tpath = '/sys/kernel/debug/tracing/' fpdtpath = '/sys/firmware/acpi/tables/FPDT' epath = '/sys/kernel/debug/tracing/events/power/' @@ -109,22 +119,24 @@ class SystemValues: dmesgfile = '' ftracefile = '' htmlfile = 'output.html' - embedded = False + result = '' rtcwake = True rtcwaketime = 15 rtcpath = '' devicefilter = [] + cgfilter = [] stamp = 0 execcount = 1 x2delay = 0 + skiphtml = False usecallgraph = False usetraceevents = False - usetraceeventsonly = False usetracemarkers = True usekprobes = True usedevsrc = False useprocmon = False notestrun = False + cgdump = False mixedphaseheight = True devprops = dict() predelay = 0 @@ -134,24 +146,33 @@ class SystemValues: tracertypefmt = '# tracer: (?P<t>.*)' firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' tracefuncs = { - 'sys_sync': dict(), - 'pm_prepare_console': dict(), - 'pm_notifier_call_chain': dict(), - 'freeze_processes': dict(), - 'freeze_kernel_threads': dict(), - 'pm_restrict_gfp_mask': dict(), - 'acpi_suspend_begin': dict(), - 'suspend_console': dict(), - 'acpi_pm_prepare': dict(), - 'syscore_suspend': dict(), - 'arch_enable_nonboot_cpus_end': dict(), - 'syscore_resume': dict(), - 'acpi_pm_finish': dict(), - 'resume_console': dict(), - 'acpi_pm_end': dict(), - 'pm_restore_gfp_mask': dict(), - 'thaw_processes': dict(), - 'pm_restore_console': dict(), + 'sys_sync': {}, + '__pm_notifier_call_chain': {}, + 'pm_prepare_console': {}, + 'pm_notifier_call_chain': {}, + 'freeze_processes': {}, + 'freeze_kernel_threads': {}, + 'pm_restrict_gfp_mask': {}, + 'acpi_suspend_begin': {}, + 'acpi_hibernation_begin': {}, + 'acpi_hibernation_enter': {}, + 'acpi_hibernation_leave': {}, + 'acpi_pm_freeze': {}, + 'acpi_pm_thaw': {}, + 'hibernate_preallocate_memory': {}, + 'create_basic_memory_bitmaps': {}, + 'swsusp_write': {}, + 'suspend_console': {}, + 'acpi_pm_prepare': {}, + 'syscore_suspend': {}, + 'arch_enable_nonboot_cpus_end': {}, + 'syscore_resume': {}, + 'acpi_pm_finish': {}, + 'resume_console': {}, + 'acpi_pm_end': {}, + 'pm_restore_gfp_mask': {}, + 'thaw_processes': {}, + 'pm_restore_console': {}, 'CPU_OFF': { 'func':'_cpu_down', 'args_x86_64': {'cpu':'%di:s32'}, @@ -173,56 +194,54 @@ class SystemValues: 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, 'acpi_os_stall': {'ub': 1}, # ACPI - 'acpi_resume_power_resources': dict(), - 'acpi_ps_parse_aml': dict(), + 'acpi_resume_power_resources': {}, + 'acpi_ps_parse_aml': {}, # filesystem - 'ext4_sync_fs': dict(), + 'ext4_sync_fs': {}, # 80211 - 'iwlagn_mac_start': dict(), - 'iwlagn_alloc_bcast_station': dict(), - 'iwl_trans_pcie_start_hw': dict(), - 'iwl_trans_pcie_start_fw': dict(), - 'iwl_run_init_ucode': dict(), - 'iwl_load_ucode_wait_alive': dict(), - 'iwl_alive_start': dict(), - 'iwlagn_mac_stop': dict(), - 'iwlagn_mac_suspend': dict(), - 'iwlagn_mac_resume': dict(), - 'iwlagn_mac_add_interface': dict(), - 'iwlagn_mac_remove_interface': dict(), - 'iwlagn_mac_change_interface': dict(), - 'iwlagn_mac_config': dict(), - 'iwlagn_configure_filter': dict(), - 'iwlagn_mac_hw_scan': dict(), - 'iwlagn_bss_info_changed': dict(), - 'iwlagn_mac_channel_switch': dict(), - 'iwlagn_mac_flush': dict(), + 'iwlagn_mac_start': {}, + 'iwlagn_alloc_bcast_station': {}, + 'iwl_trans_pcie_start_hw': {}, + 'iwl_trans_pcie_start_fw': {}, + 'iwl_run_init_ucode': {}, + 'iwl_load_ucode_wait_alive': {}, + 'iwl_alive_start': {}, + 'iwlagn_mac_stop': {}, + 'iwlagn_mac_suspend': {}, + 'iwlagn_mac_resume': {}, + 'iwlagn_mac_add_interface': {}, + 'iwlagn_mac_remove_interface': {}, + 'iwlagn_mac_change_interface': {}, + 'iwlagn_mac_config': {}, + 'iwlagn_configure_filter': {}, + 'iwlagn_mac_hw_scan': {}, + 'iwlagn_bss_info_changed': {}, + 'iwlagn_mac_channel_switch': {}, + 'iwlagn_mac_flush': {}, # ATA 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} }, # i915 - 'i915_gem_resume': dict(), - 'i915_restore_state': dict(), - 'intel_opregion_setup': dict(), - 'g4x_pre_enable_dp': dict(), - 'vlv_pre_enable_dp': dict(), - 'chv_pre_enable_dp': dict(), - 'g4x_enable_dp': dict(), - 'vlv_enable_dp': dict(), - 'intel_hpd_init': dict(), - 'intel_opregion_register': dict(), - 'intel_dp_detect': dict(), - 'intel_hdmi_detect': dict(), - 'intel_opregion_init': dict(), - 'intel_fbdev_set_suspend': dict(), + 'i915_gem_resume': {}, + 'i915_restore_state': {}, + 'intel_opregion_setup': {}, + 'g4x_pre_enable_dp': {}, + 'vlv_pre_enable_dp': {}, + 'chv_pre_enable_dp': {}, + 'g4x_enable_dp': {}, + 'vlv_enable_dp': {}, + 'intel_hpd_init': {}, + 'intel_opregion_register': {}, + 'intel_dp_detect': {}, + 'intel_hdmi_detect': {}, + 'intel_opregion_init': {}, + 'intel_fbdev_set_suspend': {}, } + cgblacklist = [] kprobes = dict() timeformat = '%.3f' + cmdline = '%s %s' % \ + (os.path.basename(sys.argv[0]), string.join(sys.argv[1:], ' ')) def __init__(self): - # if this is a phoronix test run, set some default options - if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): - self.embedded = True - self.dmesglog = self.ftracelog = True - self.htmlfile = os.environ['LOG_FILE'] self.archargs = 'args_'+platform.machine() self.hostname = platform.node() if(self.hostname == ''): @@ -237,18 +256,36 @@ class SystemValues: if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): self.ansi = True self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S') + def vprint(self, msg): + self.logmsg += msg+'\n' + if(self.verbose): + print(msg) def rootCheck(self, fatal=True): if(os.access(self.powerfile, os.W_OK)): return True if fatal: - doError('This command requires sysfs mount and root access') + msg = 'This command requires sysfs mount and root access' + print('ERROR: %s\n') % msg + self.outputResult({'error':msg}) + sys.exit() return False def rootUser(self, fatal=False): if 'USER' in os.environ and os.environ['USER'] == 'root': return True if fatal: - doError('This command must be run as root') + msg = 'This command must be run as root' + print('ERROR: %s\n') % msg + self.outputResult({'error':msg}) + sys.exit() return False + def getExec(self, cmd): + dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin', + '/usr/local/sbin', '/usr/local/bin'] + for path in dirlist: + cmdfull = os.path.join(path, cmd) + if os.path.exists(cmdfull): + return cmdfull + return '' def setPrecision(self, num): if num < 0 or num > 6: return @@ -258,15 +295,15 @@ class SystemValues: n = datetime.now() args['date'] = n.strftime('%y%m%d') args['time'] = n.strftime('%H%M%S') - args['hostname'] = self.hostname + args['hostname'] = args['host'] = self.hostname return value.format(**args) def setOutputFile(self): if self.dmesgfile != '': - m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) + m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile) if(m): self.htmlfile = m.group('name')+'.html' if self.ftracefile != '': - m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile) + m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile) if(m): self.htmlfile = m.group('name')+'.html' def systemInfo(self, info): @@ -283,16 +320,19 @@ class SystemValues: c = info['processor-version'] if 'bios-version' in info: b = info['bios-version'] - self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d' % \ - (m, p, c, b, self.cpucount, self.memtotal) - def printSystemInfo(self): + self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \ + (m, p, c, b, self.cpucount, self.memtotal, self.memfree) + def printSystemInfo(self, fatal=False): self.rootCheck(True) - out = dmidecode(self.mempath, True) + out = dmidecode(self.mempath, fatal) + if len(out) < 1: + return fmt = '%-24s: %s' for name in sorted(out): print fmt % (name, out[name]) print fmt % ('cpucount', ('%d' % self.cpucount)) print fmt % ('memtotal', ('%d kB' % self.memtotal)) + print fmt % ('memfree', ('%d kB' % self.memfree)) def cpuInfo(self): self.cpucount = 0 fp = open('/proc/cpuinfo', 'r') @@ -305,7 +345,9 @@ class SystemValues: m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line) if m: self.memtotal = int(m.group('sz')) - break + m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line) + if m: + self.memfree = int(m.group('sz')) fp.close() def initTestOutput(self, name): self.prefix = self.hostname @@ -315,39 +357,34 @@ class SystemValues: testtime = datetime.now().strftime(fmt) self.teststamp = \ '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver - if(self.embedded): - self.dmesgfile = \ - '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt' - self.ftracefile = \ - '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt' - return + ext = '' + if self.gzip: + ext = '.gz' self.dmesgfile = \ - self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' + self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext self.ftracefile = \ - self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' + self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext self.htmlfile = \ self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' if not os.path.isdir(self.testdir): os.mkdir(self.testdir) + def getValueList(self, value): + out = [] + for i in value.split(','): + if i.strip(): + out.append(i.strip()) + return out def setDeviceFilter(self, value): - self.devicefilter = [] - if value: - value = value.split(',') - for i in value: - self.devicefilter.append(i.strip()) + self.devicefilter = self.getValueList(value) + def setCallgraphFilter(self, value): + self.cgfilter = self.getValueList(value) + def setCallgraphBlacklist(self, file): + self.cgblacklist = self.listFromFile(file) def rtcWakeAlarmOn(self): call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True) - outD = open(self.rtcpath+'/date', 'r').read().strip() - outT = open(self.rtcpath+'/time', 'r').read().strip() - mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD) - mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT) - if(mD and mT): - # get the current time from hardware - utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds()) - dt = datetime(\ - int(mD.group('y')), int(mD.group('m')), int(mD.group('d')), - int(mT.group('h')), int(mT.group('m')), int(mT.group('s'))) - nowtime = int(dt.strftime('%s')) + utcoffset + nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip() + if nowtime: + nowtime = int(nowtime) else: # if hardware time fails, use the software time nowtime = int(datetime.now().strftime('%s')) @@ -369,10 +406,10 @@ class SystemValues: ktime = m.group('ktime') fp.close() self.dmesgstart = float(ktime) - def getdmesg(self): + def getdmesg(self, fwdata=[]): + op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata) # store all new dmesg lines since initdmesg was called fp = Popen('dmesg', stdout=PIPE).stdout - op = open(self.dmesgfile, 'a') for line in fp: line = line.replace('\r\n', '') idx = line.find('[') @@ -386,11 +423,17 @@ class SystemValues: op.write(line) fp.close() op.close() - def addFtraceFilterFunctions(self, file): + def listFromFile(self, file): + list = [] fp = open(file) - list = fp.read().split('\n') + for i in fp.read().split('\n'): + i = i.strip() + if i and i[0] != '#': + list.append(i) fp.close() - for i in list: + return list + def addFtraceFilterFunctions(self, file): + for i in self.listFromFile(file): if len(i) < 2: continue self.tracefuncs[i] = dict() @@ -399,9 +442,7 @@ class SystemValues: if not current: call('cat '+self.tpath+'available_filter_functions', shell=True) return - fp = open(self.tpath+'available_filter_functions') - master = fp.read().split('\n') - fp.close() + master = self.listFromFile(self.tpath+'available_filter_functions') for i in self.tracefuncs: if 'func' in self.tracefuncs[i]: i = self.tracefuncs[i]['func'] @@ -410,9 +451,7 @@ class SystemValues: else: print self.colorText(i) def setFtraceFilterFunctions(self, list): - fp = open(self.tpath+'available_filter_functions') - master = fp.read().split('\n') - fp.close() + master = self.listFromFile(self.tpath+'available_filter_functions') flist = '' for i in list: if i not in master: @@ -501,6 +540,7 @@ class SystemValues: rejects = [] # sort kprobes: trace, ub-dev, custom, dev kpl = [[], [], [], []] + linesout = len(self.kprobes) for name in sorted(self.kprobes): res = self.colorText('YES', 32) if not self.testKprobe(name, self.kprobes[name]): @@ -528,17 +568,10 @@ class SystemValues: for kp in kplist: kprobeevents += self.kprobeText(kp, self.kprobes[kp]) self.fsetVal(kprobeevents, 'kprobe_events') - # verify that the kprobes were set as ordered - check = self.fgetVal('kprobe_events') - linesout = len(kprobeevents.split('\n')) - 1 - linesack = len(check.split('\n')) - 1 if output: - res = '%d/%d' % (linesack, linesout) - if linesack < linesout: - res = self.colorText(res, 31) - else: - res = self.colorText(res, 32) - print(' working kprobe functions enabled: %s' % res) + check = self.fgetVal('kprobe_events') + linesack = (len(check.split('\n')) - 1) / 2 + print(' kprobe functions enabled: %d/%d' % (linesack, linesout)) self.fsetVal('1', 'events/kprobes/enable') def testKprobe(self, kname, kprobe): self.fsetVal('0', 'events/kprobes/enable') @@ -555,8 +588,7 @@ class SystemValues: if linesack < linesout: return False return True - def fsetVal(self, val, path, mode='w'): - file = self.tpath+path + def setVal(self, val, file, mode='w'): if not os.path.exists(file): return False try: @@ -567,8 +599,9 @@ class SystemValues: except: return False return True - def fgetVal(self, path): - file = self.tpath+path + def fsetVal(self, val, path, mode='w'): + return self.setVal(val, self.tpath+path, mode) + def getVal(self, file): res = '' if not os.path.exists(file): return res @@ -579,10 +612,13 @@ class SystemValues: except: pass return res + def fgetVal(self, path): + return self.getVal(self.tpath+path) def cleanupFtrace(self): - if(self.usecallgraph or self.usetraceevents): + if(self.usecallgraph or self.usetraceevents or self.usedevsrc): self.fsetVal('0', 'events/kprobes/enable') self.fsetVal('', 'kprobe_events') + self.fsetVal('1024', 'buffer_size_kb') def setupAllKprobes(self): for name in self.tracefuncs: self.defaultKprobe(name, self.tracefuncs[name]) @@ -599,7 +635,8 @@ class SystemValues: if name == f: return True return False - def initFtrace(self, testing=False): + def initFtrace(self): + self.printSystemInfo(False) print('INITIALIZING FTRACE...') # turn trace off self.fsetVal('0', 'tracing_on') @@ -607,17 +644,21 @@ class SystemValues: # set the trace clock to global self.fsetVal('global', 'trace_clock') self.fsetVal('nop', 'current_tracer') - # set trace buffer to a huge value - if self.usecallgraph or self.usedevsrc: - tgtsize = min(self.memtotal / 2, 2*1024*1024) - maxbuf = '%d' % (tgtsize / max(1, self.cpucount)) - if self.cpucount < 1 or not self.fsetVal(maxbuf, 'buffer_size_kb'): - self.fsetVal('131072', 'buffer_size_kb') + # set trace buffer to an appropriate value + cpus = max(1, self.cpucount) + if self.bufsize > 0: + tgtsize = self.bufsize + elif self.usecallgraph or self.usedevsrc: + tgtsize = min(self.memfree, 3*1024*1024) else: - self.fsetVal('16384', 'buffer_size_kb') - # go no further if this is just a status check - if testing: - return + tgtsize = 65536 + while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'): + # if the size failed to set, lower it and keep trying + tgtsize -= 65536 + if tgtsize < 65536: + tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus + break + print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus) # initialize the callgraph trace if(self.usecallgraph): # set trace type @@ -635,7 +676,7 @@ class SystemValues: self.fsetVal('graph-time', 'trace_options') self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth') cf = ['dpm_run_callback'] - if(self.usetraceeventsonly): + if(self.usetraceevents): cf += ['dpm_prepare', 'dpm_complete'] for fn in self.tracefuncs: if 'func' in self.tracefuncs[fn]: @@ -688,16 +729,65 @@ class SystemValues: return str return '\x1B[%d;40m%s\x1B[m' % (color, str) def writeDatafileHeader(self, filename, fwdata=[]): - fp = open(filename, 'w') - fp.write(self.teststamp+'\n') - fp.write(self.sysstamp+'\n') + fp = self.openlog(filename, 'w') + fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline)) if(self.suspendmode == 'mem' or self.suspendmode == 'command'): for fw in fwdata: if(fw): fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) + return fp + def sudouser(self, dir): + if os.path.exists(dir) and os.getuid() == 0 and \ + 'SUDO_USER' in os.environ: + cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' + call(cmd.format(os.environ['SUDO_USER'], dir), shell=True) + def outputResult(self, testdata, num=0): + if not self.result: + return + n = '' + if num > 0: + n = '%d' % num + fp = open(self.result, 'a') + if 'error' in testdata: + fp.write('result%s: fail\n' % n) + fp.write('error%s: %s\n' % (n, testdata['error'])) + else: + fp.write('result%s: pass\n' % n) + for v in ['suspend', 'resume', 'boot', 'lastinit']: + if v in testdata: + fp.write('%s%s: %.3f\n' % (v, n, testdata[v])) + for v in ['fwsuspend', 'fwresume']: + if v in testdata: + fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0)) + if 'bugurl' in testdata: + fp.write('url%s: %s\n' % (n, testdata['bugurl'])) fp.close() + self.sudouser(self.result) + def configFile(self, file): + dir = os.path.dirname(os.path.realpath(__file__)) + if os.path.exists(file): + return file + elif os.path.exists(dir+'/'+file): + return dir+'/'+file + elif os.path.exists(dir+'/config/'+file): + return dir+'/config/'+file + return '' + def openlog(self, filename, mode): + isgz = self.gzip + if mode == 'r': + try: + with gzip.open(filename, mode+'b') as fp: + test = fp.read(64) + isgz = True + except: + isgz = False + if isgz: + return gzip.open(filename, mode+'b') + return open(filename, mode) sysvals = SystemValues() +switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0'] +switchoff = ['disable', 'off', 'false', '0'] suspendmodename = { 'freeze': 'Freeze (S0)', 'standby': 'Standby (S1)', @@ -826,34 +916,65 @@ class Data: for phase in self.phases: self.devicegroups.append([phase]) self.errorinfo = {'suspend':[],'resume':[]} - def extractErrorInfo(self, dmesg): - error = '' - tm = 0.0 - for i in range(len(dmesg)): - if 'Call Trace:' in dmesg[i]: - m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i]) - if not m: - continue - tm = float(m.group('ktime')) - if tm < self.start or tm > self.end: - continue - for j in range(i-10, i+1): - error += dmesg[j] + def extractErrorInfo(self): + lf = sysvals.openlog(sysvals.dmesgfile, 'r') + i = 0 + list = [] + # sl = start line, et = error time, el = error line + type = 'ERROR' + sl = et = el = -1 + for line in lf: + i += 1 + m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) + if not m: continue - if error: - m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i]) - if m: - error += dmesg[i] - else: - if tm < self.tSuspended: - dir = 'suspend' - else: - dir = 'resume' - error = error.replace('<', '<').replace('>', '>') - vprint('kernel error found in %s at %f' % (dir, tm)) - self.errorinfo[dir].append((tm, error)) + t = float(m.group('ktime')) + if t < self.start or t > self.end: + continue + if t < self.tSuspended: + dir = 'suspend' + else: + dir = 'resume' + msg = m.group('msg') + if re.match('-*\[ *cut here *\]-*', msg): + type = 'WARNING' + sl = i + elif re.match('genirq: .*', msg): + type = 'IRQ' + sl = i + elif re.match('BUG: .*', msg) or re.match('kernel BUG .*', msg): + type = 'BUG' + sl = i + elif re.match('-*\[ *end trace .*\]-*', msg) or \ + re.match('R13: .*', msg): + if et >= 0 and sl >= 0: + list.append((type, dir, et, sl, i)) self.kerror = True - error = '' + sl = et = el = -1 + type = 'ERROR' + elif 'Call Trace:' in msg: + if el >= 0 and et >= 0: + list.append((type, dir, et, el, el)) + self.kerror = True + et, el = t, i + if sl < 0 or type == 'BUG': + slval = i + if sl >= 0: + slval = sl + list.append((type, dir, et, slval, i)) + self.kerror = True + sl = et = el = -1 + type = 'ERROR' + if el >= 0 and et >= 0: + list.append((type, dir, et, el, el)) + self.kerror = True + for e in list: + type, dir, t, idx1, idx2 = e + sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t)) + self.errorinfo[dir].append((type, t, idx1, idx2)) + if self.kerror: + sysvals.dmesglog = True + lf.close() def setStart(self, time): self.start = time def setEnd(self, time): @@ -867,6 +988,14 @@ class Data: time < d['end']): return False return True + def phaseCollision(self, phase, isbegin, line): + key = 'end' + if isbegin: + key = 'start' + if self.dmesg[phase][key] >= 0: + sysvals.vprint('IGNORE: %s' % line.strip()) + return True + return False def sourcePhase(self, start): for phase in self.phases: pend = self.dmesg[phase]['end'] @@ -918,7 +1047,7 @@ class Data: return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) # this should not happen if not tgtdev: - vprint('[%f - %f] %s-%d %s %s %s' % \ + sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \ (start, end, proc, pid, kprobename, cdata, rdata)) return False # place the call data inside the src element of the tgtdev @@ -1054,6 +1183,13 @@ class Data: if('src' in d): for e in d['src']: e.time = self.trimTimeVal(e.time, t0, dT, left) + for dir in ['suspend', 'resume']: + list = [] + for e in self.errorinfo[dir]: + type, tm, idx1, idx2 = e + tm = self.trimTimeVal(tm, t0, dT, left) + list.append((type, tm, idx1, idx2)) + self.errorinfo[dir] = list def normalizeTime(self, tZero): # trim out any standby or freeze clock time if(self.tSuspended != self.tResumed): @@ -1100,7 +1236,7 @@ class Data: if self.dmesg[p]['end'] > dev['start']: dev['end'] = self.dmesg[p]['end'] break - vprint('%s (%s): callback didnt return' % (devname, phase)) + sysvals.vprint('%s (%s): callback didnt return' % (devname, phase)) def deviceFilter(self, devicefilter): for phase in self.phases: list = self.dmesg[phase]['list'] @@ -1200,15 +1336,15 @@ class Data: devlist.append(child) return devlist def printDetails(self): - vprint('Timeline Details:') - vprint(' test start: %f' % self.start) - vprint('kernel suspend start: %f' % self.tKernSus) + sysvals.vprint('Timeline Details:') + sysvals.vprint(' test start: %f' % self.start) + sysvals.vprint('kernel suspend start: %f' % self.tKernSus) for phase in self.phases: dc = len(self.dmesg[phase]['list']) - vprint(' %16s: %f - %f (%d devices)' % (phase, \ + sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) - vprint(' kernel resume end: %f' % self.tKernRes) - vprint(' test end: %f' % self.end) + sysvals.vprint(' kernel resume end: %f' % self.tKernRes) + sysvals.vprint(' test end: %f' % self.end) def deviceChildrenAllPhases(self, devname): devlist = [] for phase in self.phases: @@ -1358,14 +1494,21 @@ class Data: tres.append(t) # process the events for suspend and resume if len(proclist) > 0: - vprint('Process Execution:') + sysvals.vprint('Process Execution:') for ps in proclist: c = self.addProcessUsageEvent(ps, tsus) if c > 0: - vprint('%25s (sus): %d' % (ps, c)) + sysvals.vprint('%25s (sus): %d' % (ps, c)) c = self.addProcessUsageEvent(ps, tres) if c > 0: - vprint('%25s (res): %d' % (ps, c)) + sysvals.vprint('%25s (res): %d' % (ps, c)) + def debugPrint(self): + for p in self.phases: + list = self.dmesg[p]['list'] + for devname in list: + dev = list[devname] + if 'ftrace' in dev: + dev['ftrace'].debugPrint(' [%s]' % devname) # Class: DevFunction # Description: @@ -1504,18 +1647,24 @@ class FTraceLine: # something else (possibly a trace marker) else: self.name = m + def isCall(self): + return self.fcall and not self.freturn + def isReturn(self): + return self.freturn and not self.fcall + def isLeaf(self): + return self.fcall and self.freturn def getDepth(self, str): return len(str)/2 - def debugPrint(self, dev=''): - if(self.freturn and self.fcall): - print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ - self.depth, self.name, self.length*1000000)) - elif(self.freturn): - print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ - self.depth, self.name, self.length*1000000)) + def debugPrint(self, info=''): + if self.isLeaf(): + print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ + self.depth, self.name, self.length*1000000, info)) + elif self.freturn: + print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ + self.depth, self.name, self.length*1000000, info)) else: - print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ - self.depth, self.name, self.length*1000000)) + print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \ + self.depth, self.name, self.length*1000000, info)) def startMarker(self): # Is this the starting line of a suspend? if not self.fevent: @@ -1558,107 +1707,160 @@ class FTraceCallGraph: depth = 0 pid = 0 name = '' - def __init__(self, pid): + partial = False + vfname = 'missing_function_name' + ignore = False + sv = 0 + def __init__(self, pid, sv): self.start = -1.0 self.end = -1.0 self.list = [] self.depth = 0 self.pid = pid - def addLine(self, line, debug=False): + self.sv = sv + def addLine(self, line): # if this is already invalid, just leave if(self.invalid): - return False - # invalidate on too much data or bad depth - if(len(self.list) >= 1000000 or self.depth < 0): + if(line.depth == 0 and line.freturn): + return 1 + return 0 + # invalidate on bad depth + if(self.depth < 0): self.invalidate(line) - return False + return 0 + # ignore data til we return to the current depth + if self.ignore: + if line.depth > self.depth: + return 0 + else: + self.list[-1].freturn = True + self.list[-1].length = line.time - self.list[-1].time + self.ignore = False + # if this is a return at self.depth, no more work is needed + if line.depth == self.depth and line.isReturn(): + if line.depth == 0: + self.end = line.time + return 1 + return 0 # compare current depth with this lines pre-call depth prelinedep = line.depth - if(line.freturn and not line.fcall): + if line.isReturn(): prelinedep += 1 last = 0 lasttime = line.time - virtualfname = 'missing_function_name' if len(self.list) > 0: last = self.list[-1] lasttime = last.time + if last.isLeaf(): + lasttime += last.length # handle low misalignments by inserting returns - if prelinedep < self.depth: - if debug and last: - print '-------- task %d --------' % self.pid - last.debugPrint() + mismatch = prelinedep - self.depth + warning = self.sv.verbose and abs(mismatch) > 1 + info = [] + if mismatch < 0: idx = 0 # add return calls to get the depth down while prelinedep < self.depth: - if debug: - print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep) self.depth -= 1 - if idx == 0 and last and last.fcall and not last.freturn: + if idx == 0 and last and last.isCall(): # special case, turn last call into a leaf last.depth = self.depth last.freturn = True last.length = line.time - last.time - if debug: - last.debugPrint() + if warning: + info.append(('[make leaf]', last)) else: vline = FTraceLine(lasttime) vline.depth = self.depth - vline.name = virtualfname + vline.name = self.vfname vline.freturn = True self.list.append(vline) - if debug: - vline.debugPrint() + if warning: + if idx == 0: + info.append(('', last)) + info.append(('[add return]', vline)) idx += 1 - if debug: - line.debugPrint() - print '' + if warning: + info.append(('', line)) # handle high misalignments by inserting calls - elif prelinedep > self.depth: - if debug and last: - print '-------- task %d --------' % self.pid - last.debugPrint() + elif mismatch > 0: idx = 0 + if warning: + info.append(('', last)) # add calls to get the depth up while prelinedep > self.depth: - if debug: - print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep) - if idx == 0 and line.freturn and not line.fcall: + if idx == 0 and line.isReturn(): # special case, turn this return into a leaf line.fcall = True prelinedep -= 1 + if warning: + info.append(('[make leaf]', line)) else: vline = FTraceLine(lasttime) vline.depth = self.depth - vline.name = virtualfname + vline.name = self.vfname vline.fcall = True - if debug: - vline.debugPrint() self.list.append(vline) self.depth += 1 if not last: self.start = vline.time + if warning: + info.append(('[add call]', vline)) idx += 1 - if debug: - line.debugPrint() - print '' + if warning and ('[make leaf]', line) not in info: + info.append(('', line)) + if warning: + print 'WARNING: ftrace data missing, corrections made:' + for i in info: + t, obj = i + if obj: + obj.debugPrint(t) # process the call and set the new depth - if(line.fcall and not line.freturn): - self.depth += 1 - elif(line.freturn and not line.fcall): + skipadd = False + md = self.sv.max_graph_depth + if line.isCall(): + # ignore blacklisted/overdepth funcs + if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist): + self.ignore = True + else: + self.depth += 1 + elif line.isReturn(): self.depth -= 1 + # remove blacklisted/overdepth/empty funcs that slipped through + if (last and last.isCall() and last.depth == line.depth) or \ + (md and last and last.depth >= md) or \ + (line.name in self.sv.cgblacklist): + while len(self.list) > 0 and self.list[-1].depth > line.depth: + self.list.pop(-1) + if len(self.list) == 0: + self.invalid = True + return 1 + self.list[-1].freturn = True + self.list[-1].length = line.time - self.list[-1].time + self.list[-1].name = line.name + skipadd = True if len(self.list) < 1: self.start = line.time - self.list.append(line) + # check for a mismatch that returned all the way to callgraph end + res = 1 + if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn: + line = self.list[-1] + skipadd = True + res = -1 + if not skipadd: + self.list.append(line) if(line.depth == 0 and line.freturn): if(self.start < 0): self.start = line.time self.end = line.time if line.fcall: self.end += line.length - if self.list[0].name == virtualfname: + if self.list[0].name == self.vfname: self.invalid = True - return True - return False + if res == -1: + self.partial = True + return res + return 0 def invalidate(self, line): if(len(self.list) > 0): first = self.list[0] @@ -1668,29 +1870,30 @@ class FTraceCallGraph: id = 'task %s' % (self.pid) window = '(%f - %f)' % (self.start, line.time) if(self.depth < 0): - vprint('Too much data for '+id+\ + print('Data misalignment for '+id+\ ' (buffer overflow), ignoring this callback') else: - vprint('Too much data for '+id+\ + print('Too much data for '+id+\ ' '+window+', ignoring this callback') - def slice(self, t0, tN): - minicg = FTraceCallGraph(0) - count = -1 - firstdepth = 0 + def slice(self, dev): + minicg = FTraceCallGraph(dev['pid'], self.sv) + minicg.name = self.name + mydepth = -1 + good = False for l in self.list: - if(l.time < t0 or l.time > tN): + if(l.time < dev['start'] or l.time > dev['end']): continue - if(count < 0): - if(not l.fcall or l.name == 'dev_driver_string'): - continue - firstdepth = l.depth - count = 0 - l.depth -= firstdepth - minicg.addLine(l) - if((count == 0 and l.freturn and l.fcall) or - (count > 0 and l.depth <= 0)): + if mydepth < 0: + if l.name == 'mutex_lock' and l.freturn: + mydepth = l.depth + continue + elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall: + good = True break - count += 1 + l.depth -= mydepth + minicg.addLine(l) + if not good or len(minicg.list) < 1: + return 0 return minicg def repair(self, enddepth): # bring the depth back to 0 with additional returns @@ -1701,11 +1904,11 @@ class FTraceCallGraph: t.depth = i t.freturn = True fixed = self.addLine(t) - if fixed: + if fixed != 0: self.end = last.time return True return False - def postProcess(self, debug=False): + def postProcess(self): if len(self.list) > 0: self.name = self.list[0].name stack = dict() @@ -1714,20 +1917,23 @@ class FTraceCallGraph: for l in self.list: # ftrace bug: reported duration is not reliable # check each leaf and clip it at max possible length - if(last and last.freturn and last.fcall): + if last and last.isLeaf(): if last.length > l.time - last.time: last.length = l.time - last.time - if(l.fcall and not l.freturn): + if l.isCall(): stack[l.depth] = l cnt += 1 - elif(l.freturn and not l.fcall): + elif l.isReturn(): if(l.depth not in stack): - if debug: + if self.sv.verbose: print 'Post Process Error: Depth missing' l.debugPrint() return False # calculate call length from call/return lines - stack[l.depth].length = l.time - stack[l.depth].time + cl = stack[l.depth] + cl.length = l.time - cl.time + if cl.name == self.vfname: + cl.name = l.name stack.pop(l.depth) l.length = 0 cnt -= 1 @@ -1736,13 +1942,13 @@ class FTraceCallGraph: # trace caught the whole call tree return True elif(cnt < 0): - if debug: + if self.sv.verbose: print 'Post Process Error: Depth is less than 0' return False # trace ended before call tree finished return self.repair(cnt) def deviceMatch(self, pid, data): - found = False + found = '' # add the callgraph data to the device hierarchy borderphase = { 'dpm_prepare': 'suspend_prepare', @@ -1756,8 +1962,10 @@ class FTraceCallGraph: if(pid == dev['pid'] and self.start <= dev['start'] and self.end >= dev['end']): - dev['ftrace'] = self.slice(dev['start'], dev['end']) - found = True + cg = self.slice(dev) + if cg: + dev['ftrace'] = cg + found = devname return found for p in data.phases: if(data.dmesg[p]['start'] <= self.start and @@ -1769,7 +1977,7 @@ class FTraceCallGraph: self.start <= dev['start'] and self.end >= dev['end']): dev['ftrace'] = self - found = True + found = devname break break return found @@ -1793,18 +2001,20 @@ class FTraceCallGraph: if out: phase, myname = out data.dmesg[phase]['list'][myname]['ftrace'] = self - def debugPrint(self): - print('[%f - %f] %s (%d)') % (self.start, self.end, self.name, self.pid) + def debugPrint(self, info=''): + print('%s pid=%d [%f - %f] %.3f us') % \ + (self.name, self.pid, self.start, self.end, + (self.end - self.start)*1000000) for l in self.list: - if(l.freturn and l.fcall): - print('%f (%02d): %s(); (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) - elif(l.freturn): - print('%f (%02d): %s} (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) + if l.isLeaf(): + print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ + l.depth, l.name, l.length*1000000, info)) + elif l.freturn: + print('%f (%02d): %s} (%.3f us)%s' % (l.time, \ + l.depth, l.name, l.length*1000000, info)) else: - print('%f (%02d): %s() { (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) + print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ + l.depth, l.name, l.length*1000000, info)) print(' ') class DevItem: @@ -1839,8 +2049,8 @@ class Timeline: self.rowH = rowheight self.scaleH = scaleheight self.html = '' - def createHeader(self, sv): - if(not sv.stamp['time']): + def createHeader(self, sv, stamp): + if(not stamp['time']): return self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \ % (sv.title, sv.version) @@ -1851,12 +2061,12 @@ class Timeline: if sv.ftracelog: self.html += '<button id="showftrace" class="logbtn btnfmt">ftrace</button>' headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' - self.html += headline_stamp.format(sv.stamp['host'], sv.stamp['kernel'], - sv.stamp['mode'], sv.stamp['time']) - if 'man' in sv.stamp and 'plat' in sv.stamp and 'cpu' in sv.stamp: + self.html += headline_stamp.format(stamp['host'], stamp['kernel'], + stamp['mode'], stamp['time']) + if 'man' in stamp and 'plat' in stamp and 'cpu' in stamp and \ + stamp['man'] and stamp['plat'] and stamp['cpu']: headline_sysinfo = '<div class="stamp sysinfo">{0} {1} <i>with</i> {2}</div>\n' - self.html += headline_sysinfo.format(sv.stamp['man'], - sv.stamp['plat'], sv.stamp['cpu']) + self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu']) # Function: getDeviceRows # Description: @@ -2067,12 +2277,16 @@ class Timeline: class TestProps: stamp = '' sysinfo = '' + cmdline = '' + kparams = '' S0i3 = False fwdata = [] stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' sysinfofmt = '^# sysinfo .*' + cmdlinefmt = '^# command \| (?P<cmd>.*)' + kparamsfmt = '^# kparams \| (?P<kp>.*)' ftrace_line_fmt_fg = \ '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ @@ -2116,13 +2330,20 @@ class TestProps: sv.hostname = data.stamp['host'] sv.suspendmode = data.stamp['mode'] if sv.suspendmode == 'command' and sv.ftracefile != '': - modes = ['on', 'freeze', 'standby', 'mem'] - out = Popen(['grep', 'suspend_enter', sv.ftracefile], + modes = ['on', 'freeze', 'standby', 'mem', 'disk'] + out = Popen(['grep', 'machine_suspend', sv.ftracefile], stderr=PIPE, stdout=PIPE).stdout.read() - m = re.match('.* suspend_enter\[(?P<mode>.*)\]', out) - if m and m.group('mode') in ['1', '2', '3']: + m = re.match('.* machine_suspend\[(?P<mode>.*)\]', out) + if m and m.group('mode') in ['1', '2', '3', '4']: sv.suspendmode = modes[int(m.group('mode'))] data.stamp['mode'] = sv.suspendmode + m = re.match(self.cmdlinefmt, self.cmdline) + if m: + sv.cmdline = m.group('cmd') + if self.kparams: + m = re.match(self.kparamsfmt, self.kparams) + if m: + sv.kparams = m.group('kp') if not sv.stamp: sv.stamp = data.stamp @@ -2186,47 +2407,43 @@ class ProcessMonitor: # ----------------- FUNCTIONS -------------------- -# Function: vprint -# Description: -# verbose print (prints only with -verbose option) -# Arguments: -# msg: the debug/log message to print -def vprint(msg): - sysvals.logmsg += msg+'\n' - if(sysvals.verbose): - print(msg) - # Function: doesTraceLogHaveTraceEvents # Description: -# Quickly determine if the ftrace log has some or all of the trace events -# required for primary parsing. Set the usetraceevents and/or -# usetraceeventsonly flags in the global sysvals object +# Quickly determine if the ftrace log has all of the trace events, +# markers, and/or kprobes required for primary parsing. def doesTraceLogHaveTraceEvents(): - # check for kprobes + kpcheck = ['_cal: (', '_cpu_down()'] + techeck = sysvals.traceevents[:] + tmcheck = ['SUSPEND START', 'RESUME COMPLETE'] sysvals.usekprobes = False - out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True) - if(out == 0): - sysvals.usekprobes = True - # check for callgraph data on trace event blocks - out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True) - if(out == 0): - sysvals.usekprobes = True - out = Popen(['head', '-1', sysvals.ftracefile], - stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') - # figure out what level of trace events are supported - sysvals.usetraceeventsonly = True - sysvals.usetraceevents = False - for e in sysvals.traceevents: - out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True) - if(out != 0): - sysvals.usetraceeventsonly = False - if(e == 'suspend_resume' and out == 0): - sysvals.usetraceevents = True - # determine is this log is properly formatted - for e in ['SUSPEND START', 'RESUME COMPLETE']: - out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True) - if(out != 0): - sysvals.usetracemarkers = False + fp = sysvals.openlog(sysvals.ftracefile, 'r') + for line in fp: + # check for kprobes + if not sysvals.usekprobes: + for i in kpcheck: + if i in line: + sysvals.usekprobes = True + # check for all necessary trace events + check = techeck[:] + for i in techeck: + if i in line: + check.remove(i) + techeck = check + # check for all necessary trace markers + check = tmcheck[:] + for i in tmcheck: + if i in line: + check.remove(i) + tmcheck = check + fp.close() + if len(techeck) == 0: + sysvals.usetraceevents = True + else: + sysvals.usetraceevents = False + if len(tmcheck) == 0: + sysvals.usetracemarkers = True + else: + sysvals.usetracemarkers = False # Function: appendIncompleteTraceLog # Description: @@ -2247,9 +2464,10 @@ def appendIncompleteTraceLog(testruns): testrun.append(TestRun(data)) # extract the callgraph and traceevent data - vprint('Analyzing the ftrace data...') + sysvals.vprint('Analyzing the ftrace data (%s)...' % \ + os.path.basename(sysvals.ftracefile)) tp = TestProps() - tf = open(sysvals.ftracefile, 'r') + tf = sysvals.openlog(sysvals.ftracefile, 'r') data = 0 for line in tf: # remove any latent carriage returns @@ -2261,6 +2479,9 @@ def appendIncompleteTraceLog(testruns): elif re.match(tp.sysinfofmt, line): tp.sysinfo = line continue + elif re.match(tp.cmdlinefmt, line): + tp.cmdline = line + continue # determine the trace data type (required for further parsing) m = re.match(sysvals.tracertypefmt, line) if(m): @@ -2393,11 +2614,14 @@ def appendIncompleteTraceLog(testruns): # create a callgraph object for the data if(pid not in testrun[testidx].ftemp): testrun[testidx].ftemp[pid] = [] - testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid)) + testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals)) # when the call is finished, see which device matches it cg = testrun[testidx].ftemp[pid][-1] - if(cg.addLine(t)): - testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid)) + res = cg.addLine(t) + if(res != 0): + testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid, sysvals)) + if(res == -1): + testrun[testidx].ftemp[pid][-1].addLine(t) tf.close() for test in testrun: @@ -2410,11 +2634,11 @@ def appendIncompleteTraceLog(testruns): # add the callgraph data to the device hierarchy for pid in test.ftemp: for cg in test.ftemp[pid]: - if len(cg.list) < 1 or cg.invalid: + if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0): continue if(not cg.postProcess()): id = 'task %s cpu %s' % (pid, m.group('cpu')) - vprint('Sanity check failed for '+\ + sysvals.vprint('Sanity check failed for '+\ id+', ignoring this callback') continue callstart = cg.start @@ -2431,8 +2655,6 @@ def appendIncompleteTraceLog(testruns): dev['ftrace'] = cg break - test.data.printDetails() - # Function: parseTraceLog # Description: # Analyze an ftrace log output file generated from this app during @@ -2441,12 +2663,13 @@ def appendIncompleteTraceLog(testruns): # The ftrace filename is taken from sysvals # Output: # An array of Data objects -def parseTraceLog(): - vprint('Analyzing the ftrace data...') +def parseTraceLog(live=False): + sysvals.vprint('Analyzing the ftrace data (%s)...' % \ + os.path.basename(sysvals.ftracefile)) if(os.path.exists(sysvals.ftracefile) == False): doError('%s does not exist' % sysvals.ftracefile) - - sysvals.setupAllKprobes() + if not live: + sysvals.setupAllKprobes() tracewatch = [] if sysvals.usekprobes: tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', @@ -2458,7 +2681,7 @@ def parseTraceLog(): testdata = [] testrun = 0 data = 0 - tf = open(sysvals.ftracefile, 'r') + tf = sysvals.openlog(sysvals.ftracefile, 'r') phase = 'suspend_prepare' for line in tf: # remove any latent carriage returns @@ -2470,6 +2693,9 @@ def parseTraceLog(): elif re.match(tp.sysinfofmt, line): tp.sysinfo = line continue + elif re.match(tp.cmdlinefmt, line): + tp.cmdline = line + continue # firmware line: pull out any firmware data m = re.match(sysvals.firmwarefmt, line) if(m): @@ -2591,6 +2817,8 @@ def parseTraceLog(): phase = 'suspend_prepare' if(not isbegin): data.dmesg[phase]['end'] = t.time + if data.dmesg[phase]['start'] < 0: + data.dmesg[phase]['start'] = data.start continue # suspend start elif(re.match('dpm_suspend\[.*', t.name)): @@ -2604,6 +2832,8 @@ def parseTraceLog(): continue # suspend_noirq start elif(re.match('dpm_suspend_noirq\[.*', t.name)): + if data.phaseCollision('suspend_noirq', isbegin, line): + continue phase = 'suspend_noirq' data.setPhase(phase, t.time, isbegin) if(not isbegin): @@ -2636,6 +2866,8 @@ def parseTraceLog(): continue # resume_noirq start elif(re.match('dpm_resume_noirq\[.*', t.name)): + if data.phaseCollision('resume_noirq', isbegin, line): + continue phase = 'resume_noirq' data.setPhase(phase, t.time, isbegin) if(isbegin): @@ -2742,11 +2974,14 @@ def parseTraceLog(): key = (m_proc, pid) if(key not in testrun.ftemp): testrun.ftemp[key] = [] - testrun.ftemp[key].append(FTraceCallGraph(pid)) + testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals)) # when the call is finished, see which device matches it cg = testrun.ftemp[key][-1] - if(cg.addLine(t)): - testrun.ftemp[key].append(FTraceCallGraph(pid)) + res = cg.addLine(t) + if(res != 0): + testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals)) + if(res == -1): + testrun.ftemp[key][-1].addLine(t) tf.close() if sysvals.suspendmode == 'command': @@ -2812,28 +3047,31 @@ def parseTraceLog(): for key in test.ftemp: proc, pid = key for cg in test.ftemp[key]: - if len(cg.list) < 1 or cg.invalid: + if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0): continue if(not cg.postProcess()): id = 'task %s' % (pid) - vprint('Sanity check failed for '+\ + sysvals.vprint('Sanity check failed for '+\ id+', ignoring this callback') continue # match cg data to devices - if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, data): + devname = '' + if sysvals.suspendmode != 'command': + devname = cg.deviceMatch(pid, data) + if not devname: sortkey = '%f%f%d' % (cg.start, cg.end, pid) sortlist[sortkey] = cg + elif len(cg.list) > 1000000: + print 'WARNING: the callgraph for %s is massive (%d lines)' %\ + (devname, len(cg.list)) # create blocks for orphan cg data for sortkey in sorted(sortlist): cg = sortlist[sortkey] name = cg.name if sysvals.isCallgraphFunc(name): - vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name)) + sysvals.vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name)) cg.newActionFromFunction(data) - if sysvals.suspendmode == 'command': - for data in testdata: - data.printDetails() return testdata # fill in any missing phases @@ -2841,7 +3079,7 @@ def parseTraceLog(): lp = data.phases[0] for p in data.phases: if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): - vprint('WARNING: phase "%s" is missing!' % p) + sysvals.vprint('WARNING: phase "%s" is missing!' % p) if(data.dmesg[p]['start'] < 0): data.dmesg[p]['start'] = data.dmesg[lp]['end'] if(p == 'resume_machine'): @@ -2859,7 +3097,6 @@ def parseTraceLog(): data.fixupInitcallsThatDidntReturn() if sysvals.usedevsrc: data.optimizeDevSrc() - data.printDetails() # x2: merge any overlapping devices between test runs if sysvals.usedevsrc and len(testdata) > 1: @@ -2878,19 +3115,18 @@ def parseTraceLog(): # The dmesg filename is taken from sysvals # Output: # An array of empty Data objects with only their dmesgtext attributes set -def loadKernelLog(justtext=False): - vprint('Analyzing the dmesg data...') +def loadKernelLog(): + sysvals.vprint('Analyzing the dmesg data (%s)...' % \ + os.path.basename(sysvals.dmesgfile)) if(os.path.exists(sysvals.dmesgfile) == False): doError('%s does not exist' % sysvals.dmesgfile) - if justtext: - dmesgtext = [] # there can be multiple test runs in a single file tp = TestProps() tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown') testruns = [] data = 0 - lf = open(sysvals.dmesgfile, 'r') + lf = sysvals.openlog(sysvals.dmesgfile, 'r') for line in lf: line = line.replace('\r\n', '') idx = line.find('[') @@ -2903,6 +3139,9 @@ def loadKernelLog(justtext=False): elif re.match(tp.sysinfofmt, line): tp.sysinfo = line continue + elif re.match(tp.cmdlinefmt, line): + tp.cmdline = line + continue m = re.match(sysvals.firmwarefmt, line) if(m): tp.fwdata.append((int(m.group('s')), int(m.group('r')))) @@ -2911,9 +3150,6 @@ def loadKernelLog(justtext=False): if(not m): continue msg = m.group("msg") - if justtext: - dmesgtext.append(line) - continue if(re.match('PM: Syncing filesystems.*', msg)): if(data): testruns.append(data) @@ -2934,8 +3170,6 @@ def loadKernelLog(justtext=False): data.dmesgtext.append(line) lf.close() - if justtext: - return dmesgtext if data: testruns.append(data) if len(testruns) < 1: @@ -2975,7 +3209,7 @@ def parseKernelLog(data): phase = 'suspend_runtime' if(data.fwValid): - vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \ + sysvals.vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \ (data.fwSuspend, data.fwResume)) # dmesg phase match table @@ -3201,7 +3435,6 @@ def parseKernelLog(data): for event in actions[name]: data.newActionGlobal(name, event['begin'], event['end']) - data.printDetails() if(len(sysvals.devicefilter) > 0): data.deviceFilter(sysvals.devicefilter) data.fixupInitcallsThatDidntReturn() @@ -3230,9 +3463,9 @@ def callgraphHTML(sv, hf, num, cg, title, color, devid): else: fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>' flen = fmt % (line.length*1000, line.time) - if(line.freturn and line.fcall): + if line.isLeaf(): hf.write(html_func_leaf.format(line.name, flen)) - elif(line.freturn): + elif line.freturn: hf.write(html_func_end) else: hf.write(html_func_start.format(num, line.name, flen)) @@ -3249,7 +3482,7 @@ def addCallgraphs(sv, hf, data): continue list = data.dmesg[p]['list'] for devname in data.sortedDevices(p): - if len(sv.devicefilter) > 0 and devname not in sv.devicefilter: + if len(sv.cgfilter) > 0 and devname not in sv.cgfilter: continue dev = list[devname] color = 'white' @@ -3270,7 +3503,6 @@ def addCallgraphs(sv, hf, data): for cg in dev['ftraces']: num = callgraphHTML(sv, hf, num, cg, name+' → '+cg.name, color, dev['id']) - hf.write('\n\n </section>\n') # Function: createHTMLSummarySimple @@ -3311,7 +3543,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): sTimeAvg = rTimeAvg = 0.0 mode = '' num = 0 - for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'])): + for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])): if mode != data['mode']: # test average line if(num > 0): @@ -3387,7 +3619,7 @@ def createHTML(testruns): data.normalizeTime(testruns[-1].tSuspended) # html function templates - html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR→</div>\n' + html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}→</div>\n' html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n' html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n' html_timetotal = '<table class="time1">\n<tr>'\ @@ -3416,20 +3648,17 @@ def createHTML(testruns): scaleH = 40 # device timeline - vprint('Creating Device Timeline...') - devtl = Timeline(30, scaleH) # write the test title and general info header - devtl.createHeader(sysvals) + devtl.createHeader(sysvals, testruns[0].stamp) # Generate the header for this timeline for data in testruns: tTotal = data.end - data.start sktime, rktime = data.getTimeValues() if(tTotal == 0): - print('ERROR: No timeline data') - sys.exit() + doError('No timeline data') if(data.tLow > 0): low_time = '%.0f'%(data.tLow*1000) if sysvals.suspendmode == 'command': @@ -3567,9 +3796,10 @@ def createHTML(testruns): data.dmesg[b]['color'], '') for e in data.errorinfo[dir]: # draw red lines for any kernel errors found - t, err = e + type, t, idx1, idx2 = e + id = '%d_%d' % (idx1, idx2) right = '%f' % (((mMax-t)*100.0)/mTotal) - devtl.html += html_error.format(right, err) + devtl.html += html_error.format(right, id, type) for b in sorted(phases[dir]): # draw the devices for this phase phaselist = data.dmesg[b]['list'] @@ -3663,14 +3893,7 @@ def createHTML(testruns): devtl.html += '</div>\n' hf = open(sysvals.htmlfile, 'w') - - # no header or css if its embedded - if(sysvals.embedded): - hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' % - (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \ - data.fwSuspend/1000000, data.fwResume/1000000)) - else: - addCSS(hf, sysvals, len(testruns), kerror) + addCSS(hf, sysvals, len(testruns), kerror) # write the device timeline hf.write(devtl.html) @@ -3701,7 +3924,7 @@ def createHTML(testruns): data = testruns[sysvals.cgtest] else: data = testruns[-1] - if(sysvals.usecallgraph and not sysvals.embedded): + if sysvals.usecallgraph: addCallgraphs(sysvals, hf, data) # add the test log as a hidden div @@ -3710,7 +3933,7 @@ def createHTML(testruns): # add the dmesg log as a hidden div if sysvals.dmesglog and sysvals.dmesgfile: hf.write('<div id="dmesglog" style="display:none;">\n') - lf = open(sysvals.dmesgfile, 'r') + lf = sysvals.openlog(sysvals.dmesgfile, 'r') for line in lf: line = line.replace('<', '<').replace('>', '>') hf.write(line) @@ -3719,28 +3942,15 @@ def createHTML(testruns): # add the ftrace log as a hidden div if sysvals.ftracelog and sysvals.ftracefile: hf.write('<div id="ftracelog" style="display:none;">\n') - lf = open(sysvals.ftracefile, 'r') + lf = sysvals.openlog(sysvals.ftracefile, 'r') for line in lf: hf.write(line) lf.close() hf.write('</div>\n') - if(not sysvals.embedded): - # write the footer and close - addScriptCode(hf, testruns) - hf.write('</body>\n</html>\n') - else: - # embedded out will be loaded in a page, skip the js - t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000 - tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000 - # add js code in a div entry for later evaluation - detail = 'var bounds = [%f,%f];\n' % (t0, tMax) - detail += 'var devtable = [\n' - for data in testruns: - topo = data.deviceTopology() - detail += '\t"%s",\n' % (topo) - detail += '];\n' - hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n') + # write the footer and close + addScriptCode(hf, testruns) + hf.write('</body>\n</html>\n') hf.close() return True @@ -4149,9 +4359,25 @@ def addScriptCode(hf, testruns): ' win.document.write(html+dt);\n'\ ' }\n'\ ' function errWindow() {\n'\ - ' var text = this.id;\n'\ + ' var range = this.id.split("_");\n'\ + ' var idx1 = parseInt(range[0]);\n'\ + ' var idx2 = parseInt(range[1]);\n'\ ' var win = window.open();\n'\ - ' win.document.write("<pre>"+text+"</pre>");\n'\ + ' var log = document.getElementById("dmesglog");\n'\ + ' var title = "<title>dmesg log</title>";\n'\ + ' var text = log.innerHTML.split("\\n");\n'\ + ' var html = "";\n'\ + ' for(var i = 0; i < text.length; i++) {\n'\ + ' if(i == idx1) {\n'\ + ' html += "<e id=target>"+text[i]+"</e>\\n";\n'\ + ' } else if(i > idx1 && i <= idx2) {\n'\ + ' html += "<e>"+text[i]+"</e>\\n";\n'\ + ' } else {\n'\ + ' html += text[i]+"\\n";\n'\ + ' }\n'\ + ' }\n'\ + ' win.document.write("<style>e{color:red}</style>"+title+"<pre>"+html+"</pre>");\n'\ + ' win.location.hash = "#target";\n'\ ' win.document.close();\n'\ ' }\n'\ ' function logWindow(e) {\n'\ @@ -4219,6 +4445,30 @@ def addScriptCode(hf, testruns): '</script>\n' hf.write(script_code); +def setRuntimeSuspend(before=True): + global sysvals + sv = sysvals + if sv.rs == 0: + return + if before: + # runtime suspend disable or enable + if sv.rs > 0: + sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled' + else: + sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled' + print('CONFIGURING RUNTIME SUSPEND...') + sv.rslist = deviceInfo(sv.rstgt) + for i in sv.rslist: + sv.setVal(sv.rsval, i) + print('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist))) + print('waiting 5 seconds...') + time.sleep(5) + else: + # runtime suspend re-enable or re-disable + for i in sv.rslist: + sv.setVal(sv.rstgt, i) + print('runtime suspend settings restored on %d devices' % len(sv.rslist)) + # Function: executeSuspend # Description: # Execute system suspend through the sysfs interface, then copy the output @@ -4227,6 +4477,19 @@ def executeSuspend(): pm = ProcessMonitor() tp = sysvals.tpath fwdata = [] + # run these commands to prepare the system for suspend + if sysvals.display: + if sysvals.display > 0: + print('TURN DISPLAY ON') + call('xset -d :0.0 dpms force suspend', shell=True) + call('xset -d :0.0 dpms force on', shell=True) + else: + print('TURN DISPLAY OFF') + call('xset -d :0.0 dpms force suspend', shell=True) + time.sleep(1) + if sysvals.sync: + print('SYNCING FILESYSTEMS') + call('sync', shell=True) # mark the start point in the kernel ring buffer just as we start sysvals.initdmesg() # start ftrace @@ -4298,47 +4561,22 @@ def executeSuspend(): pm.stop() sysvals.fsetVal('0', 'tracing_on') print('CAPTURING TRACE') - sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata) - call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True) + op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata) + fp = open(tp+'trace', 'r') + for line in fp: + op.write(line) + op.close() sysvals.fsetVal('', 'trace') devProps() # grab a copy of the dmesg output print('CAPTURING DMESG') - sysvals.writeDatafileHeader(sysvals.dmesgfile, fwdata) - sysvals.getdmesg() + sysvals.getdmesg(fwdata) -# Function: setUSBDevicesAuto -# Description: -# Set the autosuspend control parameter of all USB devices to auto -# This can be dangerous, so use at your own risk, most devices are set -# to always-on since the kernel cant determine if the device can -# properly autosuspend -def setUSBDevicesAuto(): - sysvals.rootCheck(True) - for dirname, dirnames, filenames in os.walk('/sys/devices'): - if(re.match('.*/usb[0-9]*.*', dirname) and - 'idVendor' in filenames and 'idProduct' in filenames): - call('echo auto > %s/power/control' % dirname, shell=True) - name = dirname.split('/')[-1] - desc = Popen(['cat', '%s/product' % dirname], - stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') - ctrl = Popen(['cat', '%s/power/control' % dirname], - stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') - print('control is %s for %6s: %s' % (ctrl, name, desc)) - -# Function: yesno -# Description: -# Print out an equivalent Y or N for a set of known parameter values -# Output: -# 'Y', 'N', or ' ' if the value is unknown -def yesno(val): - yesvals = ['auto', 'enabled', 'active', '1'] - novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported'] - if val in yesvals: - return 'Y' - elif val in novals: - return 'N' - return ' ' +def readFile(file): + if os.path.islink(file): + return os.readlink(file).split('/')[-1] + else: + return sysvals.getVal(file).strip() # Function: ms2nice # Description: @@ -4346,69 +4584,81 @@ def yesno(val): # Output: # The time string, e.g. "1901m16s" def ms2nice(val): - ms = 0 - try: - ms = int(val) - except: - return 0.0 - m = ms / 60000 - s = (ms / 1000) - (m * 60) - return '%3dm%2ds' % (m, s) + val = int(val) + h = val / 3600000 + m = (val / 60000) % 60 + s = (val / 1000) % 60 + if h > 0: + return '%d:%02d:%02d' % (h, m, s) + if m > 0: + return '%02d:%02d' % (m, s) + return '%ds' % s -# Function: detectUSB +def yesno(val): + list = {'enabled':'A', 'disabled':'S', 'auto':'E', 'on':'D', + 'active':'A', 'suspended':'S', 'suspending':'S'} + if val not in list: + return ' ' + return list[val] + +# Function: deviceInfo # Description: # Detect all the USB hosts and devices currently connected and add # a list of USB device names to sysvals for better timeline readability -def detectUSB(): - field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} - power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'', - 'control':'', 'persist':'', 'runtime_enabled':'', - 'runtime_status':'', 'runtime_usage':'', - 'runtime_active_time':'', - 'runtime_suspended_time':'', - 'active_duration':'', - 'connected_duration':''} - - print('LEGEND') - print('---------------------------------------------------------------------------------------------') - print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)') - print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)') - print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)') - print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)') - print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)') - print(' U = runtime usage count') - print('---------------------------------------------------------------------------------------------') - print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT') - print('---------------------------------------------------------------------------------------------') - +def deviceInfo(output=''): + if not output: + print('LEGEND') + print('---------------------------------------------------------------------------------------------') + print(' A = async/sync PM queue (A/S) C = runtime active children') + print(' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)') + print(' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)') + print(' U = runtime usage count') + print('---------------------------------------------------------------------------------------------') + print('DEVICE NAME A R S U C rACTIVE rSUSPEND') + print('---------------------------------------------------------------------------------------------') + + res = [] + tgtval = 'runtime_status' + lines = dict() for dirname, dirnames, filenames in os.walk('/sys/devices'): - if(re.match('.*/usb[0-9]*.*', dirname) and - 'idVendor' in filenames and 'idProduct' in filenames): - for i in field: - field[i] = Popen(['cat', '%s/%s' % (dirname, i)], - stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') - name = dirname.split('/')[-1] - for i in power: - power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)], - stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') - if(re.match('usb[0-9]*', name)): - first = '%-8s' % name - else: - first = '%8s' % name - print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \ - (first, field['idVendor'], field['idProduct'], \ - field['product'][0:20], field['speed'], \ - yesno(power['async']), \ - yesno(power['control']), \ - yesno(power['persist']), \ - yesno(power['runtime_enabled']), \ - yesno(power['runtime_status']), \ - power['runtime_usage'], \ - power['autosuspend'], \ - ms2nice(power['runtime_active_time']), \ - ms2nice(power['runtime_suspended_time']), \ - ms2nice(power['active_duration']), \ - ms2nice(power['connected_duration']))) + if(not re.match('.*/power', dirname) or + 'control' not in filenames or + tgtval not in filenames): + continue + name = '' + dirname = dirname[:-6] + device = dirname.split('/')[-1] + power = dict() + power[tgtval] = readFile('%s/power/%s' % (dirname, tgtval)) + # only list devices which support runtime suspend + if power[tgtval] not in ['active', 'suspended', 'suspending']: + continue + for i in ['product', 'driver', 'subsystem']: + file = '%s/%s' % (dirname, i) + if os.path.exists(file): + name = readFile(file) + break + for i in ['async', 'control', 'runtime_status', 'runtime_usage', + 'runtime_active_kids', 'runtime_active_time', + 'runtime_suspended_time']: + if i in filenames: + power[i] = readFile('%s/power/%s' % (dirname, i)) + if output: + if power['control'] == output: + res.append('%s/power/control' % dirname) + continue + lines[dirname] = '%-26s %-26s %1s %1s %1s %1s %1s %10s %10s' % \ + (device[:26], name[:26], + yesno(power['async']), \ + yesno(power['control']), \ + yesno(power['runtime_status']), \ + power['runtime_usage'], \ + power['runtime_active_kids'], \ + ms2nice(power['runtime_active_time']), \ + ms2nice(power['runtime_suspended_time'])) + for i in sorted(lines): + print lines[i] + return res # Function: devProps # Description: @@ -4444,7 +4694,7 @@ def devProps(data=0): msghead = 'Additional data added by AnalyzeSuspend' alreadystamped = False tp = TestProps() - tf = open(sysvals.ftracefile, 'r') + tf = sysvals.openlog(sysvals.ftracefile, 'r') for line in tf: if msghead in line: alreadystamped = True @@ -4469,7 +4719,7 @@ def devProps(data=0): if not alreadystamped and sysvals.suspendmode == 'command': out = '#\n# '+msghead+'\n# Device Properties: ' out += 'testcommandstring,%s,0;' % (sysvals.testcommand) - with open(sysvals.ftracefile, 'a') as fp: + with sysvals.openlog(sysvals.ftracefile, 'a') as fp: fp.write(out+'\n') sysvals.devprops = props return @@ -4526,7 +4776,7 @@ def devProps(data=0): out = '#\n# '+msghead+'\n# Device Properties: ' for dev in sorted(props): out += props[dev].out(dev) - with open(sysvals.ftracefile, 'a') as fp: + with sysvals.openlog(sysvals.ftracefile, 'a') as fp: fp.write(out+'\n') sysvals.devprops = props @@ -4869,20 +5119,12 @@ def statusCheck(probecheck=False): # what data source are we using res = 'DMESG' if(ftgood): - sysvals.usetraceeventsonly = True - sysvals.usetraceevents = False + sysvals.usetraceevents = True for e in sysvals.traceevents: - check = False - if(os.path.exists(sysvals.epath+e)): - check = True - if(not check): - sysvals.usetraceeventsonly = False - if(e == 'suspend_resume' and check): - sysvals.usetraceevents = True - if(sysvals.usetraceevents and sysvals.usetraceeventsonly): + if not os.path.exists(sysvals.epath+e): + sysvals.usetraceevents = False + if(sysvals.usetraceevents): res = 'FTRACE (all trace events found)' - elif(sysvals.usetraceevents): - res = 'DMESG and FTRACE (suspend_resume trace event found)' print(' timeline data source: %s' % res) # check if rtcwake @@ -4917,6 +5159,7 @@ def doError(msg, help=False): if(help == True): printHelp() print('ERROR: %s\n') % msg + sysvals.outputResult({'error':msg}) sys.exit() # Function: getArgInt @@ -4957,22 +5200,36 @@ def getArgFloat(name, args, min, max, main=True): doError(name+': value should be between %f and %f' % (min, max), True) return val -def processData(): +def processData(live=False): print('PROCESSING DATA') - if(sysvals.usetraceeventsonly): - testruns = parseTraceLog() + if(sysvals.usetraceevents): + testruns = parseTraceLog(live) if sysvals.dmesgfile: - dmesgtext = loadKernelLog(True) for data in testruns: - data.extractErrorInfo(dmesgtext) + data.extractErrorInfo() else: testruns = loadKernelLog() for data in testruns: parseKernelLog(data) if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)): appendIncompleteTraceLog(testruns) + sysvals.vprint('Command:\n %s' % sysvals.cmdline) + for data in testruns: + data.printDetails() + if sysvals.cgdump: + for data in testruns: + data.debugPrint() + sys.exit() + + sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) createHTML(testruns) - return testruns + print('DONE') + data = testruns[0] + stamp = data.stamp + stamp['suspend'], stamp['resume'] = data.getTimeValues() + if data.fwValid: + stamp['fwsuspend'], stamp['fwresume'] = data.fwSuspend, data.fwResume + return (testruns, stamp) # Function: rerunTest # Description: @@ -4980,37 +5237,36 @@ def processData(): def rerunTest(): if sysvals.ftracefile: doesTraceLogHaveTraceEvents() - if not sysvals.dmesgfile and not sysvals.usetraceeventsonly: + if not sysvals.dmesgfile and not sysvals.usetraceevents: doError('recreating this html output requires a dmesg file') sysvals.setOutputFile() - vprint('Output file: %s' % sysvals.htmlfile) if os.path.exists(sysvals.htmlfile): if not os.path.isfile(sysvals.htmlfile): doError('a directory already exists with this name: %s' % sysvals.htmlfile) elif not os.access(sysvals.htmlfile, os.W_OK): doError('missing permission to write to %s' % sysvals.htmlfile) - return processData() + testruns, stamp = processData(False) + return stamp # Function: runTest # Description: # execute a suspend/resume, gather the logs, and generate the output -def runTest(): +def runTest(n=0): # prepare for the test sysvals.initFtrace() sysvals.initTestOutput('suspend') - vprint('Output files:\n\t%s\n\t%s\n\t%s' % \ - (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile)) # execute the test executeSuspend() sysvals.cleanupFtrace() - processData() - - # if running as root, change output dir owner to sudo_user - if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \ - 'SUDO_USER' in os.environ: - cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' - call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True) + if sysvals.skiphtml: + sysvals.sudouser(sysvals.testdir) + return + testruns, stamp = processData(True) + for data in testruns: + del data + sysvals.sudouser(sysvals.testdir) + sysvals.outputResult(stamp, n) def find_in_html(html, strs, div=False): for str in strs: @@ -5072,10 +5328,12 @@ def runSummary(subdir, local=True): # Function: checkArgBool # Description: # check if a boolean string value is true or false -def checkArgBool(value): - yes = ['1', 'true', 'yes', 'on'] - if value.lower() in yes: +def checkArgBool(name, value): + if value in switchvalues: + if value in switchoff: + return False return True + doError('invalid boolean --> (%s: %s), use "true/false" or "1/0"' % (name, value), True) return False # Function: configFromFile @@ -5091,60 +5349,116 @@ def configFromFile(file): if 'Settings' in sections: for opt in Config.options('Settings'): value = Config.get('Settings', opt).lower() - if(opt.lower() == 'verbose'): - sysvals.verbose = checkArgBool(value) - elif(opt.lower() == 'addlogs'): - sysvals.dmesglog = sysvals.ftracelog = checkArgBool(value) - elif(opt.lower() == 'dev'): - sysvals.usedevsrc = checkArgBool(value) - elif(opt.lower() == 'proc'): - sysvals.useprocmon = checkArgBool(value) - elif(opt.lower() == 'x2'): - if checkArgBool(value): + option = opt.lower() + if(option == 'verbose'): + sysvals.verbose = checkArgBool(option, value) + elif(option == 'addlogs'): + sysvals.dmesglog = sysvals.ftracelog = checkArgBool(option, value) + elif(option == 'dev'): + sysvals.usedevsrc = checkArgBool(option, value) + elif(option == 'proc'): + sysvals.useprocmon = checkArgBool(option, value) + elif(option == 'x2'): + if checkArgBool(option, value): sysvals.execcount = 2 - elif(opt.lower() == 'callgraph'): - sysvals.usecallgraph = checkArgBool(value) - elif(opt.lower() == 'override-timeline-functions'): - overridekprobes = checkArgBool(value) - elif(opt.lower() == 'override-dev-timeline-functions'): - overridedevkprobes = checkArgBool(value) - elif(opt.lower() == 'devicefilter'): + elif(option == 'callgraph'): + sysvals.usecallgraph = checkArgBool(option, value) + elif(option == 'override-timeline-functions'): + overridekprobes = checkArgBool(option, value) + elif(option == 'override-dev-timeline-functions'): + overridedevkprobes = checkArgBool(option, value) + elif(option == 'skiphtml'): + sysvals.skiphtml = checkArgBool(option, value) + elif(option == 'sync'): + sysvals.sync = checkArgBool(option, value) + elif(option == 'rs' or option == 'runtimesuspend'): + if value in switchvalues: + if value in switchoff: + sysvals.rs = -1 + else: + sysvals.rs = 1 + else: + doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True) + elif(option == 'display'): + if value in switchvalues: + if value in switchoff: + sysvals.display = -1 + else: + sysvals.display = 1 + else: + doError('invalid value --> (%s: %s), use "on/off"' % (option, value), True) + elif(option == 'gzip'): + sysvals.gzip = checkArgBool(option, value) + elif(option == 'cgfilter'): + sysvals.setCallgraphFilter(value) + elif(option == 'cgskip'): + if value in switchoff: + sysvals.cgskip = '' + else: + sysvals.cgskip = sysvals.configFile(val) + if(not sysvals.cgskip): + doError('%s does not exist' % sysvals.cgskip) + elif(option == 'cgtest'): + sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False) + elif(option == 'cgphase'): + d = Data(0) + if value not in d.phases: + doError('invalid phase --> (%s: %s), valid phases are %s'\ + % (option, value, d.phases), True) + sysvals.cgphase = value + elif(option == 'fadd'): + file = sysvals.configFile(value) + if(not file): + doError('%s does not exist' % value) + sysvals.addFtraceFilterFunctions(file) + elif(option == 'result'): + sysvals.result = value + elif(option == 'multi'): + nums = value.split() + if len(nums) != 2: + doError('multi requires 2 integers (exec_count and delay)', True) + sysvals.multitest['run'] = True + sysvals.multitest['count'] = getArgInt('multi: n d (exec count)', nums[0], 2, 1000000, False) + sysvals.multitest['delay'] = getArgInt('multi: n d (delay between tests)', nums[1], 0, 3600, False) + elif(option == 'devicefilter'): sysvals.setDeviceFilter(value) - elif(opt.lower() == 'expandcg'): - sysvals.cgexp = checkArgBool(value) - elif(opt.lower() == 'srgap'): - if checkArgBool(value): + elif(option == 'expandcg'): + sysvals.cgexp = checkArgBool(option, value) + elif(option == 'srgap'): + if checkArgBool(option, value): sysvals.srgap = 5 - elif(opt.lower() == 'mode'): + elif(option == 'mode'): sysvals.suspendmode = value - elif(opt.lower() == 'command'): + elif(option == 'command' or option == 'cmd'): sysvals.testcommand = value - elif(opt.lower() == 'x2delay'): - sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False) - elif(opt.lower() == 'predelay'): - sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False) - elif(opt.lower() == 'postdelay'): - sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False) - elif(opt.lower() == 'maxdepth'): - sysvals.max_graph_depth = getArgInt('-maxdepth', value, 0, 1000, False) - elif(opt.lower() == 'rtcwake'): - if value.lower() == 'off': + elif(option == 'x2delay'): + sysvals.x2delay = getArgInt('x2delay', value, 0, 60000, False) + elif(option == 'predelay'): + sysvals.predelay = getArgInt('predelay', value, 0, 60000, False) + elif(option == 'postdelay'): + sysvals.postdelay = getArgInt('postdelay', value, 0, 60000, False) + elif(option == 'maxdepth'): + sysvals.max_graph_depth = getArgInt('maxdepth', value, 0, 1000, False) + elif(option == 'rtcwake'): + if value in switchoff: sysvals.rtcwake = False else: sysvals.rtcwake = True - sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False) - elif(opt.lower() == 'timeprec'): - sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False)) - elif(opt.lower() == 'mindev'): - sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False) - elif(opt.lower() == 'callloop-maxgap'): - sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False) - elif(opt.lower() == 'callloop-maxlen'): - sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False) - elif(opt.lower() == 'mincg'): - sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False) - elif(opt.lower() == 'output-dir'): - sysvals.testdir = sysvals.setOutputFolder(value) + sysvals.rtcwaketime = getArgInt('rtcwake', value, 0, 3600, False) + elif(option == 'timeprec'): + sysvals.setPrecision(getArgInt('timeprec', value, 0, 6, False)) + elif(option == 'mindev'): + sysvals.mindevlen = getArgFloat('mindev', value, 0.0, 10000.0, False) + elif(option == 'callloop-maxgap'): + sysvals.callloopmaxgap = getArgFloat('callloop-maxgap', value, 0.0, 1.0, False) + elif(option == 'callloop-maxlen'): + sysvals.callloopmaxgap = getArgFloat('callloop-maxlen', value, 0.0, 1.0, False) + elif(option == 'mincg'): + sysvals.mincglen = getArgFloat('mincg', value, 0.0, 10000.0, False) + elif(option == 'bufsize'): + sysvals.bufsize = getArgInt('bufsize', value, 1, 1024*1024*8, False) + elif(option == 'output-dir'): + sysvals.outdir = sysvals.setOutputFolder(value) if sysvals.suspendmode == 'command' and not sysvals.testcommand: doError('No command supplied for mode "command"') @@ -5259,7 +5573,14 @@ def printHelp(): print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)') print(' -addlogs Add the dmesg and ftrace logs to the html output') print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)') + print(' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)') + print(' -result fn Export a results table to a text file for parsing.') + print(' [testprep]') + print(' -sync Sync the filesystems before starting the test') + print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test') + print(' -display on/off Turn the display on or off for the test') print(' [advanced]') + print(' -gzip Gzip the trace and dmesg logs to save space') print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"') print(' -proc Add usermode process info into the timeline (default: disabled)') print(' -dev Add kernel function calls and threads to the timeline (default: disabled)') @@ -5280,14 +5601,16 @@ def printHelp(): print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)') print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)') print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)') + print(' -cgfilter S Filter the callgraph output in the timeline') + print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)') + print(' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)') print('') print('Other commands:') print(' -modes List available suspend modes') print(' -status Test to see if the system is enabled to run this tool') print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') print(' -sysinfo Print out system info extracted from BIOS') - print(' -usbtopo Print out the current USB topology with power info') - print(' -usbauto Enable autosuspend for all connected USB devices') + print(' -devinfo Print out the pm settings of all devices which support runtime suspend') print(' -flist Print the list of functions currently being captured in ftrace') print(' -flistall Print all functions capable of being captured in ftrace') print(' -summary directory Create a summary of all test in this dir') @@ -5301,9 +5624,9 @@ def printHelp(): # exec start (skipped if script is loaded as library) if __name__ == '__main__': cmd = '' - outdir = '' - multitest = {'run': False, 'count': 0, 'delay': 0} - simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status'] + simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status'] + if '-f' in sys.argv: + sysvals.cgskip = sysvals.configFile('cgskip.txt') # loop through the command line arguments args = iter(sys.argv[1:]) for arg in args: @@ -5333,6 +5656,10 @@ if __name__ == '__main__': sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000) elif(arg == '-f'): sysvals.usecallgraph = True + elif(arg == '-skiphtml'): + sysvals.skiphtml = True + elif(arg == '-cgdump'): + sysvals.cgdump = True elif(arg == '-addlogs'): sysvals.dmesglog = sysvals.ftracelog = True elif(arg == '-verbose'): @@ -5341,6 +5668,34 @@ if __name__ == '__main__': sysvals.useprocmon = True elif(arg == '-dev'): sysvals.usedevsrc = True + elif(arg == '-sync'): + sysvals.sync = True + elif(arg == '-gzip'): + sysvals.gzip = True + elif(arg == '-rs'): + try: + val = args.next() + except: + doError('-rs requires "enable" or "disable"', True) + if val.lower() in switchvalues: + if val.lower() in switchoff: + sysvals.rs = -1 + else: + sysvals.rs = 1 + else: + doError('invalid option: %s, use "enable/disable" or "on/off"' % val, True) + elif(arg == '-display'): + try: + val = args.next() + except: + doError('-display requires "on" or "off"', True) + if val.lower() in switchvalues: + if val.lower() in switchoff: + sysvals.display = -1 + else: + sysvals.display = 1 + else: + doError('invalid option: %s, use "on/off"' % val, True) elif(arg == '-maxdepth'): sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000) elif(arg == '-rtcwake'): @@ -5348,7 +5703,7 @@ if __name__ == '__main__': val = args.next() except: doError('No rtcwake time supplied', True) - if val.lower() == 'off': + if val.lower() in switchoff: sysvals.rtcwake = False else: sysvals.rtcwake = True @@ -5359,6 +5714,8 @@ if __name__ == '__main__': sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0) elif(arg == '-mincg'): sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0) + elif(arg == '-bufsize'): + sysvals.bufsize = getArgInt('-bufsize', args, 1, 1024*1024*8) elif(arg == '-cgtest'): sysvals.cgtest = getArgInt('-cgtest', args, 0, 1) elif(arg == '-cgphase'): @@ -5368,8 +5725,26 @@ if __name__ == '__main__': doError('No phase name supplied', True) d = Data(0) if val not in d.phases: - doError('Invalid phase, valid phaess are %s' % d.phases, True) + doError('invalid phase --> (%s: %s), valid phases are %s'\ + % (arg, val, d.phases), True) sysvals.cgphase = val + elif(arg == '-cgfilter'): + try: + val = args.next() + except: + doError('No callgraph functions supplied', True) + sysvals.setCallgraphFilter(val) + elif(arg == '-cgskip'): + try: + val = args.next() + except: + doError('No file supplied', True) + if val.lower() in switchoff: + sysvals.cgskip = '' + else: + sysvals.cgskip = sysvals.configFile(val) + if(not sysvals.cgskip): + doError('%s does not exist' % sysvals.cgskip) elif(arg == '-callloop-maxgap'): sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0) elif(arg == '-callloop-maxlen'): @@ -5386,31 +5761,33 @@ if __name__ == '__main__': elif(arg == '-srgap'): sysvals.srgap = 5 elif(arg == '-multi'): - multitest['run'] = True - multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000) - multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600) + sysvals.multitest['run'] = True + sysvals.multitest['count'] = getArgInt('-multi n d (exec count)', args, 2, 1000000) + sysvals.multitest['delay'] = getArgInt('-multi n d (delay between tests)', args, 0, 3600) elif(arg == '-o'): try: val = args.next() except: doError('No subdirectory name supplied', True) - outdir = sysvals.setOutputFolder(val) + sysvals.outdir = sysvals.setOutputFolder(val) elif(arg == '-config'): try: val = args.next() except: doError('No text file supplied', True) - if(os.path.exists(val) == False): + file = sysvals.configFile(val) + if(not file): doError('%s does not exist' % val) - configFromFile(val) + configFromFile(file) elif(arg == '-fadd'): try: val = args.next() except: doError('No text file supplied', True) - if(os.path.exists(val) == False): + file = sysvals.configFile(val) + if(not file): doError('%s does not exist' % val) - sysvals.addFtraceFilterFunctions(val) + sysvals.addFtraceFilterFunctions(file) elif(arg == '-dmesg'): try: val = args.next() @@ -5435,7 +5812,7 @@ if __name__ == '__main__': except: doError('No directory supplied', True) cmd = 'summary' - outdir = val + sysvals.outdir = val sysvals.notestrun = True if(os.path.isdir(val) == False): doError('%s is not accesible' % val) @@ -5445,6 +5822,12 @@ if __name__ == '__main__': except: doError('No devnames supplied', True) sysvals.setDeviceFilter(val) + elif(arg == '-result'): + try: + val = args.next() + except: + doError('No result file supplied', True) + sysvals.result = val else: doError('Invalid argument: '+arg, True) @@ -5454,42 +5837,48 @@ if __name__ == '__main__': if(sysvals.usecallgraph and sysvals.useprocmon): doError('-proc is not compatible with -f') + if sysvals.usecallgraph and sysvals.cgskip: + sysvals.vprint('Using cgskip file: %s' % sysvals.cgskip) + sysvals.setCallgraphBlacklist(sysvals.cgskip) + # callgraph size cannot exceed device size if sysvals.mincglen < sysvals.mindevlen: sysvals.mincglen = sysvals.mindevlen - # just run a utility command and exit + # remove existing buffers before calculating memory + if(sysvals.usecallgraph or sysvals.usedevsrc): + sysvals.fsetVal('16', 'buffer_size_kb') sysvals.cpuInfo() + + # just run a utility command and exit if(cmd != ''): if(cmd == 'status'): statusCheck(True) elif(cmd == 'fpdt'): getFPDT(True) elif(cmd == 'sysinfo'): - sysvals.printSystemInfo() - elif(cmd == 'usbtopo'): - detectUSB() + sysvals.printSystemInfo(True) + elif(cmd == 'devinfo'): + deviceInfo() elif(cmd == 'modes'): print getModes() elif(cmd == 'flist'): sysvals.getFtraceFilterFunctions(True) elif(cmd == 'flistall'): sysvals.getFtraceFilterFunctions(False) - elif(cmd == 'usbauto'): - setUSBDevicesAuto() elif(cmd == 'summary'): - runSummary(outdir, True) + runSummary(sysvals.outdir, True) sys.exit() # if instructed, re-analyze existing data files if(sysvals.notestrun): - rerunTest() + stamp = rerunTest() + sysvals.outputResult(stamp) sys.exit() # verify that we can run a test if(not statusCheck()): - print('Check FAILED, aborting the test run!') - sys.exit() + doError('Check FAILED, aborting the test run!') # extract mem modes and convert mode = sysvals.suspendmode @@ -5509,25 +5898,35 @@ if __name__ == '__main__': sysvals.systemInfo(dmidecode(sysvals.mempath)) - if multitest['run']: + setRuntimeSuspend(True) + if sysvals.display: + call('xset -d :0.0 dpms 0 0 0', shell=True) + call('xset -d :0.0 s off', shell=True) + if sysvals.multitest['run']: # run multiple tests in a separate subdirectory - if not outdir: - s = 'suspend-x%d' % multitest['count'] - outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S') - if not os.path.isdir(outdir): - os.mkdir(outdir) - for i in range(multitest['count']): + if not sysvals.outdir: + s = 'suspend-x%d' % sysvals.multitest['count'] + sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S') + if not os.path.isdir(sysvals.outdir): + os.mkdir(sysvals.outdir) + for i in range(sysvals.multitest['count']): if(i != 0): - print('Waiting %d seconds...' % (multitest['delay'])) - time.sleep(multitest['delay']) - print('TEST (%d/%d) START' % (i+1, multitest['count'])) + print('Waiting %d seconds...' % (sysvals.multitest['delay'])) + time.sleep(sysvals.multitest['delay']) + print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count'])) fmt = 'suspend-%y%m%d-%H%M%S' - sysvals.testdir = os.path.join(outdir, datetime.now().strftime(fmt)) - runTest() - print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) - runSummary(outdir, False) + sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) + runTest(i+1) + print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count'])) + sysvals.logmsg = '' + if not sysvals.skiphtml: + runSummary(sysvals.outdir, False) + sysvals.sudouser(sysvals.outdir) else: - if outdir: - sysvals.testdir = outdir + if sysvals.outdir: + sysvals.testdir = sysvals.outdir # run the test in the current directory runTest() + if sysvals.display: + call('xset -d :0.0 s reset', shell=True) + setRuntimeSuspend(False) |