diff options
Diffstat (limited to 'tools')
-rwxr-xr-x | tools/power/pm-graph/bootgraph.py | 125 | ||||
-rw-r--r-- | tools/power/pm-graph/config/cgskip.txt | 1 | ||||
-rw-r--r-- | tools/power/pm-graph/config/custom-timeline-functions.cfg | 4 | ||||
-rwxr-xr-x | tools/power/pm-graph/sleepgraph.py | 532 |
4 files changed, 364 insertions, 298 deletions
diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py index 8ee626c0f6a5..6dae57041537 100755 --- a/tools/power/pm-graph/bootgraph.py +++ b/tools/power/pm-graph/bootgraph.py @@ -34,6 +34,10 @@ from datetime import datetime, timedelta from subprocess import call, Popen, PIPE import sleepgraph as aslib +def pprint(msg): + print(msg) + sys.stdout.flush() + # ----------------- CLASSES -------------------- # Class: SystemValues @@ -157,11 +161,11 @@ class SystemValues(aslib.SystemValues): return cmdline def manualRebootRequired(self): cmdline = self.kernelParams() - print 'To generate a new timeline manually, follow these steps:\n' - print '1. Add the CMDLINE string to your kernel command line.' - print '2. Reboot the system.' - 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 + pprint('To generate a new timeline manually, follow these steps:\n\n'\ + '1. Add the CMDLINE string to your kernel command line.\n'\ + '2. Reboot the system.\n'\ + '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\ + 'CMDLINE="%s"' % cmdline) sys.exit() def blGrub(self): blcmd = '' @@ -431,7 +435,7 @@ def parseTraceLog(data): 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)) + pprint('Sanity check failed for %s-%d' % (proc, pid)) continue # match cg data to devices devname = data.deviceMatch(pid, cg) @@ -442,8 +446,8 @@ def parseTraceLog(data): 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)) + pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\ + (devname, len(cg.list))) # Function: retrieveLogs # Description: @@ -528,7 +532,7 @@ def createBootGraph(data): tMax = data.end tTotal = tMax - t0 if(tTotal == 0): - print('ERROR: No timeline data') + pprint('ERROR: No timeline data') return False user_mode = '%.0f'%(data.tUserMode*1000) last_init = '%.0f'%(tTotal*1000) @@ -734,7 +738,7 @@ def updateCron(restore=False): op.close() res = call([cmd, cronfile]) except Exception, e: - print 'Exception: %s' % str(e) + pprint('Exception: %s' % str(e)) shutil.move(backfile, cronfile) res = -1 if res != 0: @@ -750,7 +754,7 @@ def updateGrub(restore=False): call(sysvals.blexec, stderr=PIPE, stdout=PIPE, env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'}) except Exception, e: - print 'Exception: %s\n' % str(e) + pprint('Exception: %s\n' % str(e)) return # extract the option and create a grub config without it sysvals.rootUser(True) @@ -797,7 +801,7 @@ def updateGrub(restore=False): res = call(sysvals.blexec) os.remove(grubfile) except Exception, e: - print 'Exception: %s' % str(e) + pprint('Exception: %s' % str(e)) res = -1 # cleanup shutil.move(tempfile, grubfile) @@ -821,7 +825,7 @@ def updateKernelParams(restore=False): def doError(msg, help=False): if help == True: printHelp() - print 'ERROR: %s\n' % msg + pprint('ERROR: %s\n' % msg) sysvals.outputResult({'error':msg}) sys.exit() @@ -829,52 +833,51 @@ def doError(msg, help=False): # Description: # print out the help text def printHelp(): - print('') - print('%s v%s' % (sysvals.title, sysvals.version)) - print('Usage: bootgraph <options> <command>') - print('') - print('Description:') - print(' This tool reads in a dmesg log of linux kernel boot and') - print(' creates an html representation of the boot timeline up to') - print(' the start of the init process.') - print('') - print(' If no specific command is given the tool reads the current dmesg') - print(' and/or ftrace log and creates a timeline') - print('') - print(' Generates output files in subdirectory: boot-yymmdd-HHMMSS') - print(' HTML output: <hostname>_boot.html') - print(' raw dmesg output: <hostname>_boot_dmesg.txt') - print(' raw ftrace output: <hostname>_boot_ftrace.txt') - print('') - 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(' -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)') - print('') - print('Other commands:') - print(' -flistall Print all functions capable of being captured in ftrace') - print(' -sysinfo Print out system info extracted from BIOS') - print(' [redo]') - print(' -dmesg file Create HTML output using dmesg input (used with -ftrace)') - print(' -ftrace file Create HTML output using ftrace input (used with -dmesg)') - print('') + pprint('\n%s v%s\n'\ + 'Usage: bootgraph <options> <command>\n'\ + '\n'\ + 'Description:\n'\ + ' This tool reads in a dmesg log of linux kernel boot and\n'\ + ' creates an html representation of the boot timeline up to\n'\ + ' the start of the init process.\n'\ + '\n'\ + ' If no specific command is given the tool reads the current dmesg\n'\ + ' and/or ftrace log and creates a timeline\n'\ + '\n'\ + ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\ + ' HTML output: <hostname>_boot.html\n'\ + ' raw dmesg output: <hostname>_boot_dmesg.txt\n'\ + ' raw ftrace output: <hostname>_boot_ftrace.txt\n'\ + '\n'\ + 'Options:\n'\ + ' -h Print this help text\n'\ + ' -v Print the current tool version\n'\ + ' -verbose Print extra information during execution and analysis\n'\ + ' -addlogs Add the dmesg log to the html output\n'\ + ' -result fn Export a results table to a text file for parsing.\n'\ + ' -o name Overrides the output subdirectory name when running a new test\n'\ + ' default: boot-{date}-{time}\n'\ + ' [advanced]\n'\ + ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\ + ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\ + ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\ + ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\ + ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\ + ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\ + ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\ + ' -cgfilter S Filter the callgraph output in the timeline\n'\ + ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\ + ' -bl name Use the following boot loader for kernel params (default: grub)\n'\ + ' -reboot Reboot the machine automatically and generate a new timeline\n'\ + ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\ + '\n'\ + 'Other commands:\n'\ + ' -flistall Print all functions capable of being captured in ftrace\n'\ + ' -sysinfo Print out system info extracted from BIOS\n'\ + ' [redo]\n'\ + ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\ + ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\ + '' % (sysvals.title, sysvals.version)) return True # ----------------- MAIN -------------------- @@ -895,7 +898,7 @@ if __name__ == '__main__': printHelp() sys.exit() elif(arg == '-v'): - print("Version %s" % sysvals.version) + pprint("Version %s" % sysvals.version) sys.exit() elif(arg == '-verbose'): sysvals.verbose = True @@ -1016,7 +1019,7 @@ if __name__ == '__main__': print f elif cmd == 'checkbl': sysvals.getBootLoader() - print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec) + pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)) elif(cmd == 'sysinfo'): sysvals.printSystemInfo(True) sys.exit() diff --git a/tools/power/pm-graph/config/cgskip.txt b/tools/power/pm-graph/config/cgskip.txt index e48d588fbfb4..9ff88e7e2300 100644 --- a/tools/power/pm-graph/config/cgskip.txt +++ b/tools/power/pm-graph/config/cgskip.txt @@ -27,6 +27,7 @@ ktime_get # console calls printk dev_printk +__dev_printk console_unlock # memory handling diff --git a/tools/power/pm-graph/config/custom-timeline-functions.cfg b/tools/power/pm-graph/config/custom-timeline-functions.cfg index f8fcb06fd68b..4f80ad7d7275 100644 --- a/tools/power/pm-graph/config/custom-timeline-functions.cfg +++ b/tools/power/pm-graph/config/custom-timeline-functions.cfg @@ -105,7 +105,7 @@ override-dev-timeline-functions: true # example: [color=#CC00CC] # # arglist: A list of arguments from registers/stack addresses. See URL: -# https://www.kernel.org/doc/Documentation/trace/kprobetrace.rst +# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt # # example: cpu=%di:s32 # @@ -170,7 +170,7 @@ pm_restore_console: # example: [color=#CC00CC] # # arglist: A list of arguments from registers/stack addresses. See URL: -# https://www.kernel.org/doc/Documentation/trace/kprobetrace.rst +# https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt # # example: port=+36(%di):s32 # diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index 343e8000d9ca..52618f3444d4 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -62,6 +62,10 @@ import gzip from threading import Thread from subprocess import call, Popen, PIPE +def pprint(msg): + print(msg) + sys.stdout.flush() + # ----------------- CLASSES -------------------- # Class: SystemValues @@ -70,7 +74,7 @@ from subprocess import call, Popen, PIPE # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.1' + version = '5.2' ansi = False rs = 0 display = '' @@ -111,8 +115,10 @@ class SystemValues: mempath = '/dev/mem' powerfile = '/sys/power/state' mempowerfile = '/sys/power/mem_sleep' + diskpowerfile = '/sys/power/disk' suspendmode = 'mem' memmode = '' + diskmode = '' hostname = 'localhost' prefix = 'test' teststamp = '' @@ -139,6 +145,7 @@ class SystemValues: useprocmon = False notestrun = False cgdump = False + devdump = False mixedphaseheight = True devprops = dict() predelay = 0 @@ -265,7 +272,7 @@ class SystemValues: def vprint(self, msg): self.logmsg += msg+'\n' if self.verbose or msg.startswith('WARNING:'): - print(msg) + pprint(msg) def signalHandler(self, signum, frame): if not self.result: return @@ -290,7 +297,7 @@ class SystemValues: return True if fatal: msg = 'This command requires sysfs mount and root access' - print('ERROR: %s\n') % msg + pprint('ERROR: %s\n' % msg) self.outputResult({'error':msg}) sys.exit(1) return False @@ -299,7 +306,7 @@ class SystemValues: return True if fatal: msg = 'This command must be run as root' - print('ERROR: %s\n') % msg + pprint('ERROR: %s\n' % msg) self.outputResult({'error':msg}) sys.exit(1) return False @@ -560,7 +567,7 @@ class SystemValues: if len(self.kprobes) < 1: return if output: - print(' kprobe functions in this kernel:') + pprint(' kprobe functions in this kernel:') # first test each kprobe rejects = [] # sort kprobes: trace, ub-dev, custom, dev @@ -582,7 +589,7 @@ class SystemValues: else: kpl[2].append(name) if output: - print(' %s: %s' % (name, res)) + pprint(' %s: %s' % (name, res)) kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3] # remove all failed ones from the list for name in rejects: @@ -596,7 +603,7 @@ class SystemValues: if output: check = self.fgetVal('kprobe_events') linesack = (len(check.split('\n')) - 1) / 2 - print(' kprobe functions enabled: %d/%d' % (linesack, linesout)) + pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout)) self.fsetVal('1', 'events/kprobes/enable') def testKprobe(self, kname, kprobe): self.fsetVal('0', 'events/kprobes/enable') @@ -664,7 +671,7 @@ class SystemValues: return False def initFtrace(self): self.printSystemInfo(False) - print('INITIALIZING FTRACE...') + pprint('INITIALIZING FTRACE...') # turn trace off self.fsetVal('0', 'tracing_on') self.cleanupFtrace() @@ -681,7 +688,8 @@ class SystemValues: if self.bufsize > 0: tgtsize = self.bufsize elif self.usecallgraph or self.usedevsrc: - tgtsize = min(self.memfree, 3*1024*1024) + bmax = (1*1024*1024) if self.suspendmode == 'disk' else (3*1024*1024) + tgtsize = min(self.memfree, bmax) else: tgtsize = 65536 while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'): @@ -690,7 +698,7 @@ class SystemValues: 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) + pprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)) # initialize the callgraph trace if(self.usecallgraph): # set trace type @@ -723,7 +731,7 @@ class SystemValues: if self.usedevsrc: for name in self.dev_tracefuncs: self.defaultKprobe(name, self.dev_tracefuncs[name]) - print('INITIALIZING KPROBES...') + pprint('INITIALIZING KPROBES...') self.addKprobes(self.verbose) if(self.usetraceevents): # turn trace events on @@ -846,7 +854,7 @@ class DevProps: def out(self, dev): return '%s,%s,%d;' % (dev, self.altname, self.async) def debug(self, dev): - print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async) + pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)) def altName(self, dev): if not self.altname or self.altname == dev: return dev @@ -1217,16 +1225,8 @@ class Data: self.tLow.append('%.0f'%(tL*1000)) lp = phase def getTimeValues(self): - if 'suspend_machine' in self.dmesg: - sktime = (self.dmesg['suspend_machine']['end'] - \ - self.tKernSus) * 1000 - else: - sktime = (self.tSuspended - self.tKernSus) * 1000 - if 'resume_machine' in self.dmesg: - rktime = (self.tKernRes - \ - self.dmesg['resume_machine']['start']) * 1000 - else: - rktime = (self.tKernRes - self.tResumed) * 1000 + sktime = (self.tSuspended - self.tKernSus) * 1000 + rktime = (self.tKernRes - self.tResumed) * 1000 return (sktime, rktime) def setPhase(self, phase, ktime, isbegin, order=-1): if(isbegin): @@ -1379,14 +1379,38 @@ class Data: if(list[child]['par'] == devname): devlist.append(child) return devlist + def maxDeviceNameSize(self, phase): + size = 0 + for name in self.dmesg[phase]['list']: + if len(name) > size: + size = len(name) + return size def printDetails(self): sysvals.vprint('Timeline Details:') sysvals.vprint(' test start: %f' % self.start) sysvals.vprint('kernel suspend start: %f' % self.tKernSus) + tS = tR = False for phase in self.sortedPhases(): - dc = len(self.dmesg[phase]['list']) - sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ - self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) + devlist = self.dmesg[phase]['list'] + dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end'] + if not tS and ps >= self.tSuspended: + sysvals.vprint(' machine suspended: %f' % self.tSuspended) + tS = True + if not tR and ps >= self.tResumed: + sysvals.vprint(' machine resumed: %f' % self.tResumed) + tR = True + sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc)) + if sysvals.devdump: + sysvals.vprint(''.join('-' for i in range(80))) + maxname = '%d' % self.maxDeviceNameSize(phase) + fmt = '%3d) %'+maxname+'s - %f - %f' + c = 1 + for name in devlist: + s = devlist[name]['start'] + e = devlist[name]['end'] + sysvals.vprint(fmt % (c, name, s, e)) + c += 1 + sysvals.vprint(''.join('-' for i in range(80))) sysvals.vprint(' kernel resume end: %f' % self.tKernRes) sysvals.vprint(' test end: %f' % self.end) def deviceChildrenAllPhases(self, devname): @@ -1721,13 +1745,13 @@ class FTraceLine: return len(str)/2 def debugPrint(self, info=''): if self.isLeaf(): - print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ + pprint(' -- %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, \ + pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ self.depth, self.name, self.length*1000000, info)) else: - print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \ + pprint(' -- %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? @@ -1868,7 +1892,7 @@ class FTraceCallGraph: if warning and ('[make leaf]', line) not in info: info.append(('', line)) if warning: - print 'WARNING: ftrace data missing, corrections made:' + pprint('WARNING: ftrace data missing, corrections made:') for i in info: t, obj = i if obj: @@ -1928,10 +1952,10 @@ class FTraceCallGraph: id = 'task %s' % (self.pid) window = '(%f - %f)' % (self.start, line.time) if(self.depth < 0): - print('Data misalignment for '+id+\ + pprint('Data misalignment for '+id+\ ' (buffer overflow), ignoring this callback') else: - print('Too much data for '+id+\ + pprint('Too much data for '+id+\ ' '+window+', ignoring this callback') def slice(self, dev): minicg = FTraceCallGraph(dev['pid'], self.sv) @@ -1984,7 +2008,7 @@ class FTraceCallGraph: elif l.isReturn(): if(l.depth not in stack): if self.sv.verbose: - print 'Post Process Error: Depth missing' + pprint('Post Process Error: Depth missing') l.debugPrint() return False # calculate call length from call/return lines @@ -2001,7 +2025,7 @@ class FTraceCallGraph: return True elif(cnt < 0): if self.sv.verbose: - print 'Post Process Error: Depth is less than 0' + pprint('Post Process Error: Depth is less than 0') return False # trace ended before call tree finished return self.repair(cnt) @@ -2060,20 +2084,20 @@ class FTraceCallGraph: phase, myname = out data.dmesg[phase]['list'][myname]['ftrace'] = self def debugPrint(self, info=''): - print('%s pid=%d [%f - %f] %.3f us') % \ + pprint('%s pid=%d [%f - %f] %.3f us' % \ (self.name, self.pid, self.start, self.end, - (self.end - self.start)*1000000) + (self.end - self.start)*1000000)) for l in self.list: if l.isLeaf(): - print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ + pprint('%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, \ + pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \ l.depth, l.name, l.length*1000000, info)) else: - print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ + pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ l.depth, l.name, l.length*1000000, info)) - print(' ') + pprint(' ') class DevItem: def __init__(self, test, phase, dev): @@ -2658,7 +2682,8 @@ def parseTraceLog(live=False): doError('%s does not exist' % sysvals.ftracefile) if not live: sysvals.setupAllKprobes() - krescalls = ['pm_notifier_call_chain', 'pm_restore_console'] + ksuscalls = ['pm_prepare_console'] + krescalls = ['pm_restore_console'] tracewatch = [] if sysvals.usekprobes: tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', @@ -2738,6 +2763,7 @@ def parseTraceLog(live=False): testruns.append(testrun) tp.parseStamp(data, sysvals) data.setStart(t.time) + data.first_suspend_prepare = True phase = data.setPhase('suspend_prepare', t.time, True) continue if(not data): @@ -2797,11 +2823,12 @@ def parseTraceLog(live=False): continue # suspend_prepare start elif(re.match('dpm_prepare\[.*', t.name)): - phase = 'suspend_prepare' - if not isbegin: - data.setPhase(phase, t.time, isbegin) - if isbegin and data.tKernSus == 0: - data.tKernSus = t.time + if isbegin and data.first_suspend_prepare: + data.first_suspend_prepare = False + if data.tKernSus == 0: + data.tKernSus = t.time + continue + phase = data.setPhase('suspend_prepare', t.time, isbegin) continue # suspend start elif(re.match('dpm_suspend\[.*', t.name)): @@ -2826,11 +2853,11 @@ def parseTraceLog(live=False): else: phase = data.setPhase('resume_machine', t.time, True) if(sysvals.suspendmode in ['mem', 'disk']): - if 'suspend_machine' in data.dmesg: - data.dmesg['suspend_machine']['end'] = t.time + susp = phase.replace('resume', 'suspend') + if susp in data.dmesg: + data.dmesg[susp]['end'] = t.time data.tSuspended = t.time - if data.tResumed == 0: - data.tResumed = t.time + data.tResumed = t.time continue # resume_noirq start elif(re.match('dpm_resume_noirq\[.*', t.name)): @@ -2911,6 +2938,9 @@ def parseTraceLog(live=False): 'cdata': kprobedata, 'proc': m_proc, }) + # start of kernel resume + if(phase == 'suspend_prepare' and kprobename in ksuscalls): + data.tKernSus = t.time elif(t.freturn): if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1: continue @@ -2962,6 +2992,14 @@ def parseTraceLog(live=False): if sysvals.usedevsrc or sysvals.useprocmon: sysvals.mixedphaseheight = False + # expand phase boundaries so there are no gaps + for data in testdata: + lp = data.sortedPhases()[0] + for p in data.sortedPhases(): + if(p != lp and not ('machine' in p and 'machine' in lp)): + data.dmesg[lp]['end'] = data.dmesg[p]['start'] + lp = p + for i in range(len(testruns)): test = testruns[i] data = test.data @@ -3044,7 +3082,7 @@ def parseTraceLog(live=False): for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): if p not in data.dmesg: if not terr: - print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp) + pprint('TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)) terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp) error.append(terr) if data.tSuspended == 0: @@ -3055,14 +3093,9 @@ def parseTraceLog(live=False): sysvals.vprint('WARNING: phase "%s" is missing!' % p) lp = p if not terr and data.enterfail: - print 'test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail) + pprint('test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail)) terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode) error.append(terr) - lp = data.sortedPhases()[0] - for p in data.sortedPhases(): - if(p != lp and not ('machine' in p and 'machine' in lp)): - data.dmesg[lp]['end'] = data.dmesg[p]['start'] - lp = p if data.tSuspended == 0: data.tSuspended = data.tKernRes if data.tResumed == 0: @@ -3151,7 +3184,7 @@ def loadKernelLog(): if data: testruns.append(data) if len(testruns) < 1: - print('ERROR: dmesg log has no suspend/resume data: %s' \ + pprint('ERROR: dmesg log has no suspend/resume data: %s' \ % sysvals.dmesgfile) # fix lines with same timestamp/function with the call and return swapped @@ -3405,7 +3438,7 @@ def parseKernelLog(data): for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): if p not in data.dmesg: if not terr: - print 'TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp) + pprint('TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp)) terr = '%s failed in %s phase' % (sysvals.suspendmode, lp) if data.tSuspended == 0: data.tSuspended = data.dmesg[lp]['end'] @@ -3503,7 +3536,7 @@ def addCallgraphs(sv, hf, data): # Create summary html file for a series of tests # Arguments: # testruns: array of Data objects from parseTraceLog -def createHTMLSummarySimple(testruns, htmlfile, folder): +def createHTMLSummarySimple(testruns, htmlfile, title): # write the html header first (html head, css code, up to body start) html = '<!DOCTYPE html>\n<html>\n<head>\n\ <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ @@ -3583,7 +3616,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder): for ilk in sorted(cnt, reverse=True): if cnt[ilk] > 0: desc.append('%d %s' % (cnt[ilk], ilk)) - html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (folder, len(testruns), ', '.join(desc)) + html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (title, len(testruns), ', '.join(desc)) th = '\t<th>{0}</th>\n' td = '\t<td>{0}</td>\n' tdh = '\t<td{1}>{0}</td>\n' @@ -3685,7 +3718,7 @@ def ordinal(value): # True if the html file was created, false if it failed def createHTML(testruns, testfail): if len(testruns) < 1: - print('ERROR: Not enough test data to build a timeline') + pprint('ERROR: Not enough test data to build a timeline') return kerror = False @@ -4535,18 +4568,18 @@ def setRuntimeSuspend(before=True): sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled' else: sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled' - print('CONFIGURING RUNTIME SUSPEND...') + pprint('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...') + pprint('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist))) + pprint('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)) + pprint('runtime suspend settings restored on %d devices' % len(sv.rslist)) # Function: executeSuspend # Description: @@ -4559,17 +4592,17 @@ def executeSuspend(): battery = True if getBattery() else False # run these commands to prepare the system for suspend if sysvals.display: - print('SET DISPLAY TO %s' % sysvals.display.upper()) + pprint('SET DISPLAY TO %s' % sysvals.display.upper()) displayControl(sysvals.display) time.sleep(1) if sysvals.sync: - print('SYNCING FILESYSTEMS') + pprint('SYNCING FILESYSTEMS') call('sync', shell=True) # mark the start point in the kernel ring buffer just as we start sysvals.initdmesg() # start ftrace if(sysvals.usecallgraph or sysvals.usetraceevents): - print('START TRACING') + pprint('START TRACING') sysvals.fsetVal('1', 'tracing_on') if sysvals.useprocmon: pm.start() @@ -4582,16 +4615,16 @@ def executeSuspend(): sysvals.fsetVal('WAIT END', 'trace_marker') # start message if sysvals.testcommand != '': - print('COMMAND START') + pprint('COMMAND START') else: if(sysvals.rtcwake): - print('SUSPEND START') + pprint('SUSPEND START') else: - print('SUSPEND START (press a key to resume)') + pprint('SUSPEND START (press a key to resume)') bat1 = getBattery() if battery else False # set rtcwake if(sysvals.rtcwake): - print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) + pprint('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) sysvals.rtcWakeAlarmOn() # start of suspend trace marker if(sysvals.usecallgraph or sysvals.usetraceevents): @@ -4614,6 +4647,11 @@ def executeSuspend(): pf = open(sysvals.mempowerfile, 'w') pf.write(sysvals.memmode) pf.close() + if sysvals.diskmode and os.path.exists(sysvals.diskpowerfile): + mode = 'disk' + pf = open(sysvals.diskpowerfile, 'w') + pf.write(sysvals.diskmode) + pf.close() pf = open(sysvals.powerfile, 'w') pf.write(mode) # execution will pause here @@ -4629,7 +4667,7 @@ def executeSuspend(): time.sleep(sysvals.postdelay/1000.0) sysvals.fsetVal('WAIT END', 'trace_marker') # return from suspend - print('RESUME COMPLETE') + pprint('RESUME COMPLETE') if(sysvals.usecallgraph or sysvals.usetraceevents): sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): @@ -4644,11 +4682,11 @@ def executeSuspend(): pm.stop() sysvals.fsetVal('0', 'tracing_on') # grab a copy of the dmesg output - print('CAPTURING DMESG') + pprint('CAPTURING DMESG') sysvals.getdmesg(testdata) # grab a copy of the ftrace output if(sysvals.usecallgraph or sysvals.usetraceevents): - print('CAPTURING TRACE') + pprint('CAPTURING TRACE') op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata) fp = open(tp+'trace', 'r') for line in fp: @@ -4692,15 +4730,15 @@ def yesno(val): # a list of USB device names to sysvals for better timeline readability 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('---------------------------------------------------------------------------------------------') + pprint('LEGEND\n'\ + '---------------------------------------------------------------------------------------------\n'\ + ' A = async/sync PM queue (A/S) C = runtime active children\n'\ + ' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)\n'\ + ' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)\n'\ + ' U = runtime usage count\n'\ + '---------------------------------------------------------------------------------------------\n'\ + 'DEVICE NAME A R S U C rACTIVE rSUSPEND\n'\ + '---------------------------------------------------------------------------------------------') res = [] tgtval = 'runtime_status' @@ -4889,6 +4927,11 @@ def getModes(): fp.close() if 'mem' in modes and not deep: modes.remove('mem') + if('disk' in modes and os.path.exists(sysvals.diskpowerfile)): + fp = open(sysvals.diskpowerfile, 'r') + for m in string.split(fp.read()): + modes.append('disk-%s' % m.strip('[]')) + fp.close() return modes # Function: dmidecode @@ -5037,16 +5080,21 @@ def displayControl(cmd): xset = 'sudo -u %s %s' % (sysvals.sudouser, xset) if cmd == 'init': ret = call(xset.format('dpms 0 0 0'), shell=True) - ret = call(xset.format('s off'), shell=True) + if not ret: + ret = call(xset.format('s off'), shell=True) elif cmd == 'reset': ret = call(xset.format('s reset'), shell=True) elif cmd in ['on', 'off', 'standby', 'suspend']: b4 = displayControl('stat') ret = call(xset.format('dpms force %s' % cmd), shell=True) - curr = displayControl('stat') - sysvals.vprint('Display Switched: %s -> %s' % (b4, curr)) - if curr != cmd: - sysvals.vprint('WARNING: Display failed to change to %s' % cmd) + if not ret: + curr = displayControl('stat') + sysvals.vprint('Display Switched: %s -> %s' % (b4, curr)) + if curr != cmd: + sysvals.vprint('WARNING: Display failed to change to %s' % cmd) + if ret: + sysvals.vprint('WARNING: Display failed to change to %s with xset' % cmd) + return ret elif cmd == 'stat': fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout ret = 'unknown' @@ -5102,18 +5150,19 @@ def getFPDT(output): table = struct.unpack('4sIBB6s8sI4sI', buf[0:36]) if(output): - print('') - print('Firmware Performance Data Table (%s)' % table[0]) - print(' Signature : %s' % table[0]) - print(' Table Length : %u' % table[1]) - print(' Revision : %u' % table[2]) - print(' Checksum : 0x%x' % table[3]) - print(' OEM ID : %s' % table[4]) - print(' OEM Table ID : %s' % table[5]) - print(' OEM Revision : %u' % table[6]) - print(' Creator ID : %s' % table[7]) - print(' Creator Revision : 0x%x' % table[8]) - print('') + pprint('\n'\ + 'Firmware Performance Data Table (%s)\n'\ + ' Signature : %s\n'\ + ' Table Length : %u\n'\ + ' Revision : %u\n'\ + ' Checksum : 0x%x\n'\ + ' OEM ID : %s\n'\ + ' OEM Table ID : %s\n'\ + ' OEM Revision : %u\n'\ + ' Creator ID : %s\n'\ + ' Creator Revision : 0x%x\n'\ + '' % (table[0], table[0], table[1], table[2], table[3], + table[4], table[5], table[6], table[7], table[8])) if(table[0] != 'FPDT'): if(output): @@ -5139,22 +5188,24 @@ def getFPDT(output): first = fp.read(8) except: if(output): - print('Bad address 0x%x in %s' % (addr, sysvals.mempath)) + pprint('Bad address 0x%x in %s' % (addr, sysvals.mempath)) return [0, 0] rechead = struct.unpack('4sI', first) recdata = fp.read(rechead[1]-8) if(rechead[0] == 'FBPT'): record = struct.unpack('HBBIQQQQQ', recdata) if(output): - print('%s (%s)' % (rectype[header[0]], rechead[0])) - print(' Reset END : %u ns' % record[4]) - print(' OS Loader LoadImage Start : %u ns' % record[5]) - print(' OS Loader StartImage Start : %u ns' % record[6]) - print(' ExitBootServices Entry : %u ns' % record[7]) - print(' ExitBootServices Exit : %u ns' % record[8]) + pprint('%s (%s)\n'\ + ' Reset END : %u ns\n'\ + ' OS Loader LoadImage Start : %u ns\n'\ + ' OS Loader StartImage Start : %u ns\n'\ + ' ExitBootServices Entry : %u ns\n'\ + ' ExitBootServices Exit : %u ns'\ + '' % (rectype[header[0]], rechead[0], record[4], record[5], + record[6], record[7], record[8])) elif(rechead[0] == 'S3PT'): if(output): - print('%s (%s)' % (rectype[header[0]], rechead[0])) + pprint('%s (%s)' % (rectype[header[0]], rechead[0])) j = 0 while(j < len(recdata)): prechead = struct.unpack('HBB', recdata[j:j+4]) @@ -5164,27 +5215,26 @@ def getFPDT(output): record = struct.unpack('IIQQ', recdata[j:j+prechead[1]]) fwData[1] = record[2] if(output): - print(' %s' % prectype[prechead[0]]) - print(' Resume Count : %u' % \ - record[1]) - print(' FullResume : %u ns' % \ - record[2]) - print(' AverageResume : %u ns' % \ - record[3]) + pprint(' %s\n'\ + ' Resume Count : %u\n'\ + ' FullResume : %u ns\n'\ + ' AverageResume : %u ns'\ + '' % (prectype[prechead[0]], record[1], + record[2], record[3])) elif(prechead[0] == 1): record = struct.unpack('QQ', recdata[j+4:j+prechead[1]]) fwData[0] = record[1] - record[0] if(output): - print(' %s' % prectype[prechead[0]]) - print(' SuspendStart : %u ns' % \ - record[0]) - print(' SuspendEnd : %u ns' % \ - record[1]) - print(' SuspendTime : %u ns' % \ - fwData[0]) + ppr |