From 68f9b22842897087895230964776083e168415de Mon Sep 17 00:00:00 2001 From: Todd Brandt Date: Mon, 20 Jul 2020 18:02:49 -0700 Subject: pm-graph v5.7 - important s2idle fixes Important fixes: - in s2idle, use timekeeping_freeze trace mark instead of machine_suspend to denote entry into s2idle mode. - in s2idle, use machine_suspend trace mark to create a new virtual device called "s2idle_enter_x". It denotes an s2idle_enter call loop of iterations where s2idle was never actually achieved. It isn't counted as "freeze time" in the header. - in s2idle, only show multiple freeze times if s2idle went in and out of resume_noirq. Otherwise multiple freezes are shown with "waking" time subtracted (waking time is time spent outside s2idle dealing with wakeups). - in s2idle summaries, include "FREEZEWAKE" as an issue when at least 1ms is spent waking from s2idle. A clean run should only wake for the rtc timer. - add support for device callbacks with matching names in the same phase. In rare cases some devices register multiple callbacks from separate drivers using the same name. Without this fix only one is shown. - add kparamsfmt string back to fix bootgraph General updates: - when suspend_machine is missing, error says "failed in suspend_machine" - extract target count/time and add to summary title if -multi used - include any instances of "timeout" in dmesg as issues to be logged. - fix ftrace parse to handle any number of flags (instead of just 4). - remove sync/async_device string from device detail, remains in hover. - when using callgraph (-f) add driver name to callgraph titles. Signed-off-by: Todd Brandt Signed-off-by: Rafael J. Wysocki --- tools/power/pm-graph/README | 2 +- tools/power/pm-graph/sleepgraph.py | 249 ++++++++++++++++++++++--------------- 2 files changed, 149 insertions(+), 102 deletions(-) (limited to 'tools') diff --git a/tools/power/pm-graph/README b/tools/power/pm-graph/README index afe6beb40ad9..89d0a7dab4bc 100644 --- a/tools/power/pm-graph/README +++ b/tools/power/pm-graph/README @@ -6,7 +6,7 @@ |_| |___/ |_| pm-graph: suspend/resume/boot timing analysis tools - Version: 5.6 + Version: 5.7 Author: Todd Brandt Home Page: https://01.org/pm-graph diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index 602e64b68ba7..46ff97e909c6 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -81,7 +81,7 @@ def ascii(text): # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.6' + version = '5.7' ansi = False rs = 0 display = '' @@ -198,7 +198,7 @@ class SystemValues: 'suspend_console': {}, 'acpi_pm_prepare': {}, 'syscore_suspend': {}, - 'arch_thaw_secondary_cpus_end': {}, + 'arch_enable_nonboot_cpus_end': {}, 'syscore_resume': {}, 'acpi_pm_finish': {}, 'resume_console': {}, @@ -924,10 +924,7 @@ class SystemValues: tp = TestProps() tf = self.openlog(self.ftracefile, 'r') for line in tf: - # determine the trace data type (required for further parsing) - m = re.match(tp.tracertypefmt, line) - if(m): - tp.setTracerType(m.group('t')) + if tp.stampInfo(line, self): continue # parse only valid lines, if this is not one move on m = re.match(tp.ftrace_line_fmt, line) @@ -1244,8 +1241,8 @@ class DevProps: if self.xtraclass: return ' '+self.xtraclass if self.isasync: - return ' async_device' - return ' sync_device' + return ' (async)' + return ' (sync)' # Class: DeviceNode # Description: @@ -1301,6 +1298,7 @@ class Data: 'FAIL' : r'(?i).*\bFAILED\b.*', 'INVALID' : r'(?i).*\bINVALID\b.*', 'CRASH' : r'(?i).*\bCRASHED\b.*', + 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*', 'IRQ' : r'.*\bgenirq: .*', 'TASKFAIL': r'.*Freezing of tasks *.*', 'ACPI' : r'.*\bACPI *(?P[A-Za-z]*) *Error[: ].*', @@ -1358,11 +1356,11 @@ class Data: if self.dmesg[p]['order'] == order: return p return '' - def lastPhase(self): + def lastPhase(self, depth=1): plist = self.sortedPhases() - if len(plist) < 1: + if len(plist) < depth: return '' - return plist[-1] + return plist[-1*depth] def turbostatInfo(self): tp = TestProps() out = {'syslpi':'N/A','pkgpc10':'N/A'} @@ -1382,9 +1380,12 @@ class Data: if len(self.dmesgtext) < 1 and sysvals.dmesgfile: lf = sysvals.openlog(sysvals.dmesgfile, 'r') i = 0 + tp = TestProps() list = [] for line in lf: i += 1 + if tp.stampInfo(line, sysvals): + continue m = re.match('[ \t]*(\[ *)(?P[0-9\.]*)(\]) (?P.*)', line) if not m: continue @@ -1400,15 +1401,15 @@ class Data: list.append((msg, err, dir, t, i, i)) self.kerror = True break - msglist = [] + tp.msglist = [] for msg, type, dir, t, idx1, idx2 in list: - msglist.append(msg) + tp.msglist.append(msg) self.errorinfo[dir].append((type, t, idx1, idx2)) if self.kerror: sysvals.dmesglog = True if len(self.dmesgtext) < 1 and sysvals.dmesgfile: lf.close() - return msglist + return tp def setStart(self, time, msg=''): self.start = time if msg: @@ -1623,6 +1624,8 @@ class Data: if('src' in d): for e in d['src']: e.time = self.trimTimeVal(e.time, t0, dT, left) + e.end = self.trimTimeVal(e.end, t0, dT, left) + e.length = e.end - e.time for dir in ['suspend', 'resume']: list = [] for e in self.errorinfo[dir]: @@ -1640,7 +1643,12 @@ class Data: if tL > 0: left = True if tR > tZero else False self.trimTime(tS, tL, left) - self.tLow.append('%.0f'%(tL*1000)) + if 'trying' in self.dmesg[lp] and self.dmesg[lp]['trying'] >= 0.001: + tTry = round(self.dmesg[lp]['trying'] * 1000) + text = '%.0f (-%.0f waking)' % (tL * 1000, tTry) + else: + text = '%.0f' % (tL * 1000) + self.tLow.append(text) lp = phase def getMemTime(self): if not self.hwstart or not self.hwend: @@ -1776,7 +1784,7 @@ class Data: length = -1.0 if(start >= 0 and end >= 0): length = end - start - if pid == -2: + if pid == -2 or name not in sysvals.tracefuncs.keys(): i = 2 origname = name while(name in list): @@ -1789,6 +1797,15 @@ class Data: if color: list[name]['color'] = color return name + def findDevice(self, phase, name): + list = self.dmesg[phase]['list'] + mydev = '' + for devname in sorted(list): + if name == devname or re.match('^%s\[(?P[0-9]*)\]$' % name, devname): + mydev = devname + if mydev: + return list[mydev] + return False def deviceChildren(self, devname, phase): devlist = [] list = self.dmesg[phase]['list'] @@ -2779,6 +2796,7 @@ class TestProps: testerrfmt = '^# enter_sleep_error (?P.*)' sysinfofmt = '^# sysinfo .*' cmdlinefmt = '^# command \| (?P.*)' + kparamsfmt = '^# kparams \| (?P.*)' devpropfmt = '# Device Properties: .*' pinfofmt = '# platform-(?P[a-z,A-Z,0-9]*): (?P.*)' tracertypefmt = '# tracer: (?P.*)' @@ -2790,8 +2808,9 @@ class TestProps: '[ +!#\*@$]*(?P[0-9\.]*) .*\| (?P.*)' ftrace_line_fmt_nop = \ ' *(?P.*)-(?P[0-9]*) *\[(?P[0-9]*)\] *'+\ - '(?P.{4}) *(?P