From patchwork Wed Dec 14 18:37:07 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Todd Brandt X-Patchwork-Id: 9474481 X-Patchwork-Delegate: rjw@sisk.pl Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 47C9160571 for ; Wed, 14 Dec 2016 18:37:25 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 392F128664 for ; Wed, 14 Dec 2016 18:37:25 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 2D35B286E5; Wed, 14 Dec 2016 18:37:25 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.9 required=2.0 tests=BAYES_00,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 665892872A for ; Wed, 14 Dec 2016 18:37:19 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754327AbcLNShS (ORCPT ); Wed, 14 Dec 2016 13:37:18 -0500 Received: from mga14.intel.com ([192.55.52.115]:6624 "EHLO mga14.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754329AbcLNShR (ORCPT ); Wed, 14 Dec 2016 13:37:17 -0500 Received: from orsmga001.jf.intel.com ([10.7.209.18]) by fmsmga103.fm.intel.com with ESMTP; 14 Dec 2016 10:37:13 -0800 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.33,347,1477983600"; d="scan'208";a="1072072024" Received: from carlsch-mobl.amr.corp.intel.com (HELO technocore.amr.corp.intel.com) ([10.254.77.201]) by orsmga001.jf.intel.com with ESMTP; 14 Dec 2016 10:37:12 -0800 From: Todd Brandt To: linux-pm@vger.kernel.org Cc: todd.e.brandt@intel.com, rjw@rjwysocki.net, rafael.j.wysocki@intel.com, Todd Brandt Subject: [PATCH 3/3] AnalyzeSuspend v4.5 Date: Wed, 14 Dec 2016 10:37:07 -0800 Message-Id: <8651107c732f7366a81aae57265f6e835cfcee5f.1481740176.git.todd.e.brandt@linux.intel.com> X-Mailer: git-send-email 2.1.4 In-Reply-To: References: In-Reply-To: References: Sender: linux-pm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pm@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP - Kernel errors shown in timeline - Tool log: The tool output log is now available in the html timeline - Selective ftrace filter: can choose phase and test run (for x2) - further instrumentation of dev mode to cover wifi Signed-off-by: Todd Brandt --- scripts/analyze_suspend.py | 591 +++++++++++++++++++++------------------------ 1 file changed, 272 insertions(+), 319 deletions(-) diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py index 0126859..383df79 100755 --- a/scripts/analyze_suspend.py +++ b/scripts/analyze_suspend.py @@ -24,11 +24,6 @@ # 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 @@ -77,11 +72,13 @@ from subprocess import call, Popen, PIPE # store system values and test parameters class SystemValues: ansi = False - version = '4.4' + version = '4.5' verbose = False addlogs = False - mindevlen = 0.001 - mincglen = 1.0 + mindevlen = 0.0 + mincglen = 0.0 + cgphase = '' + cgtest = -1 callloopmaxgap = 0.0001 callloopmaxlen = 0.005 srgap = 0 @@ -96,6 +93,7 @@ class SystemValues: 'device_pm_callback_end', 'device_pm_callback_start' ] + logmsg = '' testcommand = '' mempath = '/dev/mem' powerfile = '/sys/power/state' @@ -166,18 +164,38 @@ class SystemValues: } dev_tracefuncs = { # general wait/delay/sleep - 'msleep': { 'args_x86_64': {'time':'%di:s32'} }, - 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'} }, - 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'} }, - 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} }, - 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'} }, - 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath' }, - 'acpi_os_stall': dict(), + 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 }, + 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, + 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, + 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 }, + 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, + 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, + 'acpi_os_stall': {'ub': 1}, # ACPI 'acpi_resume_power_resources': dict(), 'acpi_ps_parse_aml': dict(), # filesystem 'ext4_sync_fs': dict(), + # 80211 + 'iwlagn_mac_start': dict(), + 'iwlagn_alloc_bcast_station': dict(), + 'iwl_trans_pcie_start_hw': dict(), + 'iwl_trans_pcie_start_fw': dict(), + 'iwl_run_init_ucode': dict(), + 'iwl_load_ucode_wait_alive': dict(), + 'iwl_alive_start': dict(), + 'iwlagn_mac_stop': dict(), + 'iwlagn_mac_suspend': dict(), + 'iwlagn_mac_resume': dict(), + 'iwlagn_mac_add_interface': dict(), + 'iwlagn_mac_remove_interface': dict(), + 'iwlagn_mac_change_interface': dict(), + 'iwlagn_mac_config': dict(), + 'iwlagn_configure_filter': dict(), + 'iwlagn_mac_hw_scan': dict(), + 'iwlagn_bss_info_changed': dict(), + 'iwlagn_mac_channel_switch': dict(), + 'iwlagn_mac_flush': dict(), # ATA 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} }, # i915 @@ -196,14 +214,6 @@ class SystemValues: 'intel_opregion_init': dict(), 'intel_fbdev_set_suspend': dict(), } - kprobes_postresume = [ - { - 'name': 'ataportrst', - 'func': 'ata_eh_recover', - 'args': {'port':'+36(%di):s32'}, - 'format': 'ata{port}_port_reset' - } - ] kprobes = dict() timeformat = '%.3f' def __init__(self): @@ -429,45 +439,65 @@ class SystemValues: if 'args' in kprobe: args = kprobe['args'] if re.findall('{(?P[a-z,A-Z,0-9]*)}', func): - doError('Kprobe "%s" has format info in the function name "%s"' % (name, func), False) + doError('Kprobe "%s" has format info in the function name "%s"' % (name, func)) for arg in re.findall('{(?P[a-z,A-Z,0-9]*)}', fmt): if arg not in args: - doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False) + doError('Kprobe "%s" is missing argument "%s"' % (name, arg)) 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): + def addKprobes(self, output=False): + if len(sysvals.kprobes) < 1: + return + if output: + print(' kprobe functions in this kernel:') # first test each kprobe - print('INITIALIZING KPROBES...') rejects = [] + # sort kprobes: trace, ub-dev, custom, dev + kpl = [[], [], [], []] for name in sorted(self.kprobes): + res = self.colorText('YES', 32) if not self.testKprobe(name, self.kprobes[name]): + res = self.colorText('NO') rejects.append(name) + else: + if name in self.tracefuncs: + kpl[0].append(name) + elif name in self.dev_tracefuncs: + if 'ub' in self.dev_tracefuncs[name]: + kpl[1].append(name) + else: + kpl[3].append(name) + else: + kpl[2].append(name) + if output: + print(' %s: %s' % (name, res)) + kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3] # remove all failed ones from the list for name in rejects: - vprint('Skipping KPROBE: %s' % name) self.kprobes.pop(name) + # set the kprobes all at once self.fsetVal('', 'kprobe_events') kprobeevents = '' - # set the kprobes all at once - for kp in self.kprobes: - val = self.kprobeText(kp, self.kprobes[kp]) - vprint('Adding KPROBE: %s\n%s' % (kp, val.strip())) + for kp in kplist: kprobeevents += self.kprobeText(kp, self.kprobes[kp]) self.fsetVal(kprobeevents, 'kprobe_events') # verify that the kprobes were set as ordered check = self.fgetVal('kprobe_events') - linesout = len(kprobeevents.split('\n')) - 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(kp, self.kprobes[kp]) - self.fsetVal(kprobeevents, 'kprobe_events', 'a') + linesout = len(kprobeevents.split('\n')) - 1 + linesack = len(check.split('\n')) - 1 + if output: + res = '%d/%d' % (linesack, linesout) + if linesack < linesout: + res = self.colorText(res, 31) + else: + res = self.colorText(res, 32) + print(' working kprobe functions enabled: %s' % res) self.fsetVal('1', 'events/kprobes/enable') def testKprobe(self, kname, kprobe): + self.fsetVal('0', 'events/kprobes/enable') kprobeevents = self.kprobeText(kname, kprobe) if not kprobeevents: return False @@ -486,8 +516,9 @@ class SystemValues: if not os.path.exists(file): return False try: - fp = open(file, mode) + fp = open(file, mode, 0) fp.write(val) + fp.flush() fp.close() except: pass @@ -525,7 +556,6 @@ class SystemValues: return True return False def initFtrace(self, testing=False): - tp = self.tpath print('INITIALIZING FTRACE...') # turn trace off self.fsetVal('0', 'tracing_on') @@ -570,7 +600,8 @@ class SystemValues: if self.usedevsrc: for name in self.dev_tracefuncs: self.defaultKprobe(name, self.dev_tracefuncs[name]) - self.addKprobes() + print('INITIALIZING KPROBES...') + self.addKprobes(self.verbose) if(self.usetraceevents): # turn trace events on events = iter(self.traceevents) @@ -602,10 +633,10 @@ class SystemValues: if(os.path.exists(tp+f) == False): return False return True - def colorText(self, str): + def colorText(self, str, color=31): if not self.ansi: return str - return '\x1B[31;40m'+str+'\x1B[m' + return '\x1B[%d;40m%s\x1B[m' % (color, str) sysvals = SystemValues() @@ -658,8 +689,6 @@ class DeviceNode: # The primary container for suspend/resume test data. There is one for # each test run. The data is organized into a cronological hierarchy: # Data.dmesg { -# root structure, started as dmesg & ftrace, but now only ftrace -# contents: times for suspend start/end, resume start/end, fwdata # phases { # 10 sequential, non-overlapping phases of S/R # contents: times for phase start/end, order/color data for html @@ -670,7 +699,7 @@ class DeviceNode: # contents: start/stop times, pid/cpu/driver info # parents/children, html id for timeline/callgraph # optionally includes an ftrace callgraph -# optionally includes intradev trace events +# optionally includes dev/ps data # } # } # } @@ -697,16 +726,9 @@ class Data: stamp = 0 outfile = '' devpids = [] - dev_ubiquitous = [ - 'msleep', - 'schedule_timeout_uninterruptible', - 'schedule_timeout', - 'udelay', - 'usleep_range', - 'mutex_lock_slowpath' - ] + kerror = False def __init__(self, num): - idchar = 'abcdefghijklmnopqrstuvwxyz' + idchar = 'abcdefghij' self.pstl = dict() self.testnumber = num self.idstr = idchar[num] @@ -738,6 +760,35 @@ class Data: self.devicegroups = [] for phase in self.phases: self.devicegroups.append([phase]) + self.errorinfo = {'suspend':[],'resume':[]} + def extractErrorInfo(self, dmesg): + error = '' + tm = 0.0 + for i in range(len(dmesg)): + if 'Call Trace:' in dmesg[i]: + m = re.match('[ \t]*(\[ *)(?P[0-9\.]*)(\]) .*', dmesg[i]) + if not m: + continue + tm = float(m.group('ktime')) + if tm < self.start or tm > self.end: + continue + for j in range(i-10, i+1): + error += dmesg[j] + continue + if error: + m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i]) + if m: + error += dmesg[i] + else: + if tm < self.tSuspended: + dir = 'suspend' + else: + dir = 'resume' + error = error.replace('<', '<').replace('>', '>') + vprint('kernel error found in %s at %f' % (dir, tm)) + self.errorinfo[dir].append((tm, error)) + self.kerror = True + error = '' def setStart(self, time): self.start = time def setEnd(self, time): @@ -751,9 +802,8 @@ class Data: time < d['end']): return False return True - def sourcePhase(self, start, end): + def sourcePhase(self, start): for phase in self.phases: - pstart = self.dmesg[phase]['start'] pend = self.dmesg[phase]['end'] if start <= pend: return phase @@ -798,7 +848,7 @@ class Data: threadname = 'kthread-%d' % (pid) else: threadname = '%s-%d' % (proc, pid) - tgtphase = self.sourcePhase(start, end) + tgtphase = self.sourcePhase(start) self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '') return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) # this should not happen @@ -809,8 +859,9 @@ class Data: # place the call data inside the src element of the tgtdev if('src' not in tgtdev): tgtdev['src'] = [] + dtf = sysvals.dev_tracefuncs ubiquitous = False - if kprobename in self.dev_ubiquitous: + if kprobename in dtf and 'ub' in dtf[kprobename]: ubiquitous = True title = cdata+' '+rdata mstr = '\(.*\) *(?P.*) *\((?P.*)\+.* arg1=(?P.*)' @@ -823,7 +874,7 @@ class Data: r = '' else: r = 'ret=%s ' % r - if ubiquitous and c in self.dev_ubiquitous: + if ubiquitous and c in dtf and 'ub' in dtf[c]: return False color = sysvals.kprobeColor(kprobename) e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color) @@ -917,6 +968,8 @@ class Data: self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left) self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left) self.start = self.trimTimeVal(self.start, t0, dT, left) + self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left) + self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left) self.end = self.trimTimeVal(self.end, t0, dT, left) for phase in self.phases: p = self.dmesg[phase] @@ -964,7 +1017,7 @@ class Data: for t in sorted(tmp): slist.append(tmp[t]) return slist - def fixupInitcalls(self, phase, end): + def fixupInitcalls(self, phase): # if any calls never returned, clip them at system resume end phaselist = self.dmesg[phase]['list'] for devname in phaselist: @@ -976,8 +1029,6 @@ class Data: break vprint('%s (%s): callback didnt return' % (devname, phase)) def deviceFilter(self, devicefilter): - # check each device name & driver name - # remove it if it does not include one of the filter strings for phase in self.phases: list = self.dmesg[phase]['list'] rmlist = [] @@ -994,7 +1045,7 @@ class Data: def fixupInitcallsThatDidntReturn(self): # if any calls never returned, clip them at system resume end for phase in self.phases: - self.fixupInitcalls(phase, self.end) + self.fixupInitcalls(phase) def phaseOverlap(self, phases): rmgroups = [] newgroup = [] @@ -1068,22 +1119,6 @@ class Data: if color: list[name]['color'] = color return name - def deviceIDs(self, devlist, phase): - idlist = [] - list = self.dmesg[phase]['list'] - for devname in list: - if devname in devlist: - idlist.append(list[devname]['id']) - return idlist - def deviceParentID(self, devname, phase): - pdev = '' - pdevid = '' - list = self.dmesg[phase]['list'] - if devname in list: - pdev = list[devname]['par'] - if pdev in list: - return list[pdev]['id'] - return pdev def deviceChildren(self, devname, phase): devlist = [] list = self.dmesg[phase]['list'] @@ -1091,15 +1126,6 @@ class Data: if(list[child]['par'] == devname): devlist.append(child) return devlist - def deviceDescendants(self, devname, phase): - children = self.deviceChildren(devname, phase) - family = children - for child in children: - family += self.deviceDescendants(child, phase) - return family - def deviceChildrenIDs(self, devname, phase): - devlist = self.deviceChildren(devname, phase) - return self.deviceIDs(devlist, phase) def printDetails(self): vprint('Timeline Details:') vprint(' test start: %f' % self.start) @@ -1418,7 +1444,6 @@ class FTraceLine: 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 @@ -1721,8 +1746,9 @@ class Timeline: rows = 0 # total timeline rows rowlines = dict() rowheight = dict() - def __init__(self, rowheight): + def __init__(self, rowheight, scaleheight): self.rowH = rowheight + self.scaleH = scaleheight self.html = { 'header': '', 'timeline': '', @@ -1921,7 +1947,6 @@ class Timeline: # A list of values describing the properties of these test runs class TestProps: stamp = '' - tracertype = '' S0i3 = False fwdata = [] ftrace_line_fmt_fg = \ @@ -1939,14 +1964,13 @@ class TestProps: def __init__(self): self.ktemp = dict() def setTracerType(self, tracer): - self.tracertype = tracer if(tracer == 'function_graph'): self.cgformat = True self.ftrace_line_fmt = self.ftrace_line_fmt_fg elif(tracer == 'nop'): self.ftrace_line_fmt = self.ftrace_line_fmt_nop else: - doError('Invalid tracer format: [%s]' % tracer, False) + doError('Invalid tracer format: [%s]' % tracer) # Class: TestRun # Description: @@ -1995,7 +2019,6 @@ class ProcessMonitor: out += '%s-%s %d' % (val['name'], pid, jiffies) return 'ps - '+out def processMonitor(self, tid): - global sysvals while self.running: out = self.procstat() if out: @@ -2015,7 +2038,7 @@ class ProcessMonitor: # Arguments: # msg: the debug/log message to print def vprint(msg): - global sysvals + sysvals.logmsg += msg+'\n' if(sysvals.verbose): print(msg) @@ -2026,8 +2049,6 @@ def vprint(msg): # Arguments: # m: the valid re.match output for the stamp line 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')), @@ -2076,8 +2097,6 @@ def diffStamp(stamp1, stamp2): # required for primary parsing. Set the usetraceevents and/or # usetraceeventsonly flags in the global sysvals object def doesTraceLogHaveTraceEvents(): - global sysvals - # check for kprobes sysvals.usekprobes = False out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True) @@ -2120,8 +2139,6 @@ def doesTraceLogHaveTraceEvents(): # Arguments: # testruns: the array of Data objects obtained from parseKernelLog def appendIncompleteTraceLog(testruns): - global sysvals - # create TestRun vessels for ftrace parsing testcnt = len(testruns) testidx = 0 @@ -2312,8 +2329,7 @@ def appendIncompleteTraceLog(testruns): dev['ftrace'] = cg break - if(sysvals.verbose): - test.data.printDetails() + test.data.printDetails() # Function: parseTraceLog # Description: @@ -2324,11 +2340,9 @@ def appendIncompleteTraceLog(testruns): # Output: # An array of Data objects def parseTraceLog(): - global sysvals - vprint('Analyzing the ftrace data...') if(os.path.exists(sysvals.ftracefile) == False): - doError('%s does not exist' % sysvals.ftracefile, False) + doError('%s does not exist' % sysvals.ftracefile) sysvals.setupAllKprobes() tracewatch = [] @@ -2398,10 +2412,6 @@ def parseTraceLog(): testrun = TestRun(data) testruns.append(testrun) parseStamp(tp.stamp, data) - if sysvals.suspendmode == 'mem' and 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) data.tKernSus = t.time continue @@ -2427,6 +2437,11 @@ def parseTraceLog(): data.tKernRes = t.time if data.dmesg['resume_complete']['end'] < 0: data.dmesg['resume_complete']['end'] = t.time + if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber: + data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber] + if(data.tSuspended != 0 and data.tResumed != 0 and \ + (data.fwSuspend > 0 or data.fwResume > 0)): + data.fwValid = True if(not sysvals.usetracemarkers): # no trace markers? then quit and be sure to finish recording # the event we used to trigger resume end @@ -2713,9 +2728,8 @@ def parseTraceLog(): cg.newActionFromFunction(data) if sysvals.suspendmode == 'command': - if(sysvals.verbose): - for data in testdata: - data.printDetails() + for data in testdata: + data.printDetails() return testdata # fill in any missing phases @@ -2723,7 +2737,7 @@ def parseTraceLog(): lp = data.phases[0] for p in data.phases: if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): - print('WARNING: phase "%s" is missing!' % p) + vprint('WARNING: phase "%s" is missing!' % p) if(data.dmesg[p]['start'] < 0): data.dmesg[p]['start'] = data.dmesg[lp]['end'] if(p == 'resume_machine'): @@ -2732,6 +2746,8 @@ def parseTraceLog(): data.tLow = 0 if(data.dmesg[p]['end'] < 0): data.dmesg[p]['end'] = data.dmesg[p]['start'] + if(p != lp and not ('machine' in p and 'machine' in lp)): + data.dmesg[lp]['end'] = data.dmesg[p]['start'] lp = p if(len(sysvals.devicefilter) > 0): @@ -2739,8 +2755,7 @@ def parseTraceLog(): data.fixupInitcallsThatDidntReturn() if sysvals.usedevsrc: data.optimizeDevSrc() - if sysvals.verbose: - data.printDetails() + data.printDetails() # x2: merge any overlapping devices between test runs if sysvals.usedevsrc and len(testdata) > 1: @@ -2752,50 +2767,6 @@ def parseTraceLog(): testdata[0].stitchTouchingThreads(testdata[1:]) 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[0-9\.]*)(\]) (?P.*)', 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[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) - if(m): - stamp['kernel'] = m.group('k') - m = re.match('PM: Preparing system for (?P.*) 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] @@ -2803,15 +2774,16 @@ def loadRawKernelLog(dmesgfile): # The dmesg filename is taken from sysvals # Output: # An array of empty Data objects with only their dmesgtext attributes set -def loadKernelLog(): - global sysvals - +def loadKernelLog(justtext=False): vprint('Analyzing the dmesg data...') if(os.path.exists(sysvals.dmesgfile) == False): - doError('%s does not exist' % sysvals.dmesgfile, False) + doError('%s does not exist' % sysvals.dmesgfile) + if justtext: + dmesgtext = [] # there can be multiple test runs in a single file tp = TestProps() + tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown') testruns = [] data = 0 lf = open(sysvals.dmesgfile, 'r') @@ -2832,6 +2804,9 @@ def loadKernelLog(): if(not m): continue msg = m.group("msg") + if justtext: + dmesgtext.append(line) + continue if(re.match('PM: Syncing filesystems.*', msg)): if(data): testruns.append(data) @@ -2841,24 +2816,24 @@ def loadKernelLog(): 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 + m = re.match('.* *(?P[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) + if(m): + sysvals.stamp['kernel'] = m.group('k') + m = re.match('PM: Preparing system for (?P.*) sleep', msg) + if(m): + sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m') data.dmesgtext.append(line) - if(data): - testruns.append(data) lf.close() - 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) + if justtext: + return dmesgtext + if data: + testruns.append(data) + if len(testruns) < 1: + doError(' dmesg log has no suspend/resume data: %s' \ + % sysvals.dmesgfile) # fix lines with same timestamp/function with the call and return swapped for data in testruns: @@ -2890,8 +2865,6 @@ def loadKernelLog(): # Output: # The filled Data object def parseKernelLog(data): - global sysvals - phase = 'suspend_runtime' if(data.fwValid): @@ -2949,7 +2922,6 @@ def parseKernelLog(data): prevktime = -1.0 actions = dict() for line in data.dmesgtext: - # -- preprocessing -- # parse each dmesg line into the time and message m = re.match('[ \t]*(\[ *)(?P[0-9\.]*)(\]) (?P.*)', line) if(m): @@ -2957,8 +2929,6 @@ def parseKernelLog(data): try: ktime = float(val) except: - doWarning('INVALID DMESG LINE: '+\ - line.replace('\n', ''), 'dmesg') continue msg = m.group('msg') # initialize data start to first line time @@ -2976,12 +2946,12 @@ def parseKernelLog(data): phase = 'resume_noirq' data.dmesg[phase]['start'] = ktime - # -- phase changes -- # suspend start if(re.match(dm['suspend_prepare'], msg)): phase = 'suspend_prepare' data.dmesg[phase]['start'] = ktime data.setStart(ktime) + data.tKernSus = ktime # suspend start elif(re.match(dm['suspend'], msg)): data.dmesg['suspend_prepare']['end'] = ktime @@ -3038,7 +3008,7 @@ def parseKernelLog(data): elif(re.match(dm['post_resume'], msg)): data.dmesg['resume_complete']['end'] = ktime data.setEnd(ktime) - phase = 'post_resume' + data.tKernRes = ktime break # -- device callbacks -- @@ -3065,7 +3035,6 @@ def parseKernelLog(data): dev['length'] = int(t) dev['end'] = ktime - # -- non-devicecallback actions -- # if trace events are not available, these are better than nothing if(not sysvals.usetraceevents): # look for known actions @@ -3125,8 +3094,7 @@ def parseKernelLog(data): for event in actions[name]: data.newActionGlobal(name, event['begin'], event['end']) - if(sysvals.verbose): - data.printDetails() + data.printDetails() if(len(sysvals.devicefilter) > 0): data.deviceFilter(sysvals.devicefilter) data.fixupInitcallsThatDidntReturn() @@ -3138,8 +3106,6 @@ def parseKernelLog(data): # Arguments: # testruns: array of Data objects from parseTraceLog def createHTMLSummarySimple(testruns, htmlfile): - global sysvals - # print out the basic summary of all the tests hf = open(htmlfile, 'w') @@ -3264,7 +3230,6 @@ def createHTMLSummarySimple(testruns, htmlfile): hf.close() def htmlTitle(): - global sysvals modename = { 'freeze': 'Freeze (S0)', 'standby': 'Standby (S1)', @@ -3297,13 +3262,14 @@ def ordinal(value): # Output: # True if the html file was created, false if it failed def createHTML(testruns): - global sysvals - if len(testruns) < 1: print('ERROR: Not enough test data to build a timeline') return + kerror = False for data in testruns: + if data.kerror: + kerror = True data.normalizeTime(testruns[-1].tSuspended) x2changes = ['', 'absolute'] @@ -3318,6 +3284,7 @@ def createHTML(testruns): html_timeline = '
\n
\n' html_tblock = '
\n' html_device = '
{6}
\n' + html_error = '
ERROR→
\n' html_traceevent = '
{5}
\n' html_cpuexec = '
\n' html_phase = '
{5}
\n' @@ -3347,11 +3314,16 @@ def createHTML(testruns): hoverZ = 'z-index:8;' if sysvals.usedevsrc: hoverZ = '' + scaleH = 20 + scaleTH = 20 + if kerror: + scaleH = 40 + scaleTH = 60 # device timeline vprint('Creating Device Timeline...') - devtl = Timeline(30) + devtl = Timeline(30, scaleH) # Generate the header for this timeline for data in testruns: @@ -3415,7 +3387,6 @@ def createHTML(testruns): # time scale for potentially multiple datasets t0 = testruns[0].start tMax = testruns[-1].end - tSuspended = testruns[-1].tSuspended tTotal = tMax - t0 # determine the maximum number of rows we need to draw @@ -3507,6 +3478,11 @@ def createHTML(testruns): devtl.html['timeline'] += html_phase.format(left, width, \ '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ data.dmesg[b]['color'], '') + for e in data.errorinfo[dir]: + # draw red lines for any kernel errors found + t, err = e + right = '%f' % (((mMax-t)*100.0)/mTotal) + devtl.html['timeline'] += html_error.format(right, err) for b in sorted(phases[dir]): # draw the devices for this phase phaselist = data.dmesg[b]['list'] @@ -3623,8 +3599,7 @@ def createHTML(testruns): 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\ + cS {font:bold 13px 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\ @@ -3655,7 +3630,8 @@ def createHTML(testruns): .traceevent:hover {color:white;font-weight:bold;border:1px solid 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;pointer-events:none;top:0%;height:100%;border-right:1px solid black;z-index:6;}\n\ + .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\ + .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\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\ @@ -3683,6 +3659,8 @@ def createHTML(testruns): # write the test title and general info header if(sysvals.stamp['time'] != ""): hf.write(headline_version) + if sysvals.logmsg: + hf.write('') if sysvals.addlogs and sysvals.dmesgfile: hf.write('') if sysvals.addlogs and sysvals.ftracefile: @@ -3718,7 +3696,10 @@ def createHTML(testruns): hf.write('
\n') # write the ftrace data (callgraph) - data = testruns[-1] + if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest: + data = testruns[sysvals.cgtest] + else: + data = testruns[-1] if(sysvals.usecallgraph and not sysvals.embedded): hf.write('
\n') # write out the ftrace data converted to html @@ -3728,6 +3709,8 @@ def createHTML(testruns): html_func_leaf = '
{0} {1}
\n' num = 0 for p in data.phases: + if sysvals.cgphase and p != sysvals.cgphase: + continue list = data.dmesg[p]['list'] for devname in data.sortedDevices(p): if('ftrace' not in list[devname]): @@ -3765,11 +3748,15 @@ def createHTML(testruns): hf.write(html_func_end) hf.write('\n\n
\n') + # add the test log as a hidden div + if sysvals.logmsg: + hf.write('\n') # add the dmesg log as a hidden div if sysvals.addlogs and sysvals.dmesgfile: hf.write('\n') @@ -3822,7 +3809,7 @@ def addScriptCode(hf, testruns): ' var resolution = -1;\n'\ ' var dragval = [0, 0];\n'\ ' function redrawTimescale(t0, tMax, tS) {\n'\ - ' var rline = \'
<-R
\';\n'\ + ' var rline = \'
←R
\';\n'\ ' var tTotal = tMax - t0;\n'\ ' var list = document.getElementsByClassName("tblock");\n'\ ' for (var i = 0; i < list.length; i++) {\n'\ @@ -3847,7 +3834,7 @@ def addScriptCode(hf, testruns): ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\ ' val = (j-divTotal+1)*tS;\n'\ ' if(j == divTotal - 1)\n'\ - ' htmlline = \'
S->
\';\n'\ + ' htmlline = \'
S→
\';\n'\ ' else\n'\ ' htmlline = \'
\'+val+\'ms
\';\n'\ ' }\n'\ @@ -4027,12 +4014,7 @@ def addScriptCode(hf, testruns): ' }\n'\ ' }\n'\ ' function devListWindow(e) {\n'\ - ' var sx = e.clientX;\n'\ - ' if(sx > window.innerWidth - 440)\n'\ - ' sx = window.innerWidth - 440;\n'\ - ' var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\ - ' var win = window.open("", "_blank", cfg);\n'\ - ' if(window.chrome) win.moveBy(sx, 0);\n'\ + ' var win = window.open();\n'\ ' var html = ""+e.target.innerHTML+""+\n'\ ' "