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