diff options
Diffstat (limited to 'tools')
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) |