* [PATCH 0/3] pm-graph 5.4
@ 2019-05-14 17:53 Todd Brandt
2019-05-14 17:53 ` [PATCH 1/3] Update to pm-graph 5.3 Todd Brandt
` (3 more replies)
0 siblings, 4 replies; 5+ messages in thread
From: Todd Brandt @ 2019-05-14 17:53 UTC (permalink / raw)
To: linux-pm, rafael.j.wysocki, rjw; +Cc: todd.e.brandt, todd.e.brandt
Considerable upgrades to the summary functionality, as well as
new sources of data from turbostat and mcelog. ACPI methods are now
traceable in the timeline as well in dev mode.
Todd Brandt (3):
Update to pm-graph 5.3
Update to pm-graph 5.4
pm-graph 5.4 config and other files
tools/power/pm-graph/README | 552 ++++++++++++++++++++
tools/power/pm-graph/bootgraph.py | 8 +-
tools/power/pm-graph/config/example.cfg | 26 +
tools/power/pm-graph/sleepgraph.8 | 16 +-
tools/power/pm-graph/sleepgraph.py | 857 ++++++++++++++++++++++++--------
5 files changed, 1253 insertions(+), 206 deletions(-)
create mode 100644 tools/power/pm-graph/README
--
2.14.1
^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH 1/3] Update to pm-graph 5.3
2019-05-14 17:53 [PATCH 0/3] pm-graph 5.4 Todd Brandt
@ 2019-05-14 17:53 ` Todd Brandt
2019-05-14 17:53 ` [PATCH 2/3] Update to pm-graph 5.4 Todd Brandt
` (2 subsequent siblings)
3 siblings, 0 replies; 5+ messages in thread
From: Todd Brandt @ 2019-05-14 17:53 UTC (permalink / raw)
To: linux-pm, rafael.j.wysocki, rjw; +Cc: todd.e.brandt, todd.e.brandt
sleepgraph:
- add support for parsing kernel issues from timeline dmesg logs
- with -summary, generate a summary-issues.html for kernel issues found
- with -summary, generate a summary-devices.html for device callback times
- when recreating a timeline, use -o to set the output html filename
- capture mcelog data when hardware errors occur and store in log
- add -turbostat option to capture power data during freeze
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
tools/power/pm-graph/sleepgraph.py | 496 ++++++++++++++++++++++++++++---------
1 file changed, 379 insertions(+), 117 deletions(-)
diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py
index 52618f3444d4..41d28d63e7c9 100755
--- a/tools/power/pm-graph/sleepgraph.py
+++ b/tools/power/pm-graph/sleepgraph.py
@@ -61,6 +61,7 @@ import ConfigParser
import gzip
from threading import Thread
from subprocess import call, Popen, PIPE
+import base64
def pprint(msg):
print(msg)
@@ -74,7 +75,7 @@ def pprint(msg):
# store system values and test parameters
class SystemValues:
title = 'SleepGraph'
- version = '5.2'
+ version = '5.3'
ansi = False
rs = 0
display = ''
@@ -199,6 +200,7 @@ class SystemValues:
'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},
+ 'rt_mutex_slowlock': {'ub': 1},
# ACPI
'acpi_resume_power_resources': {},
'acpi_ps_parse_aml': {},
@@ -344,10 +346,12 @@ class SystemValues:
m = info['baseboard-manufacturer']
elif 'system-manufacturer' in info:
m = info['system-manufacturer']
- if 'baseboard-product-name' in info:
- p = info['baseboard-product-name']
- elif 'system-product-name' in info:
+ if 'system-product-name' in info:
p = info['system-product-name']
+ elif 'baseboard-product-name' in info:
+ p = info['baseboard-product-name']
+ if m[:5].lower() == 'intel' and 'baseboard-product-name' in info:
+ p = info['baseboard-product-name']
if 'processor-version' in info:
c = info['processor-version']
if 'bios-version' in info:
@@ -688,7 +692,8 @@ class SystemValues:
if self.bufsize > 0:
tgtsize = self.bufsize
elif self.usecallgraph or self.usedevsrc:
- bmax = (1*1024*1024) if self.suspendmode == 'disk' else (3*1024*1024)
+ bmax = (1*1024*1024) if self.suspendmode in ['disk', 'command'] \
+ else (3*1024*1024)
tgtsize = min(self.memfree, bmax)
else:
tgtsize = 65536
@@ -776,6 +781,10 @@ class SystemValues:
fw = test['fw']
if(fw):
fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
+ if 'mcelog' in test:
+ fp.write('# mcelog %s\n' % test['mcelog'])
+ if 'turbo' in test:
+ fp.write('# turbostat %s\n' % test['turbo'])
if 'bat' in test:
(a1, c1), (a2, c2) = test['bat']
fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2))
@@ -829,6 +838,56 @@ class SystemValues:
if isgz:
return gzip.open(filename, mode+'b')
return open(filename, mode)
+ def mcelog(self, clear=False):
+ cmd = self.getExec('mcelog')
+ if not cmd:
+ return ''
+ if clear:
+ call(cmd+' > /dev/null 2>&1', shell=True)
+ return ''
+ fp = Popen([cmd], stdout=PIPE, stderr=PIPE).stdout
+ out = fp.read().strip()
+ fp.close()
+ if not out:
+ return ''
+ return base64.b64encode(out.encode('zlib'))
+ def haveTurbostat(self):
+ cmd = self.getExec('turbostat')
+ if not cmd:
+ return False
+ fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr
+ out = fp.read().strip()
+ fp.close()
+ return re.match('turbostat version [0-8.]* .*', out)
+ def turbostat(self):
+ cmd = self.getExec('turbostat')
+ if not cmd:
+ return 'missing turbostat executable'
+ outfile = '/tmp/pm-graph-turbostat.txt'
+ res = call('%s -o %s -q -S echo freeze > %s' % \
+ (cmd, outfile, self.powerfile), shell=True)
+ if res != 0:
+ return 'turbosat returned %d' % res
+ if not os.path.exists(outfile):
+ return 'turbostat output missing'
+ fp = open(outfile, 'r')
+ text = []
+ for line in fp:
+ if re.match('[0-9.]* sec', line):
+ continue
+ text.append(line.split())
+ fp.close()
+ if len(text) < 2:
+ return 'turbostat output format error'
+ out = []
+ for key in text[0]:
+ values = []
+ idx = text[0].index(key)
+ for line in text[1:]:
+ if len(line) > idx:
+ values.append(line[idx])
+ out.append('%s=%s' % (key, ','.join(values)))
+ return '|'.join(out)
sysvals = SystemValues()
switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
@@ -941,6 +1000,8 @@ class Data:
self.outfile = ''
self.kerror = False
self.battery = 0
+ self.turbostat = 0
+ self.mcelog = 0
self.enterfail = ''
self.currphase = ''
self.pstl = dict() # process timeline
@@ -975,8 +1036,38 @@ class Data:
if len(plist) < 1:
return ''
return plist[-1]
- def extractErrorInfo(self):
- lf = sysvals.openlog(sysvals.dmesgfile, 'r')
+ def errorSummary(self, errinfo, msg):
+ found = False
+ for entry in errinfo:
+ if re.match(entry['match'], msg):
+ entry['count'] += 1
+ if sysvals.hostname not in entry['urls']:
+ entry['urls'][sysvals.hostname] = sysvals.htmlfile
+ found = True
+ break
+ if found:
+ return
+ arr = msg.split()
+ for j in range(len(arr)):
+ if re.match('^[0-9\-\.]*$', arr[j]):
+ arr[j] = '[0-9\-\.]*'
+ else:
+ arr[j] = arr[j]\
+ .replace(']', '\]').replace('[', '\[').replace('.', '\.')\
+ .replace('+', '\+').replace('*', '\*').replace('(', '\(')\
+ .replace(')', '\)')
+ mstr = ' '.join(arr)
+ entry = {
+ 'line': msg,
+ 'match': mstr,
+ 'count': 1,
+ 'urls': {sysvals.hostname: sysvals.htmlfile}
+ }
+ errinfo.append(entry)
+ def extractErrorInfo(self, issues=0):
+ lf = self.dmesgtext
+ if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
+ lf = sysvals.openlog(sysvals.dmesgfile, 'r')
i = 0
list = []
for line in lf:
@@ -993,6 +1084,8 @@ class Data:
if re.match(self.errlist[err], msg):
list.append((err, dir, t, i, i))
self.kerror = True
+ if not isinstance(issues, int):
+ self.errorSummary(issues, msg)
break
for e in list:
type, dir, t, idx1, idx2 = e
@@ -1000,7 +1093,8 @@ class Data:
self.errorinfo[dir].append((type, t, idx1, idx2))
if self.kerror:
sysvals.dmesglog = True
- lf.close()
+ if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
+ lf.close()
def setStart(self, time):
self.start = time
def setEnd(self, time):
@@ -2358,6 +2452,8 @@ class TestProps:
'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)'
+ tstatfmt = '^# turbostat (?P<t>\S*)'
+ mcelogfmt = '^# mcelog (?P<m>\S*)'
testerrfmt = '^# enter_sleep_error (?P<e>.*)'
sysinfofmt = '^# sysinfo .*'
cmdlinefmt = '^# command \| (?P<cmd>.*)'
@@ -2380,6 +2476,8 @@ class TestProps:
self.cmdline = ''
self.kparams = ''
self.testerror = []
+ self.mcelog = []
+ self.turbostat = []
self.battery = []
self.fwdata = []
self.ftrace_line_fmt = self.ftrace_line_fmt_nop
@@ -2394,6 +2492,38 @@ class TestProps:
self.ftrace_line_fmt = self.ftrace_line_fmt_nop
else:
doError('Invalid tracer format: [%s]' % tracer)
+ def decode(self, data):
+ try:
+ out = base64.b64decode(data).decode('zlib')
+ except:
+ out = data
+ return out
+ def stampInfo(self, line):
+ 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.mcelogfmt, line):
+ self.mcelog.append(line)
+ return True
+ elif re.match(self.tstatfmt, line):
+ self.turbostat.append(line)
+ return True
+ elif re.match(self.batteryfmt, line):
+ self.battery.append(line)
+ return True
+ elif re.match(self.testerrfmt, line):
+ self.testerror.append(line)
+ return True
+ elif re.match(self.firmwarefmt, line):
+ self.fwdata.append(line)
+ return True
+ return False
def parseStamp(self, data, sv):
# global test data
m = re.match(self.stampfmt, self.stamp)
@@ -2436,9 +2566,21 @@ class TestProps:
sv.stamp = data.stamp
# firmware data
if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber:
- data.fwSuspend, data.fwResume = self.fwdata[data.testnumber]
- if(data.fwSuspend > 0 or data.fwResume > 0):
- data.fwValid = True
+ m = re.match(self.firmwarefmt, self.fwdata[data.testnumber])
+ if m:
+ data.fwSuspend, data.fwResume = int(m.group('s')), int(m.group('r'))
+ if(data.fwSuspend > 0 or data.fwResume > 0):
+ data.fwValid = True
+ # mcelog data
+ if len(self.mcelog) > data.testnumber:
+ m = re.match(self.mcelogfmt, self.mcelog[data.testnumber])
+ if m:
+ data.mcelog = self.decode(m.group('m'))
+ # turbostat data
+ if len(self.turbostat) > data.testnumber:
+ m = re.match(self.tstatfmt, self.turbostat[data.testnumber])
+ if m:
+ data.turbostat = m.group('t')
# battery data
if len(self.battery) > data.testnumber:
m = re.match(self.batteryfmt, self.battery[data.testnumber])
@@ -2564,21 +2706,7 @@ def appendIncompleteTraceLog(testruns):
for line in tf:
# remove any latent carriage returns
line = line.replace('\r\n', '')
- # grab the stamp and sysinfo
- if re.match(tp.stampfmt, line):
- tp.stamp = line
- continue
- elif re.match(tp.sysinfofmt, line):
- tp.sysinfo = line
- continue
- elif re.match(tp.cmdlinefmt, line):
- tp.cmdline = line
- continue
- elif re.match(tp.batteryfmt, line):
- tp.battery.append(line)
- continue
- elif re.match(tp.testerrfmt, line):
- tp.testerror.append(line)
+ if tp.stampInfo(line):
continue
# determine the trace data type (required for further parsing)
m = re.match(tp.tracertypefmt, line)
@@ -2701,26 +2829,7 @@ def parseTraceLog(live=False):
for line in tf:
# remove any latent carriage returns
line = line.replace('\r\n', '')
- # stamp and sysinfo lines
- if re.match(tp.stampfmt, line):
- tp.stamp = line
- continue
- elif re.match(tp.sysinfofmt, line):
- tp.sysinfo = line
- continue
- elif re.match(tp.cmdlinefmt, line):
- tp.cmdline = line
- continue
- elif re.match(tp.batteryfmt, line):
- tp.battery.append(line)
- continue
- elif re.match(tp.testerrfmt, line):
- tp.testerror.append(line)
- continue
- # firmware line: pull out any firmware data
- m = re.match(tp.firmwarefmt, line)
- if(m):
- tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
+ if tp.stampInfo(line):
continue
# tracer type line: determine the trace data type
m = re.match(tp.tracertypefmt, line)
@@ -3141,25 +3250,7 @@ def loadKernelLog():
idx = line.find('[')
if idx > 1:
line = line[idx:]
- # grab the stamp and sysinfo
- if re.match(tp.stampfmt, line):
- tp.stamp = line
- continue
- elif re.match(tp.sysinfofmt, line):
- tp.sysinfo = line
- continue
- elif re.match(tp.cmdlinefmt, line):
- tp.cmdline = line
- continue
- elif re.match(tp.batteryfmt, line):
- tp.battery.append(line)
- continue
- elif re.match(tp.testerrfmt, line):
- tp.testerror.append(line)
- continue
- m = re.match(tp.firmwarefmt, line)
- if(m):
- tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
+ if tp.stampInfo(line):
continue
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
if(not m):
@@ -3531,22 +3622,16 @@ def addCallgraphs(sv, hf, data):
name+' → '+cg.name, color, dev['id'])
hf.write('\n\n </section>\n')
-# Function: createHTMLSummarySimple
-# Description:
-# Create summary html file for a series of tests
-# Arguments:
-# testruns: array of Data objects from parseTraceLog
-def createHTMLSummarySimple(testruns, htmlfile, title):
- # write the html header first (html head, css code, up to body start)
- html = '<!DOCTYPE html>\n<html>\n<head>\n\
+def summaryCSS(title, center=True):
+ tdcenter = 'text-align:center;' if center else ''
+ out = '<!DOCTYPE html>\n<html>\n<head>\n\
<meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
- <title>SleepGraph Summary</title>\n\
+ <title>'+title+'</title>\n\
<style type=\'text/css\'>\n\
.stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\
- table {width:100%;border-collapse: collapse;}\n\
- .summary {border:1px solid;}\n\
+ table {width:100%;border-collapse: collapse;border:1px solid;}\n\
th {border: 1px solid black;background:#222;color:white;}\n\
- td {font: 14px "Times New Roman";text-align: center;}\n\
+ td {font: 14px "Times New Roman";'+tdcenter+'}\n\
tr.head td {border: 1px solid black;background:#aaa;}\n\
tr.alt {background-color:#ddd;}\n\
tr.notice {color:red;}\n\
@@ -3555,6 +3640,16 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
.maxval {background-color:#FFBBBB;}\n\
.head a {color:#000;text-decoration: none;}\n\
</style>\n</head>\n<body>\n'
+ return out
+
+# Function: createHTMLSummarySimple
+# Description:
+# Create summary html file for a series of tests
+# Arguments:
+# testruns: array of Data objects from parseTraceLog
+def createHTMLSummarySimple(testruns, htmlfile, title):
+ # write the html header first (html head, css code, up to body start)
+ html = summaryCSS('Summary - SleepGraph')
# extract the test data into list
list = dict()
@@ -3579,17 +3674,20 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
num = 0
+ res = data['result']
tVal = [float(data['suspend']), float(data['resume'])]
list[mode]['data'].append([data['host'], data['kernel'],
- data['time'], tVal[0], tVal[1], data['url'], data['result'],
+ data['time'], tVal[0], tVal[1], data['url'], res,
data['issues'], data['sus_worst'], data['sus_worsttime'],
data['res_worst'], data['res_worsttime']])
idx = len(list[mode]['data']) - 1
- if data['result'] not in cnt:
- cnt[data['result']] = 1
+ if res.startswith('fail in'):
+ res = 'fail'
+ if res not in cnt:
+ cnt[res] = 1
else:
- cnt[data['result']] += 1
- if data['result'] == 'pass':
+ cnt[res] += 1
+ if res == 'pass':
for i in range(2):
tMed[i].append(tVal[i])
tAvg[i] += tVal[i]
@@ -3623,7 +3721,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
tdlink = '\t<td><a href="{0}">html</a></td>\n'
# table header
- html += '<table class="summary">\n<tr>\n' + th.format('#') +\
+ html += '<table>\n<tr>\n' + th.format('#') +\
th.format('Mode') + th.format('Host') + th.format('Kernel') +\
th.format('Test Time') + th.format('Result') + th.format('Issues') +\
th.format('Suspend') + th.format('Resume') +\
@@ -3698,6 +3796,104 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
hf.write(html+'</table>\n</body>\n</html>\n')
hf.close()
+def createHTMLDeviceSummary(testruns, htmlfile, title):
+ html = summaryCSS('Device Summary - SleepGraph', False)
+
+ # create global device list from all tests
+ devall = dict()
+ for data in testruns:
+ host, url, devlist = data['host'], data['url'], data['devlist']
+ for type in devlist:
+ if type not in devall:
+ devall[type] = dict()
+ mdevlist, devlist = devall[type], data['devlist'][type]
+ for name in devlist:
+ length = devlist[name]
+ if name not in mdevlist:
+ mdevlist[name] = {'name': name, 'host': host,
+ 'worst': length, 'total': length, 'count': 1,
+ 'url': url}
+ else:
+ if length > mdevlist[name]['worst']:
+ mdevlist[name]['worst'] = length
+ mdevlist[name]['url'] = url
+ mdevlist[name]['host'] = host
+ mdevlist[name]['total'] += length
+ mdevlist[name]['count'] += 1
+
+ # generate the html
+ th = '\t<th>{0}</th>\n'
+ td = '\t<td align=center>{0}</td>\n'
+ tdr = '\t<td align=right>{0}</td>\n'
+ tdlink = '\t<td align=center><a href="{0}">html</a></td>\n'
+ limit = 1
+ for type in sorted(devall, reverse=True):
+ num = 0
+ devlist = devall[type]
+ # table header
+ html += '<div class="stamp">%s (%s devices > %d ms)</div><table>\n' % \
+ (title, type.upper(), limit)
+ html += '<tr>\n' + '<th align=right>Device Name</th>' +\
+ th.format('Average Time') + th.format('Count') +\
+ th.format('Worst Time') + th.format('Host (worst time)') +\
+ th.format('Link (worst time)') + '</tr>\n'
+ for name in sorted(devlist, key=lambda k:devlist[k]['worst'], reverse=True):
+ data = devall[type][name]
+ data['average'] = data['total'] / data['count']
+ if data['average'] < limit:
+ continue
+ # row classes - alternate row color
+ rcls = ['alt'] if num % 2 == 1 else []
+ html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
+ html += tdr.format(data['name']) # name
+ html += td.format('%.3f ms' % data['average']) # average
+ html += td.format(data['count']) # count
+ html += td.format('%.3f ms' % data['worst']) # worst
+ html += td.format(data['host']) # host
+ html += tdlink.format(data['url']) # url
+ html += '</tr>\n'
+ num += 1
+ html += '</table>\n'
+
+ # flush the data to file
+ hf = open(htmlfile, 'w')
+ hf.write(html+'</body>\n</html>\n')
+ hf.close()
+ return devall
+
+def createHTMLIssuesSummary(issues, htmlfile, title):
+ html = summaryCSS('Issues Summary - SleepGraph', False)
+
+ # generate the html
+ th = '\t<th>{0}</th>\n'
+ td = '\t<td align={0}>{1}</td>\n'
+ tdlink = '<a href="{1}">{0}</a>'
+ subtitle = '%d issues' % len(issues) if len(issues) > 0 else 'no issues'
+ html += '<div class="stamp">%s (%s)</div><table>\n' % (title, subtitle)
+ html += '<tr>\n' + th.format('Count') + th.format('Issue') +\
+ th.format('Hosts') + th.format('First Instance') + '</tr>\n'
+
+ num = 0
+ for e in sorted(issues, key=lambda v:v['count'], reverse=True):
+ links = []
+ for host in sorted(e['urls']):
+ links.append(tdlink.format(host, e['urls'][host]))
+ # row classes - alternate row color
+ rcls = ['alt'] if num % 2 == 1 else []
+ html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
+ html += td.format('center', e['count']) # count
+ html += td.format('left', e['line']) # issue
+ html += td.format('center', len(e['urls'])) # hosts
+ html += td.format('center nowrap', '<br>'.join(links)) # links
+ html += '</tr>\n'
+ num += 1
+
+ # flush the data to file
+ hf = open(htmlfile, 'w')
+ hf.write(html+'</table>\n</body>\n</html>\n')
+ hf.close()
+ return issues
+
def ordinal(value):
suffix = 'th'
if value < 10 or value > 19:
@@ -4621,6 +4817,7 @@ def executeSuspend():
pprint('SUSPEND START')
else:
pprint('SUSPEND START (press a key to resume)')
+ sysvals.mcelog(True)
bat1 = getBattery() if battery else False
# set rtcwake
if(sysvals.rtcwake):
@@ -4652,13 +4849,21 @@ def executeSuspend():
pf = open(sysvals.diskpowerfile, 'w')
pf.write(sysvals.diskmode)
pf.close()
- pf = open(sysvals.powerfile, 'w')
- pf.write(mode)
- # execution will pause here
- try:
- pf.close()
- except Exception as e:
- tdata['error'] = str(e)
+ if mode == 'freeze' and sysvals.haveTurbostat():
+ # execution will pause here
+ turbo = sysvals.turbostat()
+ if '|' in turbo:
+ tdata['turbo'] = turbo
+ else:
+ tdata['error'] = turbo
+ else:
+ pf = open(sysvals.powerfile, 'w')
+ pf.write(mode)
+ # execution will pause here
+ try:
+ pf.close()
+ except Exception as e:
+ tdata['error'] = str(e)
if(sysvals.rtcwake):
sysvals.rtcWakeAlarmOff()
# postdelay delay
@@ -4672,6 +4877,9 @@ def executeSuspend():
sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
tdata['fw'] = getFPDT(False)
+ mcelog = sysvals.mcelog()
+ if mcelog:
+ tdata['mcelog'] = mcelog
bat2 = getBattery() if battery else False
if battery and bat1 and bat2:
tdata['bat'] = (bat1, bat2)
@@ -4694,6 +4902,7 @@ def executeSuspend():
op.close()
sysvals.fsetVal('', 'trace')
devProps()
+ return testdata
def readFile(file):
if os.path.islink(file):
@@ -5398,6 +5607,12 @@ def processData(live=False):
appendIncompleteTraceLog(testruns)
sysvals.vprint('Command:\n %s' % sysvals.cmdline)
for data in testruns:
+ if data.mcelog:
+ sysvals.vprint('MCELOG Data:')
+ for line in data.mcelog.split('\n'):
+ sysvals.vprint(' %s' % line)
+ if data.turbostat:
+ sysvals.vprint('Turbostat:\n %s' % data.turbostat.replace('|', ' '))
if data.battery:
a1, c1, a2, c2 = data.battery
s = 'Battery:\n Before - AC: %s, Charge: %d\n After - AC: %s, Charge: %d' % \
@@ -5431,7 +5646,10 @@ def rerunTest():
doesTraceLogHaveTraceEvents()
if not sysvals.dmesgfile and not sysvals.usetraceevents:
doError('recreating this html output requires a dmesg file')
- sysvals.setOutputFile()
+ if sysvals.outdir:
+ sysvals.htmlfile = sysvals.outdir
+ else:
+ sysvals.setOutputFile()
if os.path.exists(sysvals.htmlfile):
if not os.path.isfile(sysvals.htmlfile):
doError('a directory already exists with this name: %s' % sysvals.htmlfile)
@@ -5450,14 +5668,18 @@ def runTest(n=0):
sysvals.initTestOutput('suspend')
# execute the test
- executeSuspend()
+ testdata = executeSuspend()
sysvals.cleanupFtrace()
if sysvals.skiphtml:
sysvals.sudoUserchown(sysvals.testdir)
return
- testruns, stamp = processData(True)
- for data in testruns:
- del data
+ if len(testdata) > 0 and not testdata[0]['error']:
+ testruns, stamp = processData(True)
+ for data in testruns:
+ del data
+ else:
+ stamp = testdata[0]
+
sysvals.sudoUserchown(sysvals.testdir)
sysvals.outputResult(stamp, n)
if 'error' in stamp:
@@ -5487,8 +5709,13 @@ def find_in_html(html, start, end, firstonly=True):
return ''
return out
-def data_from_html(file, outpath, devlist=False):
- html = open(file, 'r').read()
+def data_from_html(file, outpath, issues):
+ if '<html>' not in file:
+ html = open(file, 'r').read()
+ sysvals.htmlfile = os.path.relpath(file, outpath)
+ else:
+ html = file
+ # extract general info
suspend = find_in_html(html, 'Kernel Suspend', 'ms')
resume = find_in_html(html, 'Kernel Resume', 'ms')
line = find_in_html(html, '<div class="stamp">', '</div>')
@@ -5499,6 +5726,7 @@ def data_from_html(file, outpath, devlist=False):
dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
except:
return False
+ sysvals.hostname = stmp[0]
tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
if error:
@@ -5509,13 +5737,39 @@ def data_from_html(file, outpath, devlist=False):
result = 'fail'
else:
result = 'pass'
+ # extract error info
ilist = []
- e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '→</div>', False)
- for i in list(set(e)):
- ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
+ log = find_in_html(html, '<div id="dmesglog" style="display:none;">',
+ '</div>').strip()
+ if log:
+ d = Data(0)
+ d.end = 999999999
+ d.dmesgtext = log.split('\n')
+ d.extractErrorInfo(issues)
+ elist = dict()
+ for dir in d.errorinfo:
+ for err in d.errorinfo[dir]:
+ if err[0] not in elist:
+ elist[err[0]] = 0
+ elist[err[0]] += 1
+ for i in elist:
+ ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i)
low = find_in_html(html, 'freeze time: <b>', ' ms</b>')
if low and '|' in low:
- ilist.append('FREEZEx%d' % len(low.split('|')))
+ issue = 'FREEZEx%d' % len(low.split('|'))
+ match = [i for i in issues if i['match'] == issue]
+ if len(match) > 0:
+ match[0]['count'] += 1
+ if sysvals.hostname not in match[0]['urls']:
+ match[0]['urls'][sysvals.hostname] = sysvals.htmlfile
+ else:
+ issues.append({
+ 'match': issue, 'count': 1, 'line': issue,
+ 'urls': {sysvals.hostname: sysvals.htmlfile},
+ })
+ ilist.append(issue)
+
+ # extract device info
devices = dict()
for line in html.split('\n'):
m = re.match(' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line)
@@ -5527,19 +5781,23 @@ def data_from_html(file, outpath, devlist=False):
name, time, phase = m.group('n'), m.group('t'), m.group('p')
if ' async' in name or ' sync' in name:
name = ' '.join(name.split(' ')[:-1])
- d = phase.split('_')[0]
+ if phase.startswith('suspend'):
+ d = 'suspend'
+ elif phase.startswith('resume'):
+ d = 'resume'
+ else:
+ continue
if d not in devices:
devices[d] = dict()
if name not in devices[d]:
devices[d][name] = 0.0
devices[d][name] += float(time)
- worst = {'suspend': {'name':'', 'time': 0.0},
- 'resume': {'name':'', 'time': 0.0}}
- for d in devices:
- if d not in worst:
- worst[d] = dict()
- dev = devices[d]
- if len(dev.keys()) > 0:
+ # create worst device info
+ worst = dict()
+ for d in ['suspend', 'resume']:
+ worst[d] = {'name':'', 'time': 0.0}
+ dev = devices[d] if d in devices else 0
+ if dev and len(dev.keys()) > 0:
n = sorted(dev, key=dev.get, reverse=True)[0]
worst[d]['name'], worst[d]['time'] = n, dev[n]
data = {
@@ -5551,14 +5809,13 @@ def data_from_html(file, outpath, devlist=False):
'issues': ' '.join(ilist),
'suspend': suspend,
'resume': resume,
+ 'devlist': devices,
'sus_worst': worst['suspend']['name'],
'sus_worsttime': worst['suspend']['time'],
'res_worst': worst['resume']['name'],
'res_worsttime': worst['resume']['time'],
- 'url': os.path.relpath(file, outpath),
+ 'url': sysvals.htmlfile,
}
- if devlist:
- data['devlist'] = devices
return data
# Function: runSummary
@@ -5567,7 +5824,7 @@ def data_from_html(file, outpath, devlist=False):
def runSummary(subdir, local=True, genhtml=False):
inpath = os.path.abspath(subdir)
outpath = os.path.abspath('.') if local else inpath
- pprint('Generating a summary of folder "%s"' % inpath)
+ pprint('Generating a summary of folder:\n %s' % inpath)
if genhtml:
for dirname, dirnames, filenames in os.walk(subdir):
sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
@@ -5583,26 +5840,31 @@ def runSummary(subdir, local=True, genhtml=False):
if sysvals.dmesgfile:
pprint('DMESG : %s' % sysvals.dmesgfile)
rerunTest()
+ issues = []
testruns = []
desc = {'host':[],'mode':[],'kernel':[]}
for dirname, dirnames, filenames in os.walk(subdir):
for filename in filenames:
if(not re.match('.*.html', filename)):
continue
- data = data_from_html(os.path.join(dirname, filename), outpath)
+ data = data_from_html(os.path.join(dirname, filename), outpath, issues)
if(not data):
continue
testruns.append(data)
for key in desc:
if data[key] not in desc[key]:
desc[key].append(data[key])
- outfile = os.path.join(outpath, 'summary.html')
- pprint('Summary file: %s' % outfile)
+ 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])
else:
title = inpath
- createHTMLSummarySimple(testruns, outfile, title)
+ createHTMLSummarySimple(testruns, os.path.join(outpath, 'summary.html'), title)
+ pprint(' summary.html - tabular list of test data found')
+ createHTMLDeviceSummary(testruns, os.path.join(outpath, 'summary-devices.html'), title)
+ pprint(' summary-devices.html - kernel device list sorted by total execution time')
+ createHTMLIssuesSummary(issues, os.path.join(outpath, 'summary-issues.html'), title)
+ pprint(' summary-issues.html - kernel issues found sorted by frequency')
# Function: checkArgBool
# Description:
--
2.14.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH 2/3] Update to pm-graph 5.4
2019-05-14 17:53 [PATCH 0/3] pm-graph 5.4 Todd Brandt
2019-05-14 17:53 ` [PATCH 1/3] Update to pm-graph 5.3 Todd Brandt
@ 2019-05-14 17:53 ` Todd Brandt
2019-05-14 17:53 ` [PATCH 3/3] pm-graph 5.4 config and other files Todd Brandt
2019-05-31 9:27 ` [PATCH 0/3] pm-graph 5.4 Rafael J. Wysocki
3 siblings, 0 replies; 5+ messages in thread
From: Todd Brandt @ 2019-05-14 17:53 UTC (permalink / raw)
To: linux-pm, rafael.j.wysocki, rjw; +Cc: todd.e.brandt, todd.e.brandt
bootgraph:
- dmesg log format has changed, update parser in two places
- fix prints in preparation for upgrade to python3
sleepgraph:
- fix prints in preparation for upgrade to python3
- add new trace events and kprobes to cover freeze more completely
- add new -ftop callgraph trace over suspend_devices_and_enter
- add -wifi option to check if a wifi connection is active
- add -skipkprobe option to suppress unwanted kprobes in dev mode
- add kernel params and sysinfo to the log output
- don't crash if /dev/mem is throwing IO errors, ignore FPDT and DMI
- fix kprobe length calculation when calls are recursive
- add several new kernel issue definitions for USB, ACPI, ATA, etc
- enable turbostat output to be read from stdout instead of from file
- add BIOS call data to the timeline from acpi_ps_execute_method kprobe
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
tools/power/pm-graph/bootgraph.py | 8 +-
tools/power/pm-graph/sleepgraph.py | 491 ++++++++++++++++++++++++++-----------
2 files changed, 347 insertions(+), 152 deletions(-)
diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py
index 6dae57041537..d7f4bd152bf1 100755
--- a/tools/power/pm-graph/bootgraph.py
+++ b/tools/power/pm-graph/bootgraph.py
@@ -333,9 +333,9 @@ def parseKernelLog():
if(not sysvals.stamp['kernel']):
sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
continue
- m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg)
+ m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg)
if(m):
- bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S')
+ bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S')
bt = bt - timedelta(seconds=int(ktime))
data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
@@ -356,7 +356,7 @@ def parseKernelLog():
data.newAction(phase, f, pid, start, ktime, int(r), int(t))
del devtemp[f]
continue
- if(re.match('^Freeing unused kernel memory.*', msg)):
+ if(re.match('^Freeing unused kernel .*', msg)):
data.tUserMode = ktime
data.dmesg['kernel']['end'] = ktime
data.dmesg['user']['start'] = ktime
@@ -1016,7 +1016,7 @@ if __name__ == '__main__':
updateKernelParams()
elif cmd == 'flistall':
for f in sysvals.getBootFtraceFilterFunctions():
- print f
+ print(f)
elif cmd == 'checkbl':
sysvals.getBootLoader()
pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec))
diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py
index 41d28d63e7c9..ccd0f3917c51 100755
--- a/tools/power/pm-graph/sleepgraph.py
+++ b/tools/power/pm-graph/sleepgraph.py
@@ -17,9 +17,9 @@
#
# Links:
# Home Page
-# https://01.org/suspendresume
+# https://01.org/pm-graph
# Source repo
-# git@github.com:01org/pm-graph
+# git@github.com:intel/pm-graph
#
# Description:
# This tool is designed to assist kernel and OS developers in optimizing
@@ -32,6 +32,7 @@
# viewed in firefox or chrome.
#
# The following kernel build options are required:
+# CONFIG_DEVMEM=y
# CONFIG_PM_DEBUG=y
# CONFIG_PM_SLEEP_DEBUG=y
# CONFIG_FTRACE=y
@@ -75,7 +76,7 @@ def pprint(msg):
# store system values and test parameters
class SystemValues:
title = 'SleepGraph'
- version = '5.3'
+ version = '5.4'
ansi = False
rs = 0
display = ''
@@ -83,8 +84,9 @@ class SystemValues:
sync = False
verbose = False
testlog = True
- dmesglog = False
+ dmesglog = True
ftracelog = False
+ tstat = False
mindevlen = 0.0
mincglen = 0.0
cgphase = ''
@@ -108,6 +110,8 @@ class SystemValues:
pmdpath = '/sys/power/pm_debug_messages'
traceevents = [
'suspend_resume',
+ 'wakeup_source_activate',
+ 'wakeup_source_deactivate',
'device_pm_callback_end',
'device_pm_callback_start'
]
@@ -139,6 +143,8 @@ class SystemValues:
x2delay = 0
skiphtml = False
usecallgraph = False
+ ftopfunc = 'suspend_devices_and_enter'
+ ftop = False
usetraceevents = False
usetracemarkers = True
usekprobes = True
@@ -167,6 +173,13 @@ class SystemValues:
'acpi_hibernation_leave': {},
'acpi_pm_freeze': {},
'acpi_pm_thaw': {},
+ 'acpi_s2idle_end': {},
+ 'acpi_s2idle_sync': {},
+ 'acpi_s2idle_begin': {},
+ 'acpi_s2idle_prepare': {},
+ 'acpi_s2idle_wake': {},
+ 'acpi_s2idle_wakeup': {},
+ 'acpi_s2idle_restore': {},
'hibernate_preallocate_memory': {},
'create_basic_memory_bitmaps': {},
'swsusp_write': {},
@@ -203,7 +216,11 @@ class SystemValues:
'rt_mutex_slowlock': {'ub': 1},
# ACPI
'acpi_resume_power_resources': {},
- 'acpi_ps_parse_aml': {},
+ 'acpi_ps_execute_method': { 'args_x86_64': {
+ 'fullpath':'+0(+40(%di)):string',
+ }},
+ # mei_me
+ 'mei_reset': {},
# filesystem
'ext4_sync_fs': {},
# 80211
@@ -252,6 +269,7 @@ class SystemValues:
timeformat = '%.3f'
cmdline = '%s %s' % \
(os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
+ kparams = ''
sudouser = ''
def __init__(self):
self.archargs = 'args_'+platform.machine()
@@ -330,6 +348,7 @@ class SystemValues:
args['date'] = n.strftime('%y%m%d')
args['time'] = n.strftime('%H%M%S')
args['hostname'] = args['host'] = self.hostname
+ args['mode'] = self.suspendmode
return value.format(**args)
def setOutputFile(self):
if self.dmesgfile != '':
@@ -341,7 +360,7 @@ class SystemValues:
if(m):
self.htmlfile = m.group('name')+'.html'
def systemInfo(self, info):
- p = c = m = b = ''
+ p = m = ''
if 'baseboard-manufacturer' in info:
m = info['baseboard-manufacturer']
elif 'system-manufacturer' in info:
@@ -352,12 +371,17 @@ class SystemValues:
p = info['baseboard-product-name']
if m[:5].lower() == 'intel' and 'baseboard-product-name' in info:
p = info['baseboard-product-name']
- if 'processor-version' in info:
- c = info['processor-version']
- if 'bios-version' in info:
- b = info['bios-version']
- self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \
- (m, p, c, b, self.cpucount, self.memtotal, self.memfree)
+ c = info['processor-version'] if 'processor-version' in info else ''
+ b = info['bios-version'] if 'bios-version' in info else ''
+ r = info['bios-release-date'] if 'bios-release-date' in info else ''
+ self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \
+ (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree)
+ try:
+ kcmd = open('/proc/cmdline', 'r').read().strip()
+ except:
+ kcmd = ''
+ if kcmd:
+ self.sysstamp += '\n# kparams | %s' % kcmd
def printSystemInfo(self, fatal=False):
self.rootCheck(True)
out = dmidecode(self.mempath, fatal)
@@ -365,10 +389,10 @@ class SystemValues:
return
fmt = '%-24s: %s'
for name in sorted(out):
- print fmt % (name, out[name])
- print fmt % ('cpucount', ('%d' % self.cpucount))
- print fmt % ('memtotal', ('%d kB' % self.memtotal))
- print fmt % ('memfree', ('%d kB' % self.memfree))
+ print(fmt % (name, out[name]))
+ print(fmt % ('cpucount', ('%d' % self.cpucount)))
+ print(fmt % ('memtotal', ('%d kB' % self.memtotal)))
+ print(fmt % ('memfree', ('%d kB' % self.memfree)))
def cpuInfo(self):
self.cpucount = 0
fp = open('/proc/cpuinfo', 'r')
@@ -388,7 +412,7 @@ class SystemValues:
def initTestOutput(self, name):
self.prefix = self.hostname
v = open('/proc/version', 'r').read().strip()
- kver = string.split(v)[2]
+ kver = v.split()[2]
fmt = name+'-%m%d%y-%H%M%S'
testtime = datetime.now().strftime(fmt)
self.teststamp = \
@@ -403,7 +427,7 @@ class SystemValues:
self.htmlfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
if not os.path.isdir(self.testdir):
- os.mkdir(self.testdir)
+ os.makedirs(self.testdir)
def getValueList(self, value):
out = []
for i in value.split(','):
@@ -414,6 +438,12 @@ class SystemValues:
self.devicefilter = self.getValueList(value)
def setCallgraphFilter(self, value):
self.cgfilter = self.getValueList(value)
+ def skipKprobes(self, value):
+ for k in self.getValueList(value):
+ if k in self.tracefuncs:
+ del self.tracefuncs[k]
+ if k in self.dev_tracefuncs:
+ del self.dev_tracefuncs[k]
def setCallgraphBlacklist(self, file):
self.cgblacklist = self.listFromFile(file)
def rtcWakeAlarmOn(self):
@@ -483,9 +513,9 @@ class SystemValues:
if 'func' in self.tracefuncs[i]:
i = self.tracefuncs[i]['func']
if i in master:
- print i
+ print(i)
else:
- print self.colorText(i)
+ print(self.colorText(i))
def setFtraceFilterFunctions(self, list):
master = self.listFromFile(self.tpath+'available_filter_functions')
flist = ''
@@ -728,7 +758,10 @@ class SystemValues:
cf.append(self.tracefuncs[fn]['func'])
else:
cf.append(fn)
- self.setFtraceFilterFunctions(cf)
+ if self.ftop:
+ self.setFtraceFilterFunctions([self.ftopfunc])
+ else:
+ self.setFtraceFilterFunctions(cf)
# initialize the kprobe trace
elif self.usekprobes:
for name in self.tracefuncs:
@@ -788,6 +821,14 @@ class SystemValues:
if 'bat' in test:
(a1, c1), (a2, c2) = test['bat']
fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2))
+ if 'wifi' in test:
+ wstr = []
+ for wifi in test['wifi']:
+ tmp = []
+ for key in sorted(wifi):
+ tmp.append('%s:%s' % (key, wifi[key]))
+ wstr.append('|'.join(tmp))
+ fp.write('# wifi %s\n' % (','.join(wstr)))
if test['error'] or len(testdata) > 1:
fp.write('# enter_sleep_error %s\n' % test['error'])
return fp
@@ -852,26 +893,22 @@ class SystemValues:
return ''
return base64.b64encode(out.encode('zlib'))
def haveTurbostat(self):
+ if not self.tstat:
+ return False
cmd = self.getExec('turbostat')
if not cmd:
return False
fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr
out = fp.read().strip()
fp.close()
- return re.match('turbostat version [0-8.]* .*', out)
+ return re.match('turbostat version [0-9\.]* .*', out)
def turbostat(self):
cmd = self.getExec('turbostat')
if not cmd:
return 'missing turbostat executable'
- outfile = '/tmp/pm-graph-turbostat.txt'
- res = call('%s -o %s -q -S echo freeze > %s' % \
- (cmd, outfile, self.powerfile), shell=True)
- if res != 0:
- return 'turbosat returned %d' % res
- if not os.path.exists(outfile):
- return 'turbostat output missing'
- fp = open(outfile, 'r')
text = []
+ fullcmd = '%s -q -S echo freeze > %s' % (cmd, self.powerfile)
+ fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE).stderr
for line in fp:
if re.match('[0-9.]* sec', line):
continue
@@ -888,6 +925,60 @@ class SystemValues:
values.append(line[idx])
out.append('%s=%s' % (key, ','.join(values)))
return '|'.join(out)
+ def checkWifi(self):
+ out = dict()
+ iwcmd, ifcmd = self.getExec('iwconfig'), self.getExec('ifconfig')
+ if not iwcmd or not ifcmd:
+ return out
+ fp = Popen(iwcmd, stdout=PIPE, stderr=PIPE).stdout
+ for line in fp:
+ m = re.match('(?P<dev>\S*) .* ESSID:(?P<ess>\S*)', line)
+ if not m:
+ continue
+ out['device'] = m.group('dev')
+ if '"' in m.group('ess'):
+ out['essid'] = m.group('ess').strip('"')
+ break
+ fp.close()
+ if 'device' in out:
+ fp = Popen([ifcmd, out['device']], stdout=PIPE, stderr=PIPE).stdout
+ for line in fp:
+ m = re.match('.* inet (?P<ip>[0-9\.]*)', line)
+ if m:
+ out['ip'] = m.group('ip')
+ break
+ fp.close()
+ return out
+ def errorSummary(self, errinfo, msg):
+ found = False
+ for entry in errinfo:
+ if re.match(entry['match'], msg):
+ entry['count'] += 1
+ if self.hostname not in entry['urls']:
+ entry['urls'][self.hostname] = [self.htmlfile]
+ elif self.htmlfile not in entry['urls'][self.hostname]:
+ entry['urls'][self.hostname].append(self.htmlfile)
+ found = True
+ break
+ if found:
+ return
+ arr = msg.split()
+ for j in range(len(arr)):
+ if re.match('^[0-9,\-\.]*$', arr[j]):
+ arr[j] = '[0-9,\-\.]*'
+ else:
+ arr[j] = arr[j]\
+ .replace('\\', '\\\\').replace(']', '\]').replace('[', '\[')\
+ .replace('.', '\.').replace('+', '\+').replace('*', '\*')\
+ .replace('(', '\(').replace(')', '\)')
+ mstr = ' '.join(arr)
+ entry = {
+ 'line': msg,
+ 'match': mstr,
+ 'count': 1,
+ 'urls': {self.hostname: [self.htmlfile]}
+ }
+ errinfo.append(entry)
sysvals = SystemValues()
switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
@@ -982,7 +1073,14 @@ class Data:
'ERROR' : '.*ERROR.*',
'WARNING' : '.*WARNING.*',
'IRQ' : '.*genirq: .*',
- 'TASKFAIL': '.*Freezing of tasks failed.*',
+ 'TASKFAIL': '.*Freezing of tasks *.*',
+ 'ACPI' : '.*ACPI *(?P<b>[A-Za-z]*) *Error[: ].*',
+ 'DEVFAIL' : '.* failed to (?P<b>[a-z]*) async: .*',
+ 'DISKFULL': '.*No space left on device.*',
+ 'USBERR' : '.*usb .*device .*, error [0-9-]*',
+ 'ATAERR' : ' *ata[0-9\.]*: .*failed.*',
+ 'MEIERR' : ' *mei.*: .*failed.*',
+ 'TPMERR' : '(?i) *tpm *tpm[0-9]*: .*error.*',
}
def __init__(self, num):
idchar = 'abcdefghij'
@@ -1000,6 +1098,7 @@ class Data:
self.outfile = ''
self.kerror = False
self.battery = 0
+ self.wifi = 0
self.turbostat = 0
self.mcelog = 0
self.enterfail = ''
@@ -1036,35 +1135,21 @@ class Data:
if len(plist) < 1:
return ''
return plist[-1]
- def errorSummary(self, errinfo, msg):
- found = False
- for entry in errinfo:
- if re.match(entry['match'], msg):
- entry['count'] += 1
- if sysvals.hostname not in entry['urls']:
- entry['urls'][sysvals.hostname] = sysvals.htmlfile
- found = True
- break
- if found:
- return
- arr = msg.split()
- for j in range(len(arr)):
- if re.match('^[0-9\-\.]*$', arr[j]):
- arr[j] = '[0-9\-\.]*'
- else:
- arr[j] = arr[j]\
- .replace(']', '\]').replace('[', '\[').replace('.', '\.')\
- .replace('+', '\+').replace('*', '\*').replace('(', '\(')\
- .replace(')', '\)')
- mstr = ' '.join(arr)
- entry = {
- 'line': msg,
- 'match': mstr,
- 'count': 1,
- 'urls': {sysvals.hostname: sysvals.htmlfile}
- }
- errinfo.append(entry)
- def extractErrorInfo(self, issues=0):
+ def turbostatInfo(self):
+ tp = TestProps()
+ out = {'syslpi':'N/A','pkgpc10':'N/A'}
+ for line in self.dmesgtext:
+ m = re.match(tp.tstatfmt, line)
+ if not m:
+ continue
+ for i in m.group('t').split('|'):
+ if 'SYS%LPI' in i:
+ out['syslpi'] = i.split('=')[-1]+'%'
+ elif 'pc10' in i:
+ out['pkgpc10'] = i.split('=')[-1]+'%'
+ break
+ return out
+ def extractErrorInfo(self):
lf = self.dmesgtext
if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
lf = sysvals.openlog(sysvals.dmesgfile, 'r')
@@ -1082,19 +1167,19 @@ class Data:
msg = m.group('msg')
for err in self.errlist:
if re.match(self.errlist[err], msg):
- list.append((err, dir, t, i, i))
+ list.append((msg, err, dir, t, i, i))
self.kerror = True
- if not isinstance(issues, int):
- self.errorSummary(issues, msg)
break
- for e in list:
- type, dir, t, idx1, idx2 = e
+ msglist = []
+ for msg, type, dir, t, idx1, idx2 in list:
+ msglist.append(msg)
sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t))
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
def setStart(self, time):
self.start = time
def setEnd(self, time):
@@ -2147,7 +2232,7 @@ class FTraceCallGraph:
if(data.dmesg[p]['start'] <= self.start and
self.start <= data.dmesg[p]['end']):
list = data.dmesg[p]['list']
- for devname in list:
+ for devname in sorted(list, key=lambda k:list[k]['start']):
dev = list[devname]
if(pid == dev['pid'] and
self.start <= dev['start'] and
@@ -2452,6 +2537,7 @@ class TestProps:
'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)'
+ wififmt = '^# wifi (?P<w>.*)'
tstatfmt = '^# turbostat (?P<t>\S*)'
mcelogfmt = '^# mcelog (?P<m>\S*)'
testerrfmt = '^# enter_sleep_error (?P<e>.*)'
@@ -2479,6 +2565,7 @@ class TestProps:
self.mcelog = []
self.turbostat = []
self.battery = []
+ self.wifi = []
self.fwdata = []
self.ftrace_line_fmt = self.ftrace_line_fmt_nop
self.cgformat = False
@@ -2505,6 +2592,9 @@ class TestProps:
elif re.match(self.sysinfofmt, line):
self.sysinfo = line
return True
+ elif re.match(self.kparamsfmt, line):
+ self.kparams = line
+ return True
elif re.match(self.cmdlinefmt, line):
self.cmdline = line
return True
@@ -2517,6 +2607,9 @@ class TestProps:
elif re.match(self.batteryfmt, line):
self.battery.append(line)
return True
+ elif re.match(self.wififmt, line):
+ self.wifi.append(line)
+ return True
elif re.match(self.testerrfmt, line):
self.testerror.append(line)
return True
@@ -2586,6 +2679,11 @@ class TestProps:
m = re.match(self.batteryfmt, self.battery[data.testnumber])
if m:
data.battery = m.groups()
+ # wifi data
+ if len(self.wifi) > data.testnumber:
+ m = re.match(self.wififmt, self.wifi[data.testnumber])
+ if m:
+ data.wifi = m.group('w')
# sleep mode enter errors
if len(self.testerror) > data.testnumber:
m = re.match(self.testerrfmt, self.testerror[data.testnumber])
@@ -2655,9 +2753,9 @@ class ProcessMonitor:
# Quickly determine if the ftrace log has all of the trace events,
# markers, and/or kprobes required for primary parsing.
def doesTraceLogHaveTraceEvents():
- kpcheck = ['_cal: (', '_cpu_down()']
+ kpcheck = ['_cal: (', '_ret: (']
techeck = ['suspend_resume', 'device_pm_callback']
- tmcheck = ['tracing_mark_write']
+ tmcheck = ['SUSPEND START', 'RESUME COMPLETE']
sysvals.usekprobes = False
fp = sysvals.openlog(sysvals.ftracefile, 'r')
for line in fp:
@@ -3042,7 +3140,7 @@ def parseTraceLog(live=False):
tp.ktemp[key].append({
'pid': pid,
'begin': t.time,
- 'end': t.time,
+ 'end': -1,
'name': displayname,
'cdata': kprobedata,
'proc': m_proc,
@@ -3053,12 +3151,11 @@ def parseTraceLog(live=False):
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
+ e = next((x for x in reversed(tp.ktemp[key]) if x['end'] < 0), 0)
+ if not e:
+ continue
+ e['end'] = t.time
+ e['rdata'] = kprobedata
# end of kernel resume
if(phase != 'suspend_prepare' and kprobename in krescalls):
if phase in data.dmesg:
@@ -3080,8 +3177,10 @@ def parseTraceLog(live=False):
if(res == -1):
testrun.ftemp[key][-1].addLine(t)
tf.close()
+ if len(testdata) < 1:
+ sysvals.vprint('WARNING: ftrace start marker is missing')
if data and not data.devicegroups:
- sysvals.vprint('WARNING: end marker is missing')
+ sysvals.vprint('WARNING: ftrace end marker is missing')
data.handleEndMarker(t.time)
if sysvals.suspendmode == 'command':
@@ -3130,9 +3229,11 @@ def parseTraceLog(live=False):
name, pid = key
if name not in sysvals.tracefuncs:
continue
+ if pid not in data.devpids:
+ data.devpids.append(pid)
for e in tp.ktemp[key]:
kb, ke = e['begin'], e['end']
- if kb == ke or tlb > kb or tle <= kb:
+ if ke - kb < 0.000001 or tlb > kb or tle <= kb:
continue
color = sysvals.kprobeColor(name)
data.newActionGlobal(e['name'], kb, ke, pid, color)
@@ -3144,7 +3245,7 @@ def parseTraceLog(live=False):
continue
for e in tp.ktemp[key]:
kb, ke = e['begin'], e['end']
- if kb == ke or tlb > kb or tle <= kb:
+ if ke - kb < 0.000001 or tlb > kb or tle <= kb:
continue
data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
ke, e['cdata'], e['rdata'])
@@ -3168,7 +3269,7 @@ def parseTraceLog(live=False):
if not devname:
sortkey = '%f%f%d' % (cg.start, cg.end, pid)
sortlist[sortkey] = cg
- elif len(cg.list) > 1000000:
+ elif len(cg.list) > 1000000 and cg.name != sysvals.ftopfunc:
sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\
(devname, len(cg.list)))
# create blocks for orphan cg data
@@ -3275,7 +3376,7 @@ def loadKernelLog():
if data:
testruns.append(data)
if len(testruns) < 1:
- pprint('ERROR: dmesg log has no suspend/resume data: %s' \
+ doError('dmesg log has no suspend/resume data: %s' \
% sysvals.dmesgfile)
# fix lines with same timestamp/function with the call and return swapped
@@ -3614,6 +3715,8 @@ def addCallgraphs(sv, hf, data):
name += ' '+p
if('ftrace' in dev):
cg = dev['ftrace']
+ if cg.name == sv.ftopfunc:
+ name = 'top level suspend/resume call'
num = callgraphHTML(sv, hf, num, cg,
name, color, dev['id'])
if('ftraces' in dev):
@@ -3653,9 +3756,10 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
# extract the test data into list
list = dict()
- tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
+ tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()]
iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
num = 0
+ useturbo = False
lastmode = ''
cnt = dict()
for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
@@ -3666,20 +3770,25 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
for i in range(2):
s = sorted(tMed[i])
list[lastmode]['med'][i] = s[int(len(s)/2)]
- iMed[i] = tMed[i].index(list[lastmode]['med'][i])
+ iMed[i] = tMed[i][list[lastmode]['med'][i]]
list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
list[lastmode]['min'] = tMin
list[lastmode]['max'] = tMax
list[lastmode]['idx'] = (iMin, iMed, iMax)
- tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []]
+ tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()]
iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
num = 0
+ pkgpc10 = syslpi = ''
+ if 'pkgpc10' in data and 'syslpi' in data:
+ pkgpc10 = data['pkgpc10']
+ syslpi = data['syslpi']
+ useturbo = True
res = data['result']
tVal = [float(data['suspend']), float(data['resume'])]
list[mode]['data'].append([data['host'], data['kernel'],
data['time'], tVal[0], tVal[1], data['url'], res,
data['issues'], data['sus_worst'], data['sus_worsttime'],
- data['res_worst'], data['res_worsttime']])
+ data['res_worst'], data['res_worsttime'], pkgpc10, syslpi])
idx = len(list[mode]['data']) - 1
if res.startswith('fail in'):
res = 'fail'
@@ -3689,7 +3798,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
cnt[res] += 1
if res == 'pass':
for i in range(2):
- tMed[i].append(tVal[i])
+ tMed[i][tVal[i]] = idx
tAvg[i] += tVal[i]
if tMin[i] == 0 or tVal[i] < tMin[i]:
iMin[i] = idx
@@ -3703,7 +3812,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
for i in range(2):
s = sorted(tMed[i])
list[lastmode]['med'][i] = s[int(len(s)/2)]
- iMed[i] = tMed[i].index(list[lastmode]['med'][i])
+ iMed[i] = tMed[i][list[lastmode]['med'][i]]
list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num]
list[lastmode]['min'] = tMin
list[lastmode]['max'] = tMax
@@ -3719,6 +3828,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
td = '\t<td>{0}</td>\n'
tdh = '\t<td{1}>{0}</td>\n'
tdlink = '\t<td><a href="{0}">html</a></td>\n'
+ colspan = '14' if useturbo else '12'
# table header
html += '<table>\n<tr>\n' + th.format('#') +\
@@ -3726,12 +3836,13 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
th.format('Test Time') + th.format('Result') + th.format('Issues') +\
th.format('Suspend') + th.format('Resume') +\
th.format('Worst Suspend Device') + th.format('SD Time') +\
- th.format('Worst Resume Device') + th.format('RD Time') +\
- th.format('Detail') + '</tr>\n'
-
+ th.format('Worst Resume Device') + th.format('RD Time')
+ if useturbo:
+ html += th.format('PkgPC10') + th.format('SysLPI')
+ html += th.format('Detail')+'</tr>\n'
# export list into html
head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\
- '<td colspan=12 class="sus">Suspend Avg={2} '+\
+ '<td colspan='+colspan+' class="sus">Suspend Avg={2} '+\
'<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\
'<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\
'<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\
@@ -3740,7 +3851,8 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
'<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\
'<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\
'</tr>\n'
- headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=12></td></tr>\n'
+ headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan='+\
+ colspan+'></td></tr>\n'
for mode in list:
# header line for each suspend mode
num = 0
@@ -3787,6 +3899,9 @@ def createHTMLSummarySimple(testruns, htmlfile, title):
html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time
html += td.format(d[10]) # res_worst
html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time
+ if useturbo:
+ html += td.format(d[12]) # pkg_pc10
+ html += td.format(d[13]) # syslpi
html += tdlink.format(d[5]) if d[5] else td.format('') # url
html += '</tr>\n'
num += 1
@@ -3861,8 +3976,10 @@ def createHTMLDeviceSummary(testruns, htmlfile, title):
hf.close()
return devall
-def createHTMLIssuesSummary(issues, htmlfile, title):
+def createHTMLIssuesSummary(testruns, issues, htmlfile, title, extra=''):
+ multihost = len([e for e in issues if len(e['urls']) > 1]) > 0
html = summaryCSS('Issues Summary - SleepGraph', False)
+ total = len(testruns)
# generate the html
th = '\t<th>{0}</th>\n'
@@ -3870,27 +3987,36 @@ def createHTMLIssuesSummary(issues, htmlfile, title):
tdlink = '<a href="{1}">{0}</a>'
subtitle = '%d issues' % len(issues) if len(issues) > 0 else 'no issues'
html += '<div class="stamp">%s (%s)</div><table>\n' % (title, subtitle)
- html += '<tr>\n' + th.format('Count') + th.format('Issue') +\
- th.format('Hosts') + th.format('First Instance') + '</tr>\n'
+ html += '<tr>\n' + th.format('Issue') + th.format('Count')
+ if multihost:
+ html += th.format('Hosts')
+ html += th.format('Tests') + th.format('Fail Rate') +\
+ th.format('First Instance') + '</tr>\n'
num = 0
for e in sorted(issues, key=lambda v:v['count'], reverse=True):
+ testtotal = 0
links = []
for host in sorted(e['urls']):
- links.append(tdlink.format(host, e['urls'][host]))
+ links.append(tdlink.format(host, e['urls'][host][0]))
+ testtotal += len(e['urls'][host])
+ rate = '%d/%d (%.2f%%)' % (testtotal, total, 100*float(testtotal)/float(total))
# row classes - alternate row color
rcls = ['alt'] if num % 2 == 1 else []
html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n'
- html += td.format('center', e['count']) # count
html += td.format('left', e['line']) # issue
- html += td.format('center', len(e['urls'])) # hosts
+ html += td.format('center', e['count']) # count
+ if multihost:
+ html += td.format('center', len(e['urls'])) # hosts
+ html += td.format('center', testtotal) # test count
+ html += td.format('center', rate) # test rate
html += td.format('center nowrap', '<br>'.join(links)) # links
html += '</tr>\n'
num += 1
# flush the data to file
hf = open(htmlfile, 'w')
- hf.write(html+'</table>\n</body>\n</html>\n')
+ hf.write(html+'</table>\n'+extra+'</body>\n</html>\n')
hf.close()
return issues
@@ -4195,7 +4321,7 @@ def createHTML(testruns, testfail):
for word in phase.split('_'):
id += word[0]
order = '%.2f' % ((p['order'] * pdelta) + pmargin)
- name = string.replace(phase, '_', ' ')
+ name = phase.replace('_', ' ')
devtl.html += devtl.html_legend.format(order, p['color'], name, id)
devtl.html += '</div>\n'
@@ -4784,6 +4910,7 @@ def setRuntimeSuspend(before=True):
def executeSuspend():
pm = ProcessMonitor()
tp = sysvals.tpath
+ wifi = sysvals.checkWifi()
testdata = []
battery = True if getBattery() else False
# run these commands to prepare the system for suspend
@@ -4857,6 +4984,8 @@ def executeSuspend():
else:
tdata['error'] = turbo
else:
+ if sysvals.haveTurbostat():
+ sysvals.vprint('WARNING: ignoring turbostat in mode "%s"' % mode)
pf = open(sysvals.powerfile, 'w')
pf.write(mode)
# execution will pause here
@@ -4883,6 +5012,8 @@ def executeSuspend():
bat2 = getBattery() if battery else False
if battery and bat1 and bat2:
tdata['bat'] = (bat1, bat2)
+ if 'device' in wifi and 'ip' in wifi:
+ tdata['wifi'] = (wifi, sysvals.checkWifi())
testdata.append(tdata)
# stop ftrace
if(sysvals.usecallgraph or sysvals.usetraceevents):
@@ -4989,7 +5120,7 @@ def deviceInfo(output=''):
ms2nice(power['runtime_active_time']), \
ms2nice(power['runtime_suspended_time']))
for i in sorted(lines):
- print lines[i]
+ print(lines[i])
return res
# Function: devProps
@@ -5122,12 +5253,12 @@ def getModes():
modes = []
if(os.path.exists(sysvals.powerfile)):
fp = open(sysvals.powerfile, 'r')
- modes = string.split(fp.read())
+ modes = fp.read().split()
fp.close()
if(os.path.exists(sysvals.mempowerfile)):
deep = False
fp = open(sysvals.mempowerfile, 'r')
- for m in string.split(fp.read()):
+ for m in fp.read().split():
memmode = m.strip('[]')
if memmode == 'deep':
deep = True
@@ -5138,7 +5269,7 @@ def getModes():
modes.remove('mem')
if('disk' in modes and os.path.exists(sysvals.diskpowerfile)):
fp = open(sysvals.diskpowerfile, 'r')
- for m in string.split(fp.read()):
+ for m in fp.read().split():
modes.append('disk-%s' % m.strip('[]'))
fp.close()
return modes
@@ -5201,14 +5332,15 @@ def dmidecode(mempath, fatal=False):
continue
# read in the memory for scanning
- fp = open(mempath, 'rb')
try:
+ fp = open(mempath, 'rb')
fp.seek(memaddr)
buf = fp.read(memsize)
except:
if(fatal):
doError('DMI table is unreachable, sorry')
else:
+ pprint('WARNING: /dev/mem is not readable, ignoring DMI data')
return out
fp.close()
@@ -5231,14 +5363,15 @@ def dmidecode(mempath, fatal=False):
return out
# read in the SM or DMI table
- fp = open(mempath, 'rb')
try:
+ fp = open(mempath, 'rb')
fp.seek(base)
buf = fp.read(length)
except:
if(fatal):
doError('DMI table is unreachable, sorry')
else:
+ pprint('WARNING: /dev/mem is not readable, ignoring DMI data')
return out
fp.close()
@@ -5382,7 +5515,11 @@ def getFPDT(output):
i = 0
fwData = [0, 0]
records = buf[36:]
- fp = open(sysvals.mempath, 'rb')
+ try:
+ fp = open(sysvals.mempath, 'rb')
+ except:
+ pprint('WARNING: /dev/mem is not readable, ignoring the FPDT data')
+ return False
while(i < len(records)):
header = struct.unpack('HBB', records[i:i+4])
if(header[0] not in rectype):
@@ -5499,13 +5636,14 @@ def statusCheck(probecheck=False):
pprint(' 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
- pprint(' are kprobes supported: %s' % res)
+ if sysvals.usekprobes:
+ res = sysvals.colorText('NO')
+ sysvals.usekprobes = sysvals.verifyKprobes()
+ if(sysvals.usekprobes):
+ res = 'YES'
+ else:
+ sysvals.usedevsrc = False
+ pprint(' are kprobes supported: %s' % res)
# what data source are we using
res = 'DMESG'
@@ -5593,6 +5731,8 @@ def getArgFloat(name, args, min, max, main=True):
def processData(live=False):
pprint('PROCESSING DATA')
+ sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \
+ (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes))
error = ''
if(sysvals.usetraceevents):
testruns, error = parseTraceLog(live)
@@ -5605,6 +5745,11 @@ def processData(live=False):
parseKernelLog(data)
if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
appendIncompleteTraceLog(testruns)
+ sysvals.vprint('System Info:')
+ for key in sorted(sysvals.stamp):
+ sysvals.vprint(' %-8s : %s' % (key.upper(), sysvals.stamp[key]))
+ if sysvals.kparams:
+ sysvals.vprint('Kparams:\n %s' % sysvals.kparams)
sysvals.vprint('Command:\n %s' % sysvals.cmdline)
for data in testruns:
if data.mcelog:
@@ -5612,12 +5757,24 @@ def processData(live=False):
for line in data.mcelog.split('\n'):
sysvals.vprint(' %s' % line)
if data.turbostat:
- sysvals.vprint('Turbostat:\n %s' % data.turbostat.replace('|', ' '))
+ idx, s = 0, 'Turbostat:\n '
+ for val in data.turbostat.split('|'):
+ idx += len(val) + 1
+ if idx >= 80:
+ idx = 0
+ s += '\n '
+ s += val + ' '
+ sysvals.vprint(s)
if data.battery:
a1, c1, a2, c2 = data.battery
s = 'Battery:\n Before - AC: %s, Charge: %d\n After - AC: %s, Charge: %d' % \
(a1, int(c1), a2, int(c2))
sysvals.vprint(s)
+ if data.wifi:
+ w = data.wifi.replace('|', ' ').split(',')
+ s = 'Wifi:\n Before %s\n After %s' % \
+ (w[0], w[1])
+ sysvals.vprint(s)
data.printDetails()
if sysvals.cgdump:
for data in testruns:
@@ -5641,13 +5798,13 @@ def processData(live=False):
# Function: rerunTest
# Description:
# generate an output from an existing set of ftrace/dmesg logs
-def rerunTest():
+def rerunTest(htmlfile=''):
if sysvals.ftracefile:
doesTraceLogHaveTraceEvents()
if not sysvals.dmesgfile and not sysvals.usetraceevents:
doError('recreating this html output requires a dmesg file')
- if sysvals.outdir:
- sysvals.htmlfile = sysvals.outdir
+ if htmlfile:
+ sysvals.htmlfile = htmlfile
else:
sysvals.setOutputFile()
if os.path.exists(sysvals.htmlfile):
@@ -5673,7 +5830,7 @@ def runTest(n=0):
if sysvals.skiphtml:
sysvals.sudoUserchown(sysvals.testdir)
return
- if len(testdata) > 0 and not testdata[0]['error']:
+ if not testdata[0]['error']:
testruns, stamp = processData(True)
for data in testruns:
del data
@@ -5709,15 +5866,13 @@ def find_in_html(html, start, end, firstonly=True):
return ''
return out
-def data_from_html(file, outpath, issues):
- if '<html>' not in file:
- html = open(file, 'r').read()
- sysvals.htmlfile = os.path.relpath(file, outpath)
- else:
- html = file
+def data_from_html(file, outpath, issues, fulldetail=False):
+ html = open(file, 'r').read()
+ sysvals.htmlfile = os.path.relpath(file, outpath)
# extract general info
suspend = find_in_html(html, 'Kernel Suspend', 'ms')
resume = find_in_html(html, 'Kernel Resume', 'ms')
+ sysinfo = find_in_html(html, '<div class="stamp sysinfo">', '</div>')
line = find_in_html(html, '<div class="stamp">', '</div>')
stmp = line.split()
if not suspend or not resume or len(stmp) != 8:
@@ -5739,13 +5894,18 @@ def data_from_html(file, outpath, issues):
result = 'pass'
# extract error info
ilist = []
+ extra = dict()
log = find_in_html(html, '<div id="dmesglog" style="display:none;">',
'</div>').strip()
if log:
d = Data(0)
d.end = 999999999
d.dmesgtext = log.split('\n')
- d.extractErrorInfo(issues)
+ msglist = d.extractErrorInfo()
+ for msg in msglist:
+ sysvals.errorSummary(issues, msg)
+ if stmp[2] == 'freeze':
+ extra = d.turbostatInfo()
elist = dict()
for dir in d.errorinfo:
for err in d.errorinfo[dir]:
@@ -5761,14 +5921,15 @@ def data_from_html(file, outpath, issues):
if len(match) > 0:
match[0]['count'] += 1
if sysvals.hostname not in match[0]['urls']:
- match[0]['urls'][sysvals.hostname] = sysvals.htmlfile
+ match[0]['urls'][sysvals.hostname] = [sysvals.htmlfile]
+ elif sysvals.htmlfile not in match[0]['urls'][sysvals.hostname]:
+ match[0]['urls'][sysvals.hostname].append(sysvals.htmlfile)
else:
issues.append({
'match': issue, 'count': 1, 'line': issue,
- 'urls': {sysvals.hostname: sysvals.htmlfile},
+ 'urls': {sysvals.hostname: [sysvals.htmlfile]},
})
ilist.append(issue)
-
# extract device info
devices = dict()
for line in html.split('\n'):
@@ -5804,6 +5965,7 @@ def data_from_html(file, outpath, issues):
'mode': stmp[2],
'host': stmp[0],
'kernel': stmp[1],
+ 'sysinfo': sysinfo,
'time': tstr,
'result': result,
'issues': ' '.join(ilist),
@@ -5816,8 +5978,28 @@ def data_from_html(file, outpath, issues):
'res_worsttime': worst['resume']['time'],
'url': sysvals.htmlfile,
}
+ for key in extra:
+ data[key] = extra[key]
+ if fulldetail:
+ data['funclist'] = find_in_html(html, '<div title="', '" class="traceevent"', False)
return data
+def genHtml(subdir):
+ for dirname, dirnames, filenames in os.walk(subdir):
+ sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
+ for filename in filenames:
+ if(re.match('.*_dmesg.txt', filename)):
+ sysvals.dmesgfile = os.path.join(dirname, filename)
+ elif(re.match('.*_ftrace.txt', filename)):
+ sysvals.ftracefile = os.path.join(dirname, filename)
+ sysvals.setOutputFile()
+ if sysvals.ftracefile and sysvals.htmlfile and \
+ not os.path.exists(sysvals.htmlfile):
+ pprint('FTRACE: %s' % sysvals.ftracefile)
+ if sysvals.dmesgfile:
+ pprint('DMESG : %s' % sysvals.dmesgfile)
+ rerunTest()
+
# Function: runSummary
# Description:
# create a summary of tests in a sub-directory
@@ -5826,20 +6008,7 @@ def runSummary(subdir, local=True, genhtml=False):
outpath = os.path.abspath('.') if local else inpath
pprint('Generating a summary of folder:\n %s' % inpath)
if genhtml:
- for dirname, dirnames, filenames in os.walk(subdir):
- sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = ''
- for filename in filenames:
- if(re.match('.*_dmesg.txt', filename)):
- sysvals.dmesgfile = os.path.join(dirname, filename)
- elif(re.match('.*_ftrace.txt', filename)):
- sysvals.ftracefile = os.path.join(dirname, filename)
- sysvals.setOutputFile()
- if sysvals.ftracefile and sysvals.htmlfile and \
- not os.path.exists(sysvals.htmlfile):
- pprint('FTRACE: %s' % sysvals.ftracefile)
- if sysvals.dmesgfile:
- pprint('DMESG : %s' % sysvals.dmesgfile)
- rerunTest()
+ genHtml(subdir)
issues = []
testruns = []
desc = {'host':[],'mode':[],'kernel':[]}
@@ -5863,7 +6032,7 @@ def runSummary(subdir, local=True, genhtml=False):
pprint(' summary.html - tabular list of test data found')
createHTMLDeviceSummary(testruns, os.path.join(outpath, 'summary-devices.html'), title)
pprint(' summary-devices.html - kernel device list sorted by total execution time')
- createHTMLIssuesSummary(issues, os.path.join(outpath, 'summary-issues.html'), title)
+ createHTMLIssuesSummary(testruns, issues, os.path.join(outpath, 'summary-issues.html'), title)
pprint(' summary-issues.html - kernel issues found sorted by frequency')
# Function: checkArgBool
@@ -6109,6 +6278,7 @@ def printHelp():
' default: suspend-{date}-{time}\n'\
' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)\n'\
' -addlogs Add the dmesg and ftrace logs to the html output\n'\
+ ' -turbostat Use turbostat to execute the command in freeze mode (default: disabled)\n'\
' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\
' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\
' -result fn Export a results table to a text file for parsing.\n'\
@@ -6130,6 +6300,7 @@ def printHelp():
' be created in a new subdirectory with a summary page.\n'\
' [debug]\n'\
' -f Use ftrace to create device callgraphs (default: disabled)\n'\
+ ' -ftop Use ftrace on the top level call: "%s" (default: disabled)\n'\
' -maxdepth N limit the callgraph data to N call levels (default: 0=all)\n'\
' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\
' -fadd file Add functions to be graphed in the timeline from a list in a text file\n'\
@@ -6149,6 +6320,7 @@ def printHelp():
' -status Test to see if the system is enabled to run this tool\n'\
' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\
' -battery Print out battery info (if available)\n'\
+ ' -wifi Print out wifi connection info (if wireless-tools and device exists)\n'\
' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\
' -sysinfo Print out system info extracted from BIOS\n'\
' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\
@@ -6158,7 +6330,7 @@ def printHelp():
' [redo]\n'\
' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)\n'\
' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)\n'\
- '' % (sysvals.title, sysvals.version, sysvals.suspendmode))
+ '' % (sysvals.title, sysvals.version, sysvals.suspendmode, sysvals.ftopfunc))
return True
# ----------------- MAIN --------------------
@@ -6168,7 +6340,7 @@ if __name__ == '__main__':
cmd = ''
simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall',
'-devinfo', '-status', '-battery', '-xon', '-xoff', '-xstandby',
- '-xsuspend', '-xinit', '-xreset', '-xstat']
+ '-xsuspend', '-xinit', '-xreset', '-xstat', '-wifi']
if '-f' in sys.argv:
sysvals.cgskip = sysvals.configFile('cgskip.txt')
# loop through the command line arguments
@@ -6200,6 +6372,10 @@ if __name__ == '__main__':
sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
elif(arg == '-f'):
sysvals.usecallgraph = True
+ elif(arg == '-ftop'):
+ sysvals.usecallgraph = True
+ sysvals.ftop = True
+ sysvals.usekprobes = False
elif(arg == '-skiphtml'):
sysvals.skiphtml = True
elif(arg == '-cgdump'):
@@ -6210,10 +6386,16 @@ if __name__ == '__main__':
genhtml = True
elif(arg == '-addlogs'):
sysvals.dmesglog = sysvals.ftracelog = True
+ elif(arg == '-nologs'):
+ sysvals.dmesglog = sysvals.ftracelog = False
elif(arg == '-addlogdmesg'):
sysvals.dmesglog = True
elif(arg == '-addlogftrace'):
sysvals.ftracelog = True
+ elif(arg == '-turbostat'):
+ sysvals.tstat = True
+ if not sysvals.haveTurbostat():
+ doError('Turbostat command not found')
elif(arg == '-verbose'):
sysvals.verbose = True
elif(arg == '-proc'):
@@ -6283,6 +6465,12 @@ if __name__ == '__main__':
except:
doError('No callgraph functions supplied', True)
sysvals.setCallgraphFilter(val)
+ elif(arg == '-skipkprobe'):
+ try:
+ val = args.next()
+ except:
+ doError('No kprobe functions supplied', True)
+ sysvals.skipKprobes(val)
elif(arg == '-cgskip'):
try:
val = args.next()
@@ -6421,7 +6609,7 @@ if __name__ == '__main__':
elif(cmd == 'devinfo'):
deviceInfo()
elif(cmd == 'modes'):
- print getModes()
+ pprint(getModes())
elif(cmd == 'flist'):
sysvals.getFtraceFilterFunctions(True)
elif(cmd == 'flistall'):
@@ -6433,11 +6621,18 @@ if __name__ == '__main__':
ret = displayControl(cmd[1:])
elif(cmd == 'xstat'):
pprint('Display Status: %s' % displayControl('stat').upper())
+ elif(cmd == 'wifi'):
+ out = sysvals.checkWifi()
+ if 'device' not in out:
+ pprint('WIFI interface not found')
+ else:
+ for key in sorted(out):
+ pprint('%6s: %s' % (key.upper(), out[key]))
sys.exit(ret)
# if instructed, re-analyze existing data files
if(sysvals.notestrun):
- stamp = rerunTest()
+ stamp = rerunTest(sysvals.outdir)
sysvals.outputResult(stamp)
sys.exit(0)
@@ -6474,7 +6669,7 @@ if __name__ == '__main__':
s = 'suspend-x%d' % sysvals.multitest['count']
sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S')
if not os.path.isdir(sysvals.outdir):
- os.mkdir(sysvals.outdir)
+ os.makedirs(sysvals.outdir)
for i in range(sysvals.multitest['count']):
if(i != 0):
pprint('Waiting %d seconds...' % (sysvals.multitest['delay']))
--
2.14.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH 3/3] pm-graph 5.4 config and other files
2019-05-14 17:53 [PATCH 0/3] pm-graph 5.4 Todd Brandt
2019-05-14 17:53 ` [PATCH 1/3] Update to pm-graph 5.3 Todd Brandt
2019-05-14 17:53 ` [PATCH 2/3] Update to pm-graph 5.4 Todd Brandt
@ 2019-05-14 17:53 ` Todd Brandt
2019-05-31 9:27 ` [PATCH 0/3] pm-graph 5.4 Rafael J. Wysocki
3 siblings, 0 replies; 5+ messages in thread
From: Todd Brandt @ 2019-05-14 17:53 UTC (permalink / raw)
To: linux-pm, rafael.j.wysocki, rjw; +Cc: todd.e.brandt, todd.e.brandt
Config/man page/README files:
- include the README in the pm-graph folder
- add more detail to the example config to describe more options
- update the sleepgraph man page to document the new arguments
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
tools/power/pm-graph/README | 552 ++++++++++++++++++++++++++++++++
tools/power/pm-graph/config/example.cfg | 26 ++
tools/power/pm-graph/sleepgraph.8 | 16 +-
3 files changed, 592 insertions(+), 2 deletions(-)
create mode 100644 tools/power/pm-graph/README
diff --git a/tools/power/pm-graph/README b/tools/power/pm-graph/README
new file mode 100644
index 000000000000..58a5591e3951
--- /dev/null
+++ b/tools/power/pm-graph/README
@@ -0,0 +1,552 @@
+ p m - g r a p h
+
+ pm-graph: suspend/resume/boot timing analysis tools
+ Version: 5.4
+ Author: Todd Brandt <todd.e.brandt@intel.com>
+ Home Page: https://01.org/pm-graph
+
+ Report bugs/issues at bugzilla.kernel.org Tools/pm-graph
+ - https://bugzilla.kernel.org/buglist.cgi?component=pm-graph&product=Tools
+
+ Full documentation available online & in man pages
+ - Getting Started:
+ https://01.org/pm-graph/documentation/getting-started
+
+ - Config File Format:
+ https://01.org/pm-graph/documentation/3-config-file-format
+
+ - upstream version in git:
+ https://github.com/intel/pm-graph/
+
+ Table of Contents
+ - Overview
+ - Setup
+ - Usage
+ - Basic Usage
+ - Dev Mode Usage
+ - Proc Mode Usage
+ - Configuration Files
+ - Usage Examples
+ - Config File Options
+ - Custom Timeline Entries
+ - Adding/Editing Timeline Functions
+ - Adding/Editing Dev Timeline Source Functions
+ - Verifying your Custom Functions
+ - Testing on consumer linux Operating Systems
+ - Android
+
+------------------------------------------------------------------
+| OVERVIEW |
+------------------------------------------------------------------
+
+ This tool suite is designed to assist kernel and OS developers in optimizing
+ their linux stack's suspend/resume & boot time. Using a kernel image built
+ with a few extra options enabled, the tools will execute a suspend or boot,
+ and will capture dmesg and ftrace data. This data is transformed into a set of
+ timelines and a callgraph to give a quick and detailed view of which devices
+ and kernel processes are taking the most time in suspend/resume & boot.
+
+------------------------------------------------------------------
+| SETUP |
+------------------------------------------------------------------
+
+ These packages are required to execute the scripts
+ - python
+ - python-requests
+
+ Ubuntu:
+ sudo apt-get install python python-requests
+
+ Fedora:
+ sudo dnf install python python-requests
+
+ The tools can most easily be installed via git clone and make install
+
+ $> git clone http://github.com/intel/pm-graph.git
+ $> cd pm-graph
+ $> sudo make install
+ $> man sleepgraph ; man bootgraph
+
+ Setup involves some minor kernel configuration
+
+ The following kernel build options are required for all kernels:
+ CONFIG_DEVMEM=y
+ CONFIG_PM_DEBUG=y
+ CONFIG_PM_SLEEP_DEBUG=y
+ CONFIG_FTRACE=y
+ CONFIG_FUNCTION_TRACER=y
+ CONFIG_FUNCTION_GRAPH_TRACER=y
+ CONFIG_KPROBES=y
+ CONFIG_KPROBES_ON_FTRACE=y
+
+ In kernel 3.15.0, two patches were upstreamed which enable the
+ v3.0 behavior. These patches allow the tool to read all the
+ data from trace events instead of from dmesg. You can enable
+ this behavior on earlier kernels with these patches:
+
+ (kernel/pre-3.15/enable_trace_events_suspend_resume.patch)
+ (kernel/pre-3.15/enable_trace_events_device_pm_callback.patch)
+
+ If you're using a kernel older than 3.15.0, the following
+ additional kernel parameters are required:
+ (e.g. in file /etc/default/grub)
+ GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=32M ..."
+
+ If you're using a kernel older than 3.11-rc2, the following simple
+ patch must be applied to enable ftrace data:
+ in file: kernel/power/suspend.c
+ in function: int suspend_devices_and_enter(suspend_state_t state)
+ remove call to "ftrace_stop();"
+ remove call to "ftrace_start();"
+
+ There is a patch which does this for kernel v3.8.0:
+ (kernel/pre-3.11-rc2/enable_ftrace_in_suspendresume.patch)
+
+
+
+------------------------------------------------------------------
+| USAGE |
+------------------------------------------------------------------
+
+Basic Usage
+___________
+
+ 1) First configure a kernel using the instructions from the previous sections.
+ Then build, install, and boot with it.
+ 2) Open up a terminal window and execute the mode list command:
+
+ %> sudo ./sleepgraph.py -modes
+ ['freeze', 'mem', 'disk']
+
+ Execute a test using one of the available power modes, e.g. mem (S3):
+
+ %> sudo ./sleepgraph.py -m mem -rtcwake 15
+
+ or with a config file
+
+ %> sudo ./sleepgraph.py -config config/suspend.cfg
+
+ When the system comes back you'll see the script finishing up and
+ creating the output files in the test subdir. It generates output
+ files in subdirectory: suspend-mmddyy-HHMMSS. The ftrace file can
+ be used to regenerate the html timeline with different options
+
+ HTML output: <hostname>_<mode>.html
+ raw dmesg output: <hostname>_<mode>_dmesg.txt
+ raw ftrace output: <hostname>_<mode>_ftrace.txt
+
+ View the html in firefox or chrome.
+
+
+Dev Mode Usage
+______________
+
+ Developer mode adds information on low level source calls to the timeline.
+ The tool sets kprobes on all delay and mutex calls to see which devices
+ are waiting for something and when. It also sets a suite of kprobes on
+ subsystem dependent calls to better fill out the timeline.
+
+ The tool will also expose kernel threads that don't normally show up in the
+ timeline. This is useful in discovering dependent threads to get a better
+ idea of what each device is waiting for. For instance, the scsi_eh thread,
+ a.k.a. scsi resume error handler, is what each SATA disk device waits for
+ before it can continue resume.
+
+ The timeline will be much larger if run with dev mode, so it can be useful
+ to set the -mindev option to clip out any device blocks that are too small
+ to see easily. The following command will give a nice dev mode run:
+
+ %> sudo ./sleepgraph.py -m mem -rtcwake 15 -mindev 1 -dev
+
+ or with a config file
+
+ %> sudo ./sleepgraph.py -config config/suspend-dev.cfg
+
+
+Proc Mode Usage
+_______________
+
+ Proc mode adds user process info to the timeline. This is done in a manner
+ similar to the bootchart utility, which graphs init processes and their
+ execution as the system boots. This tool option does the same thing but for
+ the period before and after suspend/resume.
+
+ In order to see any process info, there needs to be some delay before or
+ after resume since processes are frozen in suspend_prepare and thawed in
+ resume_complete. The predelay and postdelay args allow you to do this. It
+ can also be useful to run in x2 mode with an x2 delay, this way you can
+ see process activity before and after resume, and in between two
+ successive suspend/resumes.
+
+ The command can be run like this:
+
+ %> sudo ./sleepgraph.py -m mem -rtcwake 15 -x2 -x2delay 1000 -predelay 1000 -postdelay 1000 -proc
+
+ or with a config file
+
+ %> sudo ./sleepgraph.py -config config/suspend-proc.cfg
+
+
+------------------------------------------------------------------
+| CONFIGURATION FILES |
+------------------------------------------------------------------
+
+ Since 4.0 we've moved to using config files in lieu of command line options.
+ The config folder contains a collection of typical use cases.
+ There are corresponding configs for other power modes:
+
+ Simple suspend/resume with basic timeline (mem/freeze/standby)
+ config/suspend.cfg
+ config/freeze.cfg
+ config/standby.cfg
+
+ Dev mode suspend/resume with dev timeline (mem/freeze/standby)
+ config/suspend-dev.cfg
+ config/freeze-dev.cfg
+ config/standby-dev.cfg
+
+ Simple suspend/resume with timeline and callgraph (mem/freeze/standby)
+ config/suspend-callgraph.cfg
+ config/freeze-callgraph.cfg
+ config/standby-callgraph.cfg
+
+ Sample proc mode x2 run using mem suspend
+ config/suspend-x2-proc.cfg
+
+ Sample for editing timeline funcs (moves internal functions into config)
+ config/custom-timeline-functions.cfg
+
+ Sample debug config for serio subsystem
+ config/debug-serio-suspend.cfg
+
+
+Usage Examples
+______________
+
+ Run a simple mem suspend:
+ %> sudo ./sleepgraph.py -config config/suspend.cfg
+
+ Run a mem suspend with callgraph data:
+ %> sudo ./sleepgraph.py -config config/suspend-callgraph.cfg
+
+ Run a mem suspend with dev mode detail:
+ %> sudo ./sleepgraph.py -config config/suspend-dev.cfg
+
+
+Config File Options
+___________________
+
+ [Settings]
+
+ # Verbosity: print verbose messages (def: false)
+ verbose: false
+
+ # Suspend Mode: e.g. standby, mem, freeze, disk (def: mem)
+ mode: mem
+
+ # Output Directory Format: {hostname}, {date}, {time} give current values
+ output-dir: suspend-{hostname}-{date}-{time}
+
+ # Automatic Wakeup: use rtcwake to wakeup after X seconds (def: infinity)
+ rtcwake: 15
+
+ # Add Logs: add the dmesg and ftrace log to the html output (def: false)
+ addlogs: false
+
+ # Sus/Res Gap: insert a gap between sus & res in the timeline (def: false)
+ srgap: false
+
+ # Custom Command: Command to execute in lieu of suspend (def: "")
+ command: echo mem > /sys/power/state
+
+ # Proc mode: graph user processes and cpu usage in the timeline (def: false)
+ proc: false
+
+ # Dev mode: graph source functions in the timeline (def: false)
+ dev: false
+
+ # Suspend/Resume x2: run 2 suspend/resumes back to back (def: false)
+ x2: false
+
+ # x2 Suspend Delay: time delay between the two test runs in ms (def: 0 ms)
+ x2delay: 0
+
+ # Pre Suspend Delay: nclude an N ms delay before (1st) suspend (def: 0 ms)
+ predelay: 0
+
+ # Post Resume Delay: include an N ms delay after (last) resume (def: 0 ms)
+ postdelay: 0
+
+ # Min Device Length: graph only dev callbacks longer than min (def: 0.001 ms)
+ mindev: 0.001
+
+ # Callgraph: gather ftrace callgraph data on all timeline events (def: false)
+ callgraph: false
+
+ # Expand Callgraph: pre-expand the callgraph treeviews in html (def: false)
+ expandcg: false
+
+ # Min Callgraph Length: show callgraphs only if longer than min (def: 1 ms)
+ mincg: 1
+
+ # Timestamp Precision: number of sig digits in timestamps (0:S, [3:ms], 6:us)
+ timeprec: 3
+
+ # Device Filter: show only devs whose name/driver includes one of these strings
+ devicefilter: _cpu_up,_cpu_down,i915,usb
+
+ # Override default timeline entries:
+ # Do not use the internal default functions for timeline entries (def: false)
+ # Set this to true if you intend to only use the ones defined in the config
+ override-timeline-functions: true
+
+ # Override default dev timeline entries:
+ # Do not use the internal default functions for dev timeline entries (def: false)
+ # Set this to true if you intend to only use the ones defined in the config
+ override-dev-timeline-functions: true
+
+ # Call Loop Max Gap (dev mode only)
+ # merge loops of the same call if each is less than maxgap apart (def: 100us)
+ callloop-maxgap: 0.0001
+
+ # Call Loop Max Length (dev mode only)
+ # merge loops of the same call if each is less than maxlen in length (def: 5ms)
+ callloop-maxlen: 0.005
+
+------------------------------------------------------------------
+| CUSTOM TIMELINE ENTRIES |
+------------------------------------------------------------------
+
+Adding or Editing Timeline Functions
+____________________________________
+
+ The tool uses an array of function names to fill out empty spaces in the
+ timeline where device callbacks don't appear. For instance, in suspend_prepare
+ the tool adds the sys_sync and freeze_processes calls as virtual device blocks
+ in the timeline to show you where the time is going. These calls should fill
+ the timeline with contiguous data so that most kernel execution is covered.
+
+ It is possible to add new function calls to the timeline by adding them to
+ the config. It's also possible to copy the internal timeline functions into
+ the config so that you can override and edit them. Place them in the
+ timeline_functions_ARCH section with the name of your architecture appended.
+ i.e. for x86_64: [timeline_functions_x86_64]
+
+ Use the override-timeline-functions option if you only want to use your
+ custom calls, or leave it false to append them to the internal ones.
+
+ This section includes a list of functions (set using kprobes) which use both
+ symbol data and function arg data. The args are pulled directly from the
+ stack using this architecture's registers and stack formatting. Each entry
+ can include up to four pieces of info: The function name, a format string,
+ an argument list, and a color. But only a function name is required.
+
+ For a full example config, see config/custom-timeline-functions.cfg. It pulls
+ all the internal timeline functions into the config and allows you to edit
+ them.
+
+ Entry format:
+
+ function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple]
+
+ Required Arguments:
+
+ function: The symbol name for the function you want probed, this is the
+ minimum required for an entry, it will show up as the function
+ name with no arguments.
+
+ example: _cpu_up:
+
+ Optional Arguments:
+
+ format: The format to display the data on the timeline in. Use braces to
+ enclose the arg names.
+
+ example: CPU_ON[{cpu}]
+
+ color: The color of the entry block in the timeline. The default color is
+ transparent, so the entry shares the phase color. The color is an
+ html color string, either a word, or an RGB.
+
+ example: [color=#CC00CC]
+
+ arglist: A list of arguments from registers/stack addresses. See URL:
+ https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt
+
+ example: cpu=%di:s32
+
+ Here is a full example entry. It displays cpu resume calls in the timeline
+ in orange. They will appear as CPU_ON[0], CPU_ON[1], etc.
+
+ [timeline_functions_x86_64]
+ _cpu_up: CPU_ON[{cpu}] cpu=%di:s32 [color=orange]
+
+
+Adding or Editing Dev Mode Timeline Source Functions
+____________________________________________________
+
+ In dev mode, the tool uses an array of function names to monitor source
+ execution within the timeline entries.
+
+ The function calls are displayed inside the main device/call blocks in the
+ timeline. However, if a function call is not within a main timeline event,
+ it will spawn an entirely new event named after the caller's kernel thread.
+ These asynchronous kernel threads will populate in a separate section
+ beneath the main device/call section.
+
+ The tool has a set of hard coded calls which focus on the most common use
+ cases: msleep, udelay, schedule_timeout, mutex_lock_slowpath, etc. These are
+ the functions that add a hardcoded time delay to the suspend/resume path.
+ The tool also includes some common functions native to important
+ subsystems: ata, i915, and ACPI, etc.
+
+ It is possible to add new function calls to the dev timeline by adding them
+ to the config. It's also possible to copy the internal dev timeline
+ functions into the config so that you can override and edit them. Place them
+ in the dev_timeline_functions_ARCH section with the name of your architecture
+ appended. i.e. for x86_64: [dev_timeline_functions_x86_64]
+
+ Use the override-dev-timeline-functions option if you only want to use your
+ custom calls, or leave it false to append them to the internal ones.
+
+ The format is the same as the timeline_functions_x86_64 section. It's a
+ list of functions (set using kprobes) which use both symbol data and function
+ arg data. The args are pulled directly from the stack using this
+ architecture's registers and stack formatting. Each entry can include up
+ to four pieces of info: The function name, a format string, an argument list,
+ and a color. But only the function name is required.
+
+ For a full example config, see config/custom-timeline-functions.cfg. It pulls
+ all the internal dev timeline functions into the config and allows you to edit
+ them.
+
+ Here is a full example entry. It displays the ATA port reset calls as
+ ataN_port_reset in the timeline. This is where most of the SATA disk resume
+ time goes, so it can be helpful to see the low level call.
+
+ [dev_timeline_functions_x86_64]
+ ata_eh_recover: ata{port}_port_reset port=+36(%di):s32 [color=#CC00CC]
+
+
+Verifying your custom functions
+_______________________________
+
+ Once you have a set of functions (kprobes) defined, it can be useful to
+ perform a quick check to see if you formatted them correctly and if the system
+ actually supports them. To do this, run the tool with your config file
+ and the -status option. The tool will go through all the kprobes (both
+ custom and internal if you haven't overridden them) and actually attempts
+ to set them in ftrace. It will then print out success or fail for you.
+
+ Note that kprobes which don't actually exist in the kernel won't stop the
+ tool, they just wont show up.
+
+ For example:
+
+ sudo ./sleepgraph.py -config config/custom-timeline-functions.cfg -status
+ Checking this system (myhostname)...
+ have root access: YES
+ is sysfs mounted: YES
+ is "mem" a valid power mode: YES
+ is ftrace supported: YES
+ are kprobes supported: YES
+ timeline data source: FTRACE (all trace events found)
+ is rtcwake supported: YES
+ verifying timeline kprobes work:
+ _cpu_down: YES
+ _cpu_up: YES
+ acpi_pm_finish: YES
+ acpi_pm_prepare: YES
+ freeze_kernel_threads: YES
+ freeze_processes: YES
+ sys_sync: YES
+ thaw_processes: YES
+ verifying dev kprobes work:
+ __const_udelay: YES
+ __mutex_lock_slowpath: YES
+ acpi_os_stall: YES
+ acpi_ps_parse_aml: YES
+ intel_opregion_init: NO
+ intel_opregion_register: NO
+ intel_opregion_setup: NO
+ msleep: YES
+ schedule_timeout: YES
+ schedule_timeout_uninterruptible: YES
+ usleep_range: YES
+
+
+------------------------------------------------------------------
+| TESTING ON CONSUMER LINUX OPERATING SYSTEMS |
+------------------------------------------------------------------
+
+Android
+_______
+
+ The easiest way to execute on an android device is to run the android.sh
+ script on the device, then pull the ftrace log back to the host and run
+ sleepgraph.py on it.
+
+ Here are the steps:
+
+ [download and install the tool on the device]
+
+ host%> wget https://raw.githubusercontent.com/intel/pm-graph/master/tools/android.sh
+ host%> adb connect 192.168.1.6
+ host%> adb root
+ # push the script to a writeable location
+ host%> adb push android.sh /sdcard/
+
+ [check whether the tool will run on your device]
+
+ host%> adb shell
+ dev%> cd /sdcard
+ dev%> sh android.sh status
+ host : asus_t100
+ kernel : 3.14.0-i386-dirty
+ modes : freeze mem
+ rtcwake : supported
+ ftrace : supported
+ trace events {
+ suspend_resume: found
+ device_pm_callback_end: found
+ device_pm_callback_start: found
+ }
+ # the above is what you see on a system that's properly patched
+
+ [execute the suspend]
+
+ # NOTE: The suspend will only work if the screen isn't timed out,
+ # so you have to press some keys first to wake it up b4 suspend)
+ dev%> sh android.sh suspend mem
+ ------------------------------------
+ Suspend/Resume timing test initiated
+ ------------------------------------
+ hostname : asus_t100
+ kernel : 3.14.0-i386-dirty
+ mode : mem
+ ftrace out : /mnt/shell/emulated/0/ftrace.txt
+ dmesg out : /mnt/shell/emulated/0/dmesg.txt
+ log file : /mnt/shell/emulated/0/log.txt
+ ------------------------------------
+ INITIALIZING FTRACE........DONE
+ STARTING FTRACE
+ SUSPEND START @ 21:24:02 (rtcwake in 10 seconds)
+ <adb connection will now terminate>
+
+ [retrieve the data from the device]
+
+ # I find that you have to actually kill the adb process and
+ # reconnect sometimes in order for the connection to work post-suspend
+ host%> adb connect 192.168.1.6
+ # (required) get the ftrace data, this is the most important piece
+ host%> adb pull /sdcard/ftrace.txt
+ # (optional) get the dmesg data, this is for debugging
+ host%> adb pull /sdcard/dmesg.txt
+ # (optional) get the log, which just lists some test times for comparison
+ host%> adb pull /sdcard/log.txt
+
+ [create an output html file using sleepgraph.py]
+
+ host%> sleepgraph.py -ftrace ftrace.txt
+
+ You should now have an output.html with the android data, enjoy!
diff --git a/tools/power/pm-graph/config/example.cfg b/tools/power/pm-graph/config/example.cfg
index 05b2efb9bb54..1ef3eb9383fa 100644
--- a/tools/power/pm-graph/config/example.cfg
+++ b/tools/power/pm-graph/config/example.cfg
@@ -98,12 +98,34 @@ postdelay: 0
# graph only devices longer than min in the timeline (default: 0.001 ms)
mindev: 0.001
+# Call Loop Max Gap (dev mode only)
+# merge loops of the same call if each is less than maxgap apart (def: 100us)
+callloop-maxgap: 0.0001
+
+# Call Loop Max Length (dev mode only)
+# merge loops of the same call if each is less than maxlen in length (def: 5ms)
+callloop-maxlen: 0.005
+
+# Override default timeline entries:
+# Do not use the internal default functions for timeline entries (def: false)
+# Set this to true if you intend to only use the ones defined in the config
+override-timeline-functions: true
+
+# Override default dev timeline entries:
+# Do not use the internal default functions for dev timeline entries (def: false)
+# Set this to true if you intend to only use the ones defined in the config
+override-dev-timeline-functions: true
+
# ---- Debug Options ----
# Callgraph
# gather detailed ftrace callgraph data on all timeline events (default: false)
callgraph: false
+# Max graph depth
+# limit the callgraph trace to this depth (default: 0 = all)
+maxdepth: 2
+
# Callgraph phase filter
# Only enable callgraphs for one phase, i.e. resume_noirq (default: all)
cgphase: suspend
@@ -131,3 +153,7 @@ timeprec: 6
# Add kprobe functions to the timeline
# Add functions to the timeline from a text file (default: no-action)
# fadd: file.txt
+
+# Ftrace buffer size
+# Set trace buffer size to N kilo-bytes (default: all of free memory up to 3GB)
+# bufsize: 1000
diff --git a/tools/power/pm-graph/sleepgraph.8 b/tools/power/pm-graph/sleepgraph.8
index 24a2e7d0ae63..9648be644d5f 100644
--- a/tools/power/pm-graph/sleepgraph.8
+++ b/tools/power/pm-graph/sleepgraph.8
@@ -53,6 +53,11 @@ disable rtcwake and require a user keypress to resume.
Add the dmesg and ftrace logs to the html output. They will be viewable by
clicking buttons in the timeline.
.TP
+\fB-turbostat\fR
+Use turbostat to execute the command in freeze mode (default: disabled). This
+will provide turbostat output in the log which will tell you which actual
+power modes were entered.
+.TP
\fB-result \fIfile\fR
Export a results table to a text file for parsing.
.TP
@@ -121,6 +126,10 @@ be created in a new subdirectory with a summary page: suspend-xN-{date}-{time}.
Use ftrace to create device callgraphs (default: disabled). This can produce
very large outputs, i.e. 10MB - 100MB.
.TP
+\fB-ftop\fR
+Use ftrace on the top level call: "suspend_devices_and_enter" only (default: disabled).
+This option implies -f and creates a single callgraph covering all of suspend/resume.
+.TP
\fB-maxdepth \fIlevel\fR
limit the callgraph trace depth to \fIlevel\fR (default: 0=all). This is
the best way to limit the output size when using callgraphs via -f.
@@ -138,8 +147,8 @@ which are barely visible in the timeline.
The value is a float: e.g. 0.001 represents 1 us.
.TP
\fB-cgfilter \fI"func1,func2,..."\fR
-Reduce callgraph output in the timeline by limiting it to a list of calls. The
-argument can be a single function name or a comma delimited list.
+Reduce callgraph output in the timeline by limiting it certain devices. The
+argument can be a single device name or a comma delimited list.
(default: none)
.TP
\fB-cgskip \fIfile\fR
@@ -183,6 +192,9 @@ Print out the contents of the ACPI Firmware Performance Data Table.
\fB-battery\fR
Print out battery status and current charge.
.TP
+\fB-wifi\fR
+Print out wifi status and connection details.
+.TP
\fB-xon/-xoff/-xstandby/-xsuspend\fR
Test xset by attempting to switch the display to the given mode. This
is the same command which will be issued by \fB-display \fImode\fR.
--
2.14.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH 0/3] pm-graph 5.4
2019-05-14 17:53 [PATCH 0/3] pm-graph 5.4 Todd Brandt
` (2 preceding siblings ...)
2019-05-14 17:53 ` [PATCH 3/3] pm-graph 5.4 config and other files Todd Brandt
@ 2019-05-31 9:27 ` Rafael J. Wysocki
3 siblings, 0 replies; 5+ messages in thread
From: Rafael J. Wysocki @ 2019-05-31 9:27 UTC (permalink / raw)
To: Todd Brandt; +Cc: linux-pm, rafael.j.wysocki, todd.e.brandt
On Tuesday, May 14, 2019 7:53:56 PM CEST Todd Brandt wrote:
> Considerable upgrades to the summary functionality, as well as
> new sources of data from turbostat and mcelog. ACPI methods are now
> traceable in the timeline as well in dev mode.
>
> Todd Brandt (3):
> Update to pm-graph 5.3
> Update to pm-graph 5.4
> pm-graph 5.4 config and other files
>
> tools/power/pm-graph/README | 552 ++++++++++++++++++++
> tools/power/pm-graph/bootgraph.py | 8 +-
> tools/power/pm-graph/config/example.cfg | 26 +
> tools/power/pm-graph/sleepgraph.8 | 16 +-
> tools/power/pm-graph/sleepgraph.py | 857 ++++++++++++++++++++++++--------
> 5 files changed, 1253 insertions(+), 206 deletions(-)
> create mode 100644 tools/power/pm-graph/README
>
>
All three applied, thanks!
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2019-05-31 9:27 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2019-05-14 17:53 [PATCH 0/3] pm-graph 5.4 Todd Brandt
2019-05-14 17:53 ` [PATCH 1/3] Update to pm-graph 5.3 Todd Brandt
2019-05-14 17:53 ` [PATCH 2/3] Update to pm-graph 5.4 Todd Brandt
2019-05-14 17:53 ` [PATCH 3/3] pm-graph 5.4 config and other files Todd Brandt
2019-05-31 9:27 ` [PATCH 0/3] pm-graph 5.4 Rafael J. Wysocki
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox