diff options
author | Todd Brandt | 2020-07-20 18:02:49 -0700 |
---|---|---|
committer | Rafael J. Wysocki | 2020-07-27 13:03:36 +0200 |
commit | 68f9b22842897087895230964776083e168415de (patch) | |
tree | fb99c9759dfda803494f6502c572be30a8489e66 | |
parent | 671be01ca28456d8ce8d7f59e7fdcb1e05571322 (diff) |
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_<n>x". It denotes an s2idle_enter call
loop of <n> 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 <todd.e.brandt@linux.intel.com>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
-rw-r--r-- | tools/power/pm-graph/README | 2 | ||||
-rwxr-xr-x | tools/power/pm-graph/sleepgraph.py | 249 |
2 files changed, 149 insertions, 102 deletions
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 <todd.e.brandt@intel.com> 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<b>[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<ktime>[0-9\.]*)(\]) (?P<msg>.*)', 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<num>[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<e>.*)' sysinfofmt = '^# sysinfo .*' cmdlinefmt = '^# command \| (?P<cmd>.*)' + kparamsfmt = '^# kparams \| (?P<kp>.*)' devpropfmt = '# Device Properties: .*' pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9]*): (?P<info>.*)' tracertypefmt = '# tracer: (?P<t>.*)' @@ -2790,8 +2808,9 @@ class TestProps: '[ +!#\*@$]*(?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<flags>\S*) *(?P<time>[0-9\.]*): *'+\ '(?P<msg>.*)' + machinesuspend = 'machine_suspend\[.*' def __init__(self): self.stamp = '' self.sysinfo = '' @@ -2812,16 +2831,13 @@ class TestProps: self.ftrace_line_fmt = self.ftrace_line_fmt_nop else: doError('Invalid tracer format: [%s]' % tracer) - def stampInfo(self, line): + def stampInfo(self, line, sv): if re.match(self.stampfmt, line): self.stamp = line return True elif re.match(self.sysinfofmt, line): self.sysinfo = line return True - elif re.match(self.cmdlinefmt, line): - self.cmdline = line - return True elif re.match(self.tstatfmt, line): self.turbostat.append(line) return True @@ -2834,6 +2850,20 @@ class TestProps: elif re.match(self.firmwarefmt, line): self.fwdata.append(line) return True + elif(re.match(self.devpropfmt, line)): + self.parseDevprops(line, sv) + return True + elif(re.match(self.pinfofmt, line)): + self.parsePlatformInfo(line, sv) + return True + m = re.match(self.cmdlinefmt, line) + if m: + self.cmdline = m.group('cmd') + return True + m = re.match(self.tracertypefmt, line) + if(m): + self.setTracerType(m.group('t')) + return True return False def parseStamp(self, data, sv): # global test data @@ -2858,9 +2888,13 @@ class TestProps: data.stamp[key] = val sv.hostname = data.stamp['host'] sv.suspendmode = data.stamp['mode'] + if sv.suspendmode == 'freeze': + self.machinesuspend = 'timekeeping_freeze\[.*' + else: + self.machinesuspend = 'machine_suspend\[.*' if sv.suspendmode == 'command' and sv.ftracefile != '': modes = ['on', 'freeze', 'standby', 'mem', 'disk'] - fp = sysvals.openlog(sv.ftracefile, 'r') + fp = sv.openlog(sv.ftracefile, 'r') for line in fp: m = re.match('.* machine_suspend\[(?P<mode>.*)\]', line) if m and m.group('mode') in ['1', '2', '3', '4']: @@ -2868,9 +2902,7 @@ class TestProps: data.stamp['mode'] = sv.suspendmode break fp.close() - m = re.match(self.cmdlinefmt, self.cmdline) - if m: - sv.cmdline = m.group('cmd') + sv.cmdline = self.cmdline if not sv.stamp: sv.stamp = data.stamp # firmware data @@ -3052,20 +3084,7 @@ def appendIncompleteTraceLog(testruns): for line in tf: # remove any latent carriage returns line = line.replace('\r\n', '') - if tp.stampInfo(line): - continue - # determine the trace data type (required for further parsing) - m = re.match(tp.tracertypefmt, line) - if(m): - tp.setTracerType(m.group('t')) - continue - # device properties line - if(re.match(tp.devpropfmt, line)): - tp.parseDevprops(line, sysvals) - continue - # platform info line - if(re.match(tp.pinfofmt, line)): - tp.parsePlatformInfo(line, sysvals) + if tp.stampInfo(line, sysvals): continue # parse only valid lines, if this is not one move on m = re.match(tp.ftrace_line_fmt, line) @@ -3166,33 +3185,19 @@ def parseTraceLog(live=False): if sysvals.usekprobes: tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', - 'CPU_OFF', 'timekeeping_freeze', 'acpi_suspend'] + 'CPU_OFF', 'acpi_suspend'] # extract the callgraph and traceevent data + s2idle_enter = hwsus = False tp = TestProps() - testruns = [] - testdata = [] - testrun = 0 - data, limbo = 0, True + testruns, testdata = [], [] + testrun, data, limbo = 0, 0, True tf = sysvals.openlog(sysvals.ftracefile, 'r') phase = 'suspend_prepare' for line in tf: # remove any latent carriage returns line = line.replace('\r\n', '') - if tp.stampInfo(line): - continue - # tracer type line: determine the trace data type - m = re.match(tp.tracertypefmt, line) - if(m): - tp.setTracerType(m.group('t')) - continue - # device properties line - if(re.match(tp.devpropfmt, line)): - tp.parseDevprops(line, sysvals) - continue - # platform info line - if(re.match(tp.pinfofmt, line)): - tp.parsePlatformInfo(line, sysvals) + if tp.stampInfo(line, sysvals): continue # ignore all other commented lines if line[0] == '#': @@ -3303,16 +3308,29 @@ def parseTraceLog(live=False): phase = data.setPhase('suspend_noirq', t.time, isbegin) continue # suspend_machine/resume_machine - elif(re.match('machine_suspend\[.*', t.name)): + elif(re.match(tp.machinesuspend, t.name)): + lp = data.lastPhase() if(isbegin): - lp = data.lastPhase() + hwsus = True if lp.startswith('resume_machine'): - data.dmesg[lp]['end'] = t.time + # trim out s2idle loops, track time trying to freeze + llp = data.lastPhase(2) + if llp.startswith('suspend_machine'): + if 'trying' not in data.dmesg[llp]: + data.dmesg[llp]['trying'] = 0 + data.dmesg[llp]['trying'] += \ + t.time - data.dmesg[lp]['start'] + data.currphase = '' + del data.dmesg[lp] + continue phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True) data.setPhase(phase, t.time, False) if data.tSuspended == 0: data.tSuspended = t.time else: + if lp.startswith('resume_machine'): + data.dmesg[lp]['end'] = t.time + continue phase = data.setPhase('resume_machine', t.time, True) if(sysvals.suspendmode in ['mem', 'disk']): susp = phase.replace('resume', 'suspend') @@ -3343,6 +3361,19 @@ def parseTraceLog(live=False): # global events (outside device calls) are graphed if(name not in testrun.ttemp): testrun.ttemp[name] = [] + # special handling for s2idle_enter + if name == 'machine_suspend': + if hwsus: + s2idle_enter = hwsus = False + elif s2idle_enter and not isbegin: + if(len(testrun.ttemp[name]) > 0): + testrun.ttemp[name][-1]['end'] = t.time + testrun.ttemp[name][-1]['loop'] += 1 + elif not s2idle_enter and isbegin: + s2idle_enter = True + testrun.ttemp[name].append({'begin': t.time, + 'end': t.time, 'pid': pid, 'loop': 0}) + continue if(isbegin): # create a new list entry testrun.ttemp[name].append(\ @@ -3374,9 +3405,8 @@ def parseTraceLog(live=False): if(not m): continue n = m.group('d') - list = data.dmesg[phase]['list'] - if(n in list): - dev = list[n] + dev = data.findDevice(phase, n) + if dev: dev['length'] = t.time - dev['start'] dev['end'] = t.time # kprobe event processing @@ -3479,7 +3509,12 @@ def parseTraceLog(live=False): # add actual trace funcs for name in sorted(test.ttemp): for event in test.ttemp[name]: - data.newActionGlobal(name, event['begin'], event['end'], event['pid']) + if event['end'] - event['begin'] <= 0: + continue + title = name + if name == 'machine_suspend' and 'loop' in event: + title = 's2idle_enter_%dx' % event['loop'] + data.newActionGlobal(title, event['begin'], event['end'], event['pid']) # add the kprobe based virtual tracefuncs as actual devices for key in sorted(tp.ktemp): name, pid = key @@ -3548,8 +3583,9 @@ def parseTraceLog(live=False): for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): if p not in data.dmesg: if not terr: - pprint('TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)) - terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp) + ph = p if 'machine' in p else lp + terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph) + pprint('TEST%s FAILED: %s' % (tn, terr)) error.append(terr) if data.tSuspended == 0: data.tSuspended = data.dmesg[lp]['end'] @@ -3611,7 +3647,7 @@ def loadKernelLog(): idx = line.find('[') if idx > 1: line = line[idx:] - if tp.stampInfo(line): + if tp.stampInfo(line, sysvals): continue m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if(not m): @@ -3959,18 +3995,20 @@ def addCallgraphs(sv, hf, data): if sv.cgphase and p != sv.cgphase: continue list = data.dmesg[p]['list'] - for devname in data.sortedDevices(p): - if len(sv.cgfilter) > 0 and devname not in sv.cgfilter: + for d in data.sortedDevices(p): + if len(sv.cgfilter) > 0 and d not in sv.cgfilter: continue - dev = list[devname] + dev = list[d] color = 'white' if 'color' in data.dmesg[p]: color = data.dmesg[p]['color'] if 'color' in dev: color = dev['color'] - name = devname - if(devname in sv.devprops): - name = sv.devprops[devname].altName(devname) + name = d if '[' not in d else d.split('[')[0] + if(d in sv.devprops): + name = sv.devprops[d].altName(d) + if 'drv' in dev and dev['drv']: + name += ' {%s}' % dev['drv'] if sv.suspendmode in suspendmodename: name += ' '+p if('ftrace' in dev): @@ -4517,12 +4555,9 @@ def createHTML(testruns, testfail): # draw the devices for this phase phaselist = data.dmesg[b]['list'] for d in sorted(data.tdevlist[b]): - name = d - drv = '' - dev = phaselist[d] - xtraclass = '' - xtrainfo = '' - xtrastyle = '' + dname = d if '[' not in d else d.split('[')[0] + name, dev = dname, phaselist[d] + drv = xtraclass = xtrainfo = xtrastyle = '' if 'htmlclass' in dev: xtraclass = dev['htmlclass'] if 'color' in dev: @@ -4553,7 +4588,7 @@ def createHTML(testruns, testfail): title += b devtl.html += devtl.html_device.format(dev['id'], \ title, left, top, '%.3f'%rowheight, width, \ - d+drv, xtraclass, xtrastyle) + dname+drv, xtraclass, xtrastyle) if('cpuexec' in dev): for t in sorted(dev['cpuexec']): start, end = t @@ -4571,6 +4606,8 @@ def createHTML(testruns, testfail): continue # draw any trace events for this device for e in dev['src']: + if e.length == 0: + continue height = '%.3f' % devtl.rowH top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH)) left = '%f' % (((e.time-m0)*100)/mTotal) @@ -5876,7 +5913,7 @@ def getArgFloat(name, args, min, max, main=True): def processData(live=False, quiet=False): if not quiet: - pprint('PROCESSING DATA') + pprint('PROCESSING: %s' % sysvals.htmlfile) sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \ (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes)) error = '' @@ -5928,7 +5965,7 @@ def processData(live=False, quiet=False): sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) createHTML(testruns, error) if not quiet: - pprint('DONE') + pprint('DONE: %s' % sysvals.htmlfile) data = testruns[0] stamp = data.stamp stamp['suspend'], stamp['resume'] = data.getTimeValues() @@ -5984,25 +6021,27 @@ def runTest(n=0, quiet=False): return 0 def find_in_html(html, start, end, firstonly=True): - n, cnt, out = 0, len(html), [] - while n < cnt: - e = cnt if (n + 10000 > cnt or n == 0) else n + 10000 - m = re.search(start, html[n:e]) - if not m: - break - i = m.end() - m = re.search(end, html[n+i:e]) + cnt, out, list = len(html), [], [] + if firstonly: + m = re.search(start, html) + if m: + list.append(m) + else: + list = re.finditer(start, html) + for match in list: + s = match.end() + e = cnt if (len(out) < 1 or s + 10000 > cnt) else s + 10000 + m = re.search(end, html[s:e]) if not m: break - j = m.start() - str = html[n+i:n+i+j] + e = s + m.start() + str = html[s:e] if end == 'ms': num = re.search(r'[-+]?\d*\.\d+|\d+', str) str = num.group() if num else 'NaN' if firstonly: return str out.append(str) - n += i+j if firstonly: return '' return out @@ -6034,7 +6073,7 @@ def data_from_html(file, outpath, issues, fulldetail=False): else: result = 'pass' # extract error info - ilist = [] + tp, ilist = False, [] extra = dict() log = find_in_html(html, '<div id="dmesglog" style="display:none;">', '</div>').strip() @@ -6042,8 +6081,8 @@ def data_from_html(file, outpath, issues, fulldetail=False): d = Data(0) d.end = 999999999 d.dmesgtext = log.split('\n') - msglist = d.extractErrorInfo() - for msg in msglist: + tp = d.extractErrorInfo() + for msg in tp.msglist: sysvals.errorSummary(issues, msg) if stmp[2] == 'freeze': extra = d.turbostatInfo() @@ -6059,8 +6098,8 @@ def data_from_html(file, outpath, issues, fulldetail=False): if wifi: extra['wifi'] = wifi low = find_in_html(html, 'freeze time: <b>', ' ms</b>') - if low and '|' in low: - issue = 'FREEZEx%d' % len(low.split('|')) + if low and 'waking' in low: + issue = 'FREEZEWAKE' match = [i for i in issues if i['match'] == issue] if len(match) > 0: match[0]['count'] += 1 @@ -6126,6 +6165,11 @@ def data_from_html(file, outpath, issues, fulldetail=False): data[key] = extra[key] if fulldetail: data['funclist'] = find_in_html(html, '<div title="', '" class="traceevent"', False) + if tp: + for arg in ['-multi ', '-info ']: + if arg in tp.cmdline: + data['target'] = tp.cmdline[tp.cmdline.find(arg):].split()[1] + break return data def genHtml(subdir, force=False): @@ -6155,8 +6199,7 @@ def runSummary(subdir, local=True, genhtml=False): pprint('Generating a summary of folder:\n %s' % inpath) if genhtml: genHtml(subdir) - issues = [] - testruns = [] + target, issues, testruns = '', [], [] desc = {'host':[],'mode':[],'kernel':[]} for dirname, dirnames, filenames in os.walk(subdir): for filename in filenames: @@ -6165,6 +6208,8 @@ def runSummary(subdir, local=True, genhtml=False): data = data_from_html(os.path.join(dirname, filename), outpath, issues) if(not data): continue + if 'target' in data: + target = data['target'] testruns.append(data) for key in desc: if data[key] not in desc[key]: @@ -6172,6 +6217,8 @@ def runSummary(subdir, local=True, genhtml=False): pprint('Summary files:') if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1: title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0]) + if target: + title += ' %s' % target else: title = inpath createHTMLSummarySimple(testruns, os.path.join(outpath, 'summary.html'), title) |