diff options
Diffstat (limited to 'tools/power/pm-graph')
| -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) |