ee8b09cd60
This tool is designed to assist kernel and OS developers in optimizing their linux stack's suspend/resume time. Using a kernel image built with a few extra options enabled, the tool will execute a suspend and will capture dmesg and ftrace data until resume is complete. This data is transformed into a device timeline and a callgraph to give a quick and detailed view of which devices and callbacks are taking the most time in suspend/resume. The output is a single html file which can be viewed in firefox or chrome. References: https://01.org/suspendresume Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
1446 lines
48 KiB
Python
Executable file
1446 lines
48 KiB
Python
Executable file
#!/usr/bin/python
|
|
#
|
|
# Tool for analyzing suspend/resume timing
|
|
# Copyright (c) 2013, Intel Corporation.
|
|
#
|
|
# This program is free software; you can redistribute it and/or modify it
|
|
# under the terms and conditions of the GNU General Public License,
|
|
# version 2, as published by the Free Software Foundation.
|
|
#
|
|
# This program is distributed in the hope it will be useful, but WITHOUT
|
|
# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
|
|
# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
|
|
# more details.
|
|
#
|
|
# You should have received a copy of the GNU General Public License along with
|
|
# this program; if not, write to the Free Software Foundation, Inc.,
|
|
# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
|
|
#
|
|
# Authors:
|
|
# Todd Brandt <todd.e.brandt@linux.intel.com>
|
|
#
|
|
# Description:
|
|
# This tool is designed to assist kernel and OS developers in optimizing
|
|
# their linux stack's suspend/resume time. Using a kernel image built
|
|
# with a few extra options enabled, the tool will execute a suspend and
|
|
# will capture dmesg and ftrace data until resume is complete. This data
|
|
# is transformed into a device timeline and a callgraph to give a quick
|
|
# and detailed view of which devices and callbacks are taking the most
|
|
# time in suspend/resume. The output is a single html file which can be
|
|
# viewed in firefox or chrome.
|
|
#
|
|
# The following kernel build options are required:
|
|
# CONFIG_PM_DEBUG=y
|
|
# CONFIG_PM_SLEEP_DEBUG=y
|
|
# CONFIG_FTRACE=y
|
|
# CONFIG_FUNCTION_TRACER=y
|
|
# CONFIG_FUNCTION_GRAPH_TRACER=y
|
|
#
|
|
# The following additional kernel parameters are required:
|
|
# (e.g. in file /etc/default/grub)
|
|
# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
|
|
#
|
|
|
|
import sys
|
|
import time
|
|
import os
|
|
import string
|
|
import re
|
|
import array
|
|
import platform
|
|
import datetime
|
|
import struct
|
|
|
|
# -- classes --
|
|
|
|
class SystemValues:
|
|
testdir = "."
|
|
tpath = "/sys/kernel/debug/tracing/"
|
|
mempath = "/dev/mem"
|
|
powerfile = "/sys/power/state"
|
|
suspendmode = "mem"
|
|
prefix = "test"
|
|
teststamp = ""
|
|
dmesgfile = ""
|
|
ftracefile = ""
|
|
htmlfile = ""
|
|
rtcwake = False
|
|
def setOutputFile(self):
|
|
if((self.htmlfile == "") and (self.dmesgfile != "")):
|
|
m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile)
|
|
if(m):
|
|
self.htmlfile = m.group("name")+".html"
|
|
if((self.htmlfile == "") and (self.ftracefile != "")):
|
|
m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile)
|
|
if(m):
|
|
self.htmlfile = m.group("name")+".html"
|
|
if(self.htmlfile == ""):
|
|
self.htmlfile = "output.html"
|
|
def initTestOutput(self):
|
|
hostname = platform.node()
|
|
if(hostname != ""):
|
|
self.prefix = hostname
|
|
v = os.popen("cat /proc/version").read().strip()
|
|
kver = string.split(v)[2]
|
|
self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip()
|
|
self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver
|
|
self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt"
|
|
self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt"
|
|
self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html"
|
|
os.mkdir(self.testdir)
|
|
|
|
class Data:
|
|
altdevname = dict()
|
|
usedmesg = False
|
|
useftrace = False
|
|
notestrun = False
|
|
verbose = False
|
|
phases = []
|
|
dmesg = {} # root data structure
|
|
start = 0.0
|
|
end = 0.0
|
|
stamp = {'time': "", 'host': "", 'mode': ""}
|
|
id = 0
|
|
tSuspended = 0.0
|
|
fwValid = False
|
|
fwSuspend = 0
|
|
fwResume = 0
|
|
def initialize(self):
|
|
self.dmesg = { # dmesg log data
|
|
'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "#CCFFCC", 'order': 0},
|
|
'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "green", 'order': 1},
|
|
'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "#00FFFF", 'order': 2},
|
|
'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "blue", 'order': 3},
|
|
'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "red", 'order': 4},
|
|
'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "orange", 'order': 5},
|
|
'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "yellow", 'order': 6},
|
|
'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
|
|
'row': 0, 'color': "#FFFFCC", 'order': 7}
|
|
}
|
|
self.phases = self.sortedPhases()
|
|
def normalizeTime(self):
|
|
tSus = tRes = self.tSuspended
|
|
if self.fwValid:
|
|
tSus -= -self.fwSuspend / 1000000000.0
|
|
tRes -= self.fwResume / 1000000000.0
|
|
self.tSuspended = 0.0
|
|
self.start -= tSus
|
|
self.end -= tRes
|
|
for phase in self.phases:
|
|
zero = tRes
|
|
if "suspend" in phase:
|
|
zero = tSus
|
|
p = self.dmesg[phase]
|
|
p['start'] -= zero
|
|
p['end'] -= zero
|
|
list = p['list']
|
|
for name in list:
|
|
d = list[name]
|
|
d['start'] -= zero
|
|
d['end'] -= zero
|
|
if('ftrace' in d):
|
|
cg = d['ftrace']
|
|
cg.start -= zero
|
|
cg.end -= zero
|
|
for line in cg.list:
|
|
line.time -= zero
|
|
if self.fwValid:
|
|
fws = -self.fwSuspend / 1000000000.0
|
|
fwr = self.fwResume / 1000000000.0
|
|
list = dict()
|
|
self.id += 1
|
|
devid = "dc%d" % self.id
|
|
list["firmware-suspend"] = \
|
|
{'start': fws, 'end': 0, 'pid': 0, 'par': "",
|
|
'length': -fws, 'row': 0, 'id': devid };
|
|
self.id += 1
|
|
devid = "dc%d" % self.id
|
|
list["firmware-resume"] = \
|
|
{'start': 0, 'end': fwr, 'pid': 0, 'par': "",
|
|
'length': fwr, 'row': 0, 'id': devid };
|
|
self.dmesg['BIOS'] = \
|
|
{'list': list, 'start': fws, 'end': fwr,
|
|
'row': 0, 'color': "purple", 'order': 4}
|
|
self.dmesg['resume_cpu']['order'] += 1
|
|
self.dmesg['resume_noirq']['order'] += 1
|
|
self.dmesg['resume_early']['order'] += 1
|
|
self.dmesg['resume_general']['order'] += 1
|
|
self.phases = self.sortedPhases()
|
|
def vprint(self, msg):
|
|
if(self.verbose):
|
|
print(msg)
|
|
def dmesgSortVal(self, phase):
|
|
return self.dmesg[phase]['order']
|
|
def sortedPhases(self):
|
|
return sorted(self.dmesg, key=self.dmesgSortVal)
|
|
def sortedDevices(self, phase):
|
|
list = self.dmesg[phase]['list']
|
|
slist = []
|
|
tmp = dict()
|
|
for devname in list:
|
|
dev = list[devname]
|
|
tmp[dev['start']] = devname
|
|
for t in sorted(tmp):
|
|
slist.append(tmp[t])
|
|
return slist
|
|
def fixupInitcalls(self, phase, end):
|
|
# if any calls never returned, clip them at system resume end
|
|
phaselist = self.dmesg[phase]['list']
|
|
for devname in phaselist:
|
|
dev = phaselist[devname]
|
|
if(dev['end'] < 0):
|
|
dev['end'] = end
|
|
self.vprint("%s (%s): callback didn't return" % (devname, phase))
|
|
def fixupInitcallsThatDidntReturn(self):
|
|
# if any calls never returned, clip them at system resume end
|
|
for phase in self.phases:
|
|
self.fixupInitcalls(phase, self.dmesg['resume_general']['end'])
|
|
if(phase == "resume_general"):
|
|
break
|
|
def newAction(self, phase, name, pid, parent, start, end):
|
|
self.id += 1
|
|
devid = "dc%d" % self.id
|
|
list = self.dmesg[phase]['list']
|
|
length = -1.0
|
|
if(start >= 0 and end >= 0):
|
|
length = end - start
|
|
list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
|
|
'length': length, 'row': 0, 'id': devid }
|
|
def deviceIDs(self, devlist, phase):
|
|
idlist = []
|
|
for p in self.phases:
|
|
if(p[0] != phase[0]):
|
|
continue
|
|
list = data.dmesg[p]['list']
|
|
for devname in list:
|
|
if devname in devlist:
|
|
idlist.append(list[devname]['id'])
|
|
return idlist
|
|
def deviceParentID(self, devname, phase):
|
|
pdev = ""
|
|
pdevid = ""
|
|
for p in self.phases:
|
|
if(p[0] != phase[0]):
|
|
continue
|
|
list = data.dmesg[p]['list']
|
|
if devname in list:
|
|
pdev = list[devname]['par']
|
|
for p in self.phases:
|
|
if(p[0] != phase[0]):
|
|
continue
|
|
list = data.dmesg[p]['list']
|
|
if pdev in list:
|
|
return list[pdev]['id']
|
|
return pdev
|
|
def deviceChildrenIDs(self, devname, phase):
|
|
devlist = []
|
|
for p in self.phases:
|
|
if(p[0] != phase[0]):
|
|
continue
|
|
list = data.dmesg[p]['list']
|
|
for child in list:
|
|
if(list[child]['par'] == devname):
|
|
devlist.append(child)
|
|
return self.deviceIDs(devlist, phase)
|
|
|
|
class FTraceLine:
|
|
time = 0.0
|
|
length = 0.0
|
|
fcall = False
|
|
freturn = False
|
|
fevent = False
|
|
depth = 0
|
|
name = ""
|
|
def __init__(self, t, m, d):
|
|
self.time = float(t)
|
|
# check to see if this is a trace event
|
|
em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m)
|
|
if(em):
|
|
self.name = em.group("msg")
|
|
self.fevent = True
|
|
return
|
|
# convert the duration to seconds
|
|
if(d):
|
|
self.length = float(d)/1000000
|
|
# the indentation determines the depth
|
|
match = re.match(r"^(?P<d> *)(?P<o>.*)$", m)
|
|
if(not match):
|
|
return
|
|
self.depth = self.getDepth(match.group('d'))
|
|
m = match.group('o')
|
|
# function return
|
|
if(m[0] == '}'):
|
|
self.freturn = True
|
|
if(len(m) > 1):
|
|
# includes comment with function name
|
|
match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m)
|
|
if(match):
|
|
self.name = match.group('n')
|
|
# function call
|
|
else:
|
|
self.fcall = True
|
|
# function call with children
|
|
if(m[-1] == '{'):
|
|
match = re.match(r"^(?P<n>.*) *\(.*", m)
|
|
if(match):
|
|
self.name = match.group('n')
|
|
# function call with no children (leaf)
|
|
elif(m[-1] == ';'):
|
|
self.freturn = True
|
|
match = re.match(r"^(?P<n>.*) *\(.*", m)
|
|
if(match):
|
|
self.name = match.group('n')
|
|
# something else (possibly a trace marker)
|
|
else:
|
|
self.name = m
|
|
def getDepth(self, str):
|
|
return len(str)/2
|
|
|
|
class FTraceCallGraph:
|
|
start = -1.0
|
|
end = -1.0
|
|
list = []
|
|
invalid = False
|
|
depth = 0
|
|
def __init__(self):
|
|
self.start = -1.0
|
|
self.end = -1.0
|
|
self.list = []
|
|
self.depth = 0
|
|
def setDepth(self, line):
|
|
if(line.fcall and not line.freturn):
|
|
line.depth = self.depth
|
|
self.depth += 1
|
|
elif(line.freturn and not line.fcall):
|
|
self.depth -= 1
|
|
line.depth = self.depth
|
|
else:
|
|
line.depth = self.depth
|
|
def addLine(self, line, match):
|
|
if(not self.invalid):
|
|
self.setDepth(line)
|
|
if(line.depth == 0 and line.freturn):
|
|
self.end = line.time
|
|
self.list.append(line)
|
|
return True
|
|
if(self.invalid):
|
|
return False
|
|
if(len(self.list) >= 1000000 or self.depth < 0):
|
|
first = self.list[0]
|
|
self.list = []
|
|
self.list.append(first)
|
|
self.invalid = True
|
|
id = "task %s cpu %s" % (match.group("pid"), match.group("cpu"))
|
|
window = "(%f - %f)" % (self.start, line.time)
|
|
data.vprint("Too much data for "+id+" "+window+", ignoring this callback")
|
|
return False
|
|
self.list.append(line)
|
|
if(self.start < 0):
|
|
self.start = line.time
|
|
return False
|
|
def sanityCheck(self):
|
|
stack = dict()
|
|
cnt = 0
|
|
for l in self.list:
|
|
if(l.fcall and not l.freturn):
|
|
stack[l.depth] = l
|
|
cnt += 1
|
|
elif(l.freturn and not l.fcall):
|
|
if(not stack[l.depth]):
|
|
return False
|
|
stack[l.depth].length = l.length
|
|
stack[l.depth] = 0
|
|
l.length = 0
|
|
cnt -= 1
|
|
if(cnt == 0):
|
|
return True
|
|
return False
|
|
def debugPrint(self, filename):
|
|
if(filename == "stdout"):
|
|
print("[%f - %f]") % (self.start, self.end)
|
|
for l in self.list:
|
|
if(l.freturn and l.fcall):
|
|
print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
|
|
elif(l.freturn):
|
|
print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
|
|
else:
|
|
print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
|
|
print(" ")
|
|
else:
|
|
fp = open(filename, 'w')
|
|
print(filename)
|
|
for l in self.list:
|
|
if(l.freturn and l.fcall):
|
|
fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
|
|
elif(l.freturn):
|
|
fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
|
|
else:
|
|
fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
|
|
fp.close()
|
|
|
|
class Timeline:
|
|
html = {}
|
|
scaleH = 0.0 # height of the timescale row as a percent of the timeline height
|
|
rowH = 0.0 # height of each row in percent of the timeline height
|
|
row_height_pixels = 30
|
|
maxrows = 0
|
|
height = 0
|
|
def __init__(self):
|
|
self.html = {
|
|
'timeline': "",
|
|
'legend': "",
|
|
'scale': ""
|
|
}
|
|
def setRows(self, rows):
|
|
self.maxrows = int(rows)
|
|
self.scaleH = 100.0/float(self.maxrows)
|
|
self.height = self.maxrows*self.row_height_pixels
|
|
r = float(self.maxrows - 1)
|
|
if(r < 1.0):
|
|
r = 1.0
|
|
self.rowH = (100.0 - self.scaleH)/r
|
|
|
|
# -- global objects --
|
|
|
|
sysvals = SystemValues()
|
|
data = Data()
|
|
|
|
# -- functions --
|
|
|
|
# Function: initFtrace
|
|
# Description:
|
|
# Configure ftrace to capture a function trace during suspend/resume
|
|
def initFtrace():
|
|
global sysvals
|
|
|
|
print("INITIALIZING FTRACE...")
|
|
# turn trace off
|
|
os.system("echo 0 > "+sysvals.tpath+"tracing_on")
|
|
# set the trace clock to global
|
|
os.system("echo global > "+sysvals.tpath+"trace_clock")
|
|
# set trace buffer to a huge value
|
|
os.system("echo nop > "+sysvals.tpath+"current_tracer")
|
|
os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb")
|
|
# clear the trace buffer
|
|
os.system("echo \"\" > "+sysvals.tpath+"trace")
|
|
# set trace type
|
|
os.system("echo function_graph > "+sysvals.tpath+"current_tracer")
|
|
os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter")
|
|
# set trace format options
|
|
os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options")
|
|
os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options")
|
|
# focus only on device suspend and resume
|
|
os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function")
|
|
|
|
# Function: verifyFtrace
|
|
# Description:
|
|
# Check that ftrace is working on the system
|
|
def verifyFtrace():
|
|
global sysvals
|
|
files = ["available_filter_functions", "buffer_size_kb",
|
|
"current_tracer", "set_ftrace_filter",
|
|
"trace", "trace_marker"]
|
|
for f in files:
|
|
if(os.path.exists(sysvals.tpath+f) == False):
|
|
return False
|
|
return True
|
|
|
|
def parseStamp(line):
|
|
global data, sysvals
|
|
stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\
|
|
"(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\
|
|
" (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$"
|
|
m = re.match(stampfmt, line)
|
|
if(m):
|
|
dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")),
|
|
int(m.group("d")), int(m.group("H")), int(m.group("M")),
|
|
int(m.group("S")))
|
|
data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p")
|
|
data.stamp['host'] = m.group("host")
|
|
data.stamp['mode'] = m.group("mode")
|
|
data.stamp['kernel'] = m.group("kernel")
|
|
sysvals.suspendmode = data.stamp['mode']
|
|
|
|
# Function: analyzeTraceLog
|
|
# Description:
|
|
# Analyse an ftrace log output file generated from this app during
|
|
# the execution phase. Create an "ftrace" structure in memory for
|
|
# subsequent formatting in the html output file
|
|
def analyzeTraceLog():
|
|
global sysvals, data
|
|
|
|
# the ftrace data is tied to the dmesg data
|
|
if(not data.usedmesg):
|
|
return
|
|
|
|
# read through the ftrace and parse the data
|
|
data.vprint("Analyzing the ftrace data...")
|
|
ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\
|
|
" *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\
|
|
"[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)"
|
|
ftemp = dict()
|
|
inthepipe = False
|
|
tf = open(sysvals.ftracefile, 'r')
|
|
count = 0
|
|
for line in tf:
|
|
count = count + 1
|
|
# grab the time stamp if it's valid
|
|
if(count == 1):
|
|
parseStamp(line)
|
|
continue
|
|
# parse only valid lines
|
|
m = re.match(ftrace_line_fmt, line)
|
|
if(not m):
|
|
continue
|
|
m_time = m.group("time")
|
|
m_pid = m.group("pid")
|
|
m_msg = m.group("msg")
|
|
m_dur = m.group("dur")
|
|
if(m_time and m_pid and m_msg):
|
|
t = FTraceLine(m_time, m_msg, m_dur)
|
|
pid = int(m_pid)
|
|
else:
|
|
continue
|
|
# the line should be a call, return, or event
|
|
if(not t.fcall and not t.freturn and not t.fevent):
|
|
continue
|
|
# only parse the ftrace data during suspend/resume
|
|
if(not inthepipe):
|
|
# look for the suspend start marker
|
|
if(t.fevent):
|
|
if(t.name == "SUSPEND START"):
|
|
data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count))
|
|
inthepipe = True
|
|
continue
|
|
else:
|
|
# look for the resume end marker
|
|
if(t.fevent):
|
|
if(t.name == "RESUME COMPLETE"):
|
|
data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count))
|
|
inthepipe = False
|
|
break
|
|
continue
|
|
# create a callgraph object for the data
|
|
if(pid not in ftemp):
|
|
ftemp[pid] = FTraceCallGraph()
|
|
# when the call is finished, see which device matches it
|
|
if(ftemp[pid].addLine(t, m)):
|
|
if(not ftemp[pid].sanityCheck()):
|
|
id = "task %s cpu %s" % (pid, m.group("cpu"))
|
|
data.vprint("Sanity check failed for "+id+", ignoring this callback")
|
|
continue
|
|
callstart = ftemp[pid].start
|
|
callend = ftemp[pid].end
|
|
for p in data.phases:
|
|
if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']):
|
|
list = data.dmesg[p]['list']
|
|
for devname in list:
|
|
dev = list[devname]
|
|
if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']):
|
|
data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid))
|
|
dev['ftrace'] = ftemp[pid]
|
|
break
|
|
ftemp[pid] = FTraceCallGraph()
|
|
tf.close()
|
|
|
|
# Function: sortKernelLog
|
|
# Description:
|
|
# The dmesg output log sometimes comes with with lines that have
|
|
# timestamps out of order. This could cause issues since a call
|
|
# could accidentally end up in the wrong phase
|
|
def sortKernelLog():
|
|
global sysvals, data
|
|
lf = open(sysvals.dmesgfile, 'r')
|
|
dmesglist = []
|
|
count = 0
|
|
for line in lf:
|
|
line = line.replace("\r\n", "")
|
|
if(count == 0):
|
|
parseStamp(line)
|
|
elif(count == 1):
|
|
m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line)
|
|
if(m):
|
|
data.fwSuspend = int(m.group("s"))
|
|
data.fwResume = int(m.group("r"))
|
|
if(data.fwSuspend > 0 or data.fwResume > 0):
|
|
data.fwValid = True
|
|
if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)):
|
|
dmesglist.append(line)
|
|
count += 1
|
|
lf.close()
|
|
last = ""
|
|
|
|
# fix lines with the same time stamp and function with the call and return swapped
|
|
for line in dmesglist:
|
|
mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling (?P<f>.*)\+ @ .*, parent: .*", line)
|
|
mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last)
|
|
if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))):
|
|
i = dmesglist.index(last)
|
|
j = dmesglist.index(line)
|
|
dmesglist[i] = line
|
|
dmesglist[j] = last
|
|
last = line
|
|
return dmesglist
|
|
|
|
# Function: analyzeKernelLog
|
|
# Description:
|
|
# Analyse a dmesg log output file generated from this app during
|
|
# the execution phase. Create a set of device structures in memory
|
|
# for subsequent formatting in the html output file
|
|
def analyzeKernelLog():
|
|
global sysvals, data
|
|
|
|
print("PROCESSING DATA")
|
|
data.vprint("Analyzing the dmesg data...")
|
|
if(os.path.exists(sysvals.dmesgfile) == False):
|
|
print("ERROR: %s doesn't exist") % sysvals.dmesgfile
|
|
return False
|
|
|
|
lf = sortKernelLog()
|
|
phase = "suspend_runtime"
|
|
|
|
dm = {
|
|
'suspend_general': r"PM: Syncing filesystems.*",
|
|
'suspend_early': r"PM: suspend of devices complete after.*",
|
|
'suspend_noirq': r"PM: late suspend of devices complete after.*",
|
|
'suspend_cpu': r"PM: noirq suspend of devices complete after.*",
|
|
'resume_cpu': r"ACPI: Low-level resume complete.*",
|
|
'resume_noirq': r"ACPI: Waking up from system sleep state.*",
|
|
'resume_early': r"PM: noirq resume of devices complete after.*",
|
|
'resume_general': r"PM: early resume of devices complete after.*",
|
|
'resume_complete': r".*Restarting tasks \.\.\..*",
|
|
}
|
|
if(sysvals.suspendmode == "standby"):
|
|
dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
|
|
elif(sysvals.suspendmode == "disk"):
|
|
dm['suspend_early'] = r"PM: freeze of devices complete after.*"
|
|
dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*"
|
|
dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*"
|
|
dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
|
|
dm['resume_early'] = r"PM: noirq restore of devices complete after.*"
|
|
dm['resume_general'] = r"PM: early restore of devices complete after.*"
|
|
|
|
action_start = 0.0
|
|
for line in lf:
|
|
# -- preprocessing --
|
|
# parse each dmesg line into the time and message
|
|
m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)
|
|
if(m):
|
|
ktime = float(m.group("ktime"))
|
|
msg = m.group("msg")
|
|
else:
|
|
print line
|
|
continue
|
|
|
|
# -- phase changes --
|
|
# suspend_general start
|
|
if(re.match(dm['suspend_general'], msg)):
|
|
phase = "suspend_general"
|
|
data.dmesg[phase]['start'] = ktime
|
|
data.start = ktime
|
|
# action start: syncing filesystems
|
|
action_start = ktime
|
|
# suspend_early start
|
|
elif(re.match(dm['suspend_early'], msg)):
|
|
data.dmesg["suspend_general"]['end'] = ktime
|
|
phase = "suspend_early"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# suspend_noirq start
|
|
elif(re.match(dm['suspend_noirq'], msg)):
|
|
data.dmesg["suspend_early"]['end'] = ktime
|
|
phase = "suspend_noirq"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# suspend_cpu start
|
|
elif(re.match(dm['suspend_cpu'], msg)):
|
|
data.dmesg["suspend_noirq"]['end'] = ktime
|
|
phase = "suspend_cpu"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# resume_cpu start
|
|
elif(re.match(dm['resume_cpu'], msg)):
|
|
data.tSuspended = ktime
|
|
data.dmesg["suspend_cpu"]['end'] = ktime
|
|
phase = "resume_cpu"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# resume_noirq start
|
|
elif(re.match(dm['resume_noirq'], msg)):
|
|
data.dmesg["resume_cpu"]['end'] = ktime
|
|
phase = "resume_noirq"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# action end: ACPI resume
|
|
data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime)
|
|
# resume_early start
|
|
elif(re.match(dm['resume_early'], msg)):
|
|
data.dmesg["resume_noirq"]['end'] = ktime
|
|
phase = "resume_early"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# resume_general start
|
|
elif(re.match(dm['resume_general'], msg)):
|
|
data.dmesg["resume_early"]['end'] = ktime
|
|
phase = "resume_general"
|
|
data.dmesg[phase]['start'] = ktime
|
|
# resume complete start
|
|
elif(re.match(dm['resume_complete'], msg)):
|
|
data.dmesg["resume_general"]['end'] = ktime
|
|
data.end = ktime
|
|
phase = "resume_runtime"
|
|
break
|
|
|
|
# -- device callbacks --
|
|
if(phase in data.phases):
|
|
# device init call
|
|
if(re.match(r"calling (?P<f>.*)\+ @ .*, parent: .*", msg)):
|
|
sm = re.match(r"calling (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg);
|
|
f = sm.group("f")
|
|
n = sm.group("n")
|
|
p = sm.group("p")
|
|
if(f and n and p):
|
|
data.newAction(phase, f, int(n), p, ktime, -1)
|
|
# device init return
|
|
elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)):
|
|
sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg);
|
|
f = sm.group("f")
|
|
t = sm.group("t")
|
|
list = data.dmesg[phase]['list']
|
|
if(f in list):
|
|
dev = list[f]
|
|
dev['length'] = int(t)
|
|
dev['end'] = ktime
|
|
data.vprint("%15s [%f - %f] %s(%d) %s" %
|
|
(phase, dev['start'], dev['end'], f, dev['pid'], dev['par']))
|
|
|
|
# -- phase specific actions --
|
|
if(phase == "suspend_general"):
|
|
if(re.match(r"PM: Preparing system for mem sleep.*", msg)):
|
|
data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime)
|
|
elif(re.match(r"Freezing user space processes .*", msg)):
|
|
action_start = ktime
|
|
elif(re.match(r"Freezing remaining freezable tasks.*", msg)):
|
|
data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime)
|
|
action_start = ktime
|
|
elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)):
|
|
data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime)
|
|
elif(phase == "suspend_cpu"):
|
|
m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg)
|
|
if(m):
|
|
cpu = "CPU"+m.group("cpu")
|
|
data.newAction(phase, cpu, -1, "", action_start, ktime)
|
|
action_start = ktime
|
|
elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)):
|
|
action_start = ktime
|
|
elif(re.match(r"Disabling non-boot CPUs .*", msg)):
|
|
data.newAction(phase, "ACPI", -1, "", action_start, ktime)
|
|
action_start = ktime
|
|
elif(phase == "resume_cpu"):
|
|
m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg)
|
|
if(m):
|
|
cpu = "CPU"+m.group("cpu")
|
|
data.newAction(phase, cpu, -1, "", action_start, ktime)
|
|
action_start = ktime
|
|
elif(re.match(r"Enabling non-boot CPUs .*", msg)):
|
|
action_start = ktime
|
|
|
|
# fill in any missing phases
|
|
lp = "suspend_general"
|
|
for p in data.phases:
|
|
if(p == "suspend_general"):
|
|
continue
|
|
if(data.dmesg[p]['start'] < 0):
|
|
data.dmesg[p]['start'] = data.dmesg[lp]['end']
|
|
if(p == "resume_cpu"):
|
|
data.tSuspended = data.dmesg[lp]['end']
|
|
if(data.dmesg[p]['end'] < 0):
|
|
data.dmesg[p]['end'] = data.dmesg[p]['start']
|
|
lp = p
|
|
|
|
data.fixupInitcallsThatDidntReturn()
|
|
return True
|
|
|
|
# Function: setTimelineRows
|
|
# Description:
|
|
# Organize the device or thread lists into the smallest
|
|
# number of rows possible, with no entry overlapping
|
|
# Arguments:
|
|
# list: the list to sort (dmesg or ftrace)
|
|
# sortedkeys: sorted key list to use
|
|
def setTimelineRows(list, sortedkeys):
|
|
global data
|
|
|
|
# clear all rows and set them to undefined
|
|
remaining = len(list)
|
|
rowdata = dict()
|
|
row = 0
|
|
for item in list:
|
|
list[item]['row'] = -1
|
|
|
|
# try to pack each row with as many ranges as possible
|
|
while(remaining > 0):
|
|
if(row not in rowdata):
|
|
rowdata[row] = []
|
|
for item in sortedkeys:
|
|
if(list[item]['row'] < 0):
|
|
s = list[item]['start']
|
|
e = list[item]['end']
|
|
valid = True
|
|
for ritem in rowdata[row]:
|
|
rs = ritem['start']
|
|
re = ritem['end']
|
|
if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))):
|
|
valid = False
|
|
break
|
|
if(valid):
|
|
rowdata[row].append(list[item])
|
|
list[item]['row'] = row
|
|
remaining -= 1
|
|
row += 1
|
|
return row
|
|
|
|
# Function: createTimeScale
|
|
# Description:
|
|
# Create timescale lines for the dmesg and ftrace timelines
|
|
# Arguments:
|
|
# t0: start time (suspend begin)
|
|
# tMax: end time (resume end)
|
|
# tSuspend: time when suspend occurs
|
|
def createTimeScale(t0, tMax, tSuspended):
|
|
global data
|
|
timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n"
|
|
output = '<div id="timescale">\n'
|
|
|
|
# set scale for timeline
|
|
tTotal = tMax - t0
|
|
tS = 0.1
|
|
if(tTotal <= 0):
|
|
return output
|
|
if(tTotal > 4):
|
|
tS = 1
|
|
if(tSuspended < 0):
|
|
for i in range(int(tTotal/tS)+1):
|
|
pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal))
|
|
if(i > 0):
|
|
val = "%0.f" % (float(i)*tS*1000)
|
|
else:
|
|
val = ""
|
|
output += timescale.format(pos, val)
|
|
else:
|
|
tSuspend = tSuspended - t0
|
|
divTotal = int(tTotal/tS) + 1
|
|
divSuspend = int(tSuspend/tS)
|
|
s0 = (tSuspend - tS*divSuspend)*100/tTotal
|
|
for i in range(divTotal):
|
|
pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0)
|
|
if((i == 0) and (s0 < 3)):
|
|
val = ""
|
|
elif(i == divSuspend):
|
|
val = "S/R"
|
|
else:
|
|
val = "%0.f" % (float(i-divSuspend)*tS*1000)
|
|
output += timescale.format(pos, val)
|
|
output += '</div>\n'
|
|
return output
|
|
|
|
# Function: createHTML
|
|
# Description:
|
|
# Create the output html file.
|
|
def createHTML():
|
|
global sysvals, data
|
|
|
|
data.normalizeTime()
|
|
|
|
# html function templates
|
|
headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
|
|
html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n<div id="dmesgzoombox" class="zoombox">\n'
|
|
html_timeline = '<div id="{0}" class="timeline" style="height:{1}px">\n'
|
|
html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
|
|
html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
|
|
html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n'
|
|
html_timetotal = '<table class="time1">\n<tr>'\
|
|
'<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\
|
|
'<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\
|
|
'</tr>\n</table>\n'
|
|
html_timegroups = '<table class="time2">\n<tr>'\
|
|
'<td class="green">Kernel Suspend: {0} ms</td>'\
|
|
'<td class="purple">Firmware Suspend: {1} ms</td>'\
|
|
'<td class="purple">Firmware Resume: {2} ms</td>'\
|
|
'<td class="yellow">Kernel Resume: {3} ms</td>'\
|
|
'</tr>\n</table>\n'
|
|
|
|
# device timeline (dmesg)
|
|
if(data.usedmesg):
|
|
data.vprint("Creating Device Timeline...")
|
|
devtl = Timeline()
|
|
|
|
# Generate the header for this timeline
|
|
t0 = data.start
|
|
tMax = data.end
|
|
tTotal = tMax - t0
|
|
if(tTotal == 0):
|
|
print("ERROR: No timeline data")
|
|
sys.exit()
|
|
suspend_time = "%.0f"%(-data.start*1000)
|
|
resume_time = "%.0f"%(data.end*1000)
|
|
if data.fwValid:
|
|
devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total")
|
|
sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000)
|
|
sftime = "%.3f"%(data.fwSuspend / 1000000.0)
|
|
rftime = "%.3f"%(data.fwResume / 1000000.0)
|
|
rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000)
|
|
devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime)
|
|
else:
|
|
devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel")
|
|
|
|
# determine the maximum number of rows we need to draw
|
|
timelinerows = 0
|
|
for phase in data.dmesg:
|
|
list = data.dmesg[phase]['list']
|
|
rows = setTimelineRows(list, list)
|
|
data.dmesg[phase]['row'] = rows
|
|
if(rows > timelinerows):
|
|
timelinerows = rows
|
|
|
|
# calculate the timeline height and create its bounding box
|
|
devtl.setRows(timelinerows + 1)
|
|
devtl.html['timeline'] += html_zoombox;
|
|
devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height);
|
|
|
|
# draw the colored boxes for each of the phases
|
|
for b in data.dmesg:
|
|
phase = data.dmesg[b]
|
|
left = "%.3f" % (((phase['start']-data.start)*100)/tTotal)
|
|
width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal)
|
|
devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "")
|
|
|
|
# draw the time scale, try to make the number of labels readable
|
|
devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended)
|
|
devtl.html['timeline'] += devtl.html['scale']
|
|
for b in data.dmesg:
|
|
phaselist = data.dmesg[b]['list']
|
|
for d in phaselist:
|
|
name = d
|
|
if(d in data.altdevname):
|
|
name = data.altdevname[d]
|
|
dev = phaselist[d]
|
|
height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
|
|
top = "%.3f" % ((dev['row']*height) + devtl.scaleH)
|
|
left = "%.3f" % (((dev['start']-data.start)*100)/tTotal)
|
|
width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal)
|
|
len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000)
|
|
color = "rgba(204,204,204,0.5)"
|
|
devtl.html['timeline'] += html_device.format(dev['id'], name+len+b, left, top, "%.3f"%height, width, name)
|
|
|
|
# timeline is finished
|
|
devtl.html['timeline'] += "</div>\n</div>\n"
|
|
|
|
# draw a legend which describes the phases by color
|
|
devtl.html['legend'] = "<div class=\"legend\">\n"
|
|
pdelta = 100.0/data.phases.__len__()
|
|
pmargin = pdelta / 4.0
|
|
for phase in data.phases:
|
|
order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
|
|
name = string.replace(phase, "_", " ")
|
|
devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name)
|
|
devtl.html['legend'] += "</div>\n"
|
|
|
|
hf = open(sysvals.htmlfile, 'w')
|
|
thread_height = 0
|
|
|
|
# write the html header first (html head, css code, everything up to the start of body)
|
|
html_header = "<!DOCTYPE html>\n<html>\n<head>\n\
|
|
<meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\
|
|
<title>AnalyzeSuspend</title>\n\
|
|
<style type='text/css'>\n\
|
|
body {overflow-y: scroll;}\n\
|
|
.stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
|
|
.callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
|
|
.callgraph article * {padding-left: 28px;}\n\
|
|
h1 {color:black;font: bold 30px Times;}\n\
|
|
table {width:100%;}\n\
|
|
.gray {background-color:rgba(80,80,80,0.1);}\n\
|
|
.green {background-color:rgba(204,255,204,0.4);}\n\
|
|
.purple {background-color:rgba(128,0,128,0.2);}\n\
|
|
.yellow {background-color:rgba(255,255,204,0.4);}\n\
|
|
.time1 {font: 22px Arial;border:1px solid;}\n\
|
|
.time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
|
|
td {text-align: center;}\n\
|
|
.tdhl {color: red;}\n\
|
|
.hide {display: none;}\n\
|
|
.pf {display: none;}\n\
|
|
.pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version=\"1.0\" standalone=\"no\"?><svg xmlns=\"http://www.w3.org/2000/svg\" height=\"18\" width=\"18\" version=\"1.1\"><circle cx=\"9\" cy=\"9\" r=\"8\" stroke=\"black\" stroke-width=\"1\" fill=\"white\"/><rect x=\"4\" y=\"8\" width=\"10\" height=\"2\" style=\"fill:black;stroke-width:0\"/><rect x=\"8\" y=\"4\" width=\"2\" height=\"10\" style=\"fill:black;stroke-width:0\"/></svg>\') no-repeat left center;}\n\
|
|
.pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version=\"1.0\" standalone=\"no\"?><svg xmlns=\"http://www.w3.org/2000/svg\" height=\"18\" width=\"18\" version=\"1.1\"><circle cx=\"9\" cy=\"9\" r=\"8\" stroke=\"black\" stroke-width=\"1\" fill=\"white\"/><rect x=\"4\" y=\"8\" width=\"10\" height=\"2\" style=\"fill:black;stroke-width:0\"/></svg>\') no-repeat left center;}\n\
|
|
.pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
|
|
.zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
|
|
.timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
|
|
.thread {position: absolute; height: "+"%.3f"%thread_height+"%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
|
|
.thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
|
|
.phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
|
|
.t {position: absolute; top: 0%; height: 100%; border-right:1px solid black;}\n\
|
|
.legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
|
|
.legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
|
|
button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
|
|
</style>\n</head>\n<body>\n"
|
|
hf.write(html_header)
|
|
|
|
# write the test title and general info header
|
|
if(data.stamp['time'] != ""):
|
|
hf.write(headline_stamp.format(data.stamp['host'],
|
|
data.stamp['kernel'], data.stamp['mode'], data.stamp['time']))
|
|
|
|
# write the dmesg data (device timeline)
|
|
if(data.usedmesg):
|
|
hf.write(devtl.html['timeline'])
|
|
hf.write(devtl.html['legend'])
|
|
hf.write('<div id="devicedetail"></div>\n')
|
|
hf.write('<div id="devicetree"></div>\n')
|
|
|
|
# write the ftrace data (callgraph)
|
|
if(data.useftrace):
|
|
hf.write('<section id="callgraphs" class="callgraph">\n')
|
|
# write out the ftrace data converted to html
|
|
html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
|
|
html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
|
|
html_func_end = '</article>\n'
|
|
html_func_leaf = '<article>{0} {1}</article>\n'
|
|
num = 0
|
|
for p in data.phases:
|
|
list = data.dmesg[p]['list']
|
|
for devname in data.sortedDevices(p):
|
|
if('ftrace' not in list[devname]):
|
|
continue
|
|
name = devname
|
|
if(devname in data.altdevname):
|
|
name = data.altdevname[devname]
|
|
devid = list[devname]['id']
|
|
cg = list[devname]['ftrace']
|
|
flen = "(%.3f ms)" % ((cg.end - cg.start)*1000)
|
|
hf.write(html_func_top.format(devid, data.dmesg[p]['color'], num, name+" "+p, flen))
|
|
num += 1
|
|
for line in cg.list:
|
|
if(line.length < 0.000000001):
|
|
flen = ""
|
|
else:
|
|
flen = "(%.3f ms)" % (line.length*1000)
|
|
if(line.freturn and line.fcall):
|
|
hf.write(html_func_leaf.format(line.name, flen))
|
|
elif(line.freturn):
|
|
hf.write(html_func_end)
|
|
else:
|
|
hf.write(html_func_start.format(num, line.name, flen))
|
|
num += 1
|
|
hf.write(html_func_end)
|
|
hf.write("\n\n </section>\n")
|
|
# write the footer and close
|
|
addScriptCode(hf)
|
|
hf.write("</body>\n</html>\n")
|
|
hf.close()
|
|
return True
|
|
|
|
def addScriptCode(hf):
|
|
global data
|
|
|
|
t0 = (data.start - data.tSuspended) * 1000
|
|
tMax = (data.end - data.tSuspended) * 1000
|
|
# create an array in javascript memory with the device details
|
|
detail = ' var bounds = [%f,%f];\n' % (t0, tMax)
|
|
detail += ' var d = [];\n'
|
|
dfmt = ' d["%s"] = { n:"%s", p:"%s", c:[%s] };\n';
|
|
for p in data.dmesg:
|
|
list = data.dmesg[p]['list']
|
|
for d in list:
|
|
parent = data.deviceParentID(d, p)
|
|
idlist = data.deviceChildrenIDs(d, p)
|
|
idstr = ""
|
|
for i in idlist:
|
|
if(idstr == ""):
|
|
idstr += '"'+i+'"'
|
|
else:
|
|
idstr += ', '+'"'+i+'"'
|
|
detail += dfmt % (list[d]['id'], d, parent, idstr)
|
|
|
|
# add the code which will manipulate the data in the browser
|
|
script_code = \
|
|
'<script type="text/javascript">\n'+detail+\
|
|
' var filter = [];\n'\
|
|
' var table = [];\n'\
|
|
' function deviceParent(devid) {\n'\
|
|
' var devlist = [];\n'\
|
|
' if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
|
|
' if(d[devid].p in d)\n'\
|
|
' devlist = deviceParent(d[devid].p);\n'\
|
|
' else if(d[devid].p != "")\n'\
|
|
' devlist = [d[devid].p];\n'\
|
|
' devlist[devlist.length] = d[devid].n;\n'\
|
|
' return devlist;\n'\
|
|
' }\n'\
|
|
' function deviceChildren(devid, column, row) {\n'\
|
|
' if(!(devid in d)) return;\n'\
|
|
' if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
|
|
' var cell = {name: d[devid].n, span: 1};\n'\
|
|
' var span = 0;\n'\
|
|
' if(column >= table.length) table[column] = [];\n'\
|
|
' table[column][row] = cell;\n'\
|
|
' for(var i = 0; i < d[devid].c.length; i++) {\n'\
|
|
' var cid = d[devid].c[i];\n'\
|
|
' span += deviceChildren(cid, column+1, row+span);\n'\
|
|
' }\n'\
|
|
' if(span == 0) span = 1;\n'\
|
|
' table[column][row].span = span;\n'\
|
|
' return span;\n'\
|
|
' }\n'\
|
|
' function deviceTree(devid, resume) {\n'\
|
|
' var html = "<table border=1>";\n'\
|
|
' filter = [];\n'\
|
|
' table = [];\n'\
|
|
' plist = deviceParent(devid);\n'\
|
|
' var devidx = plist.length - 1;\n'\
|
|
' for(var i = 0; i < devidx; i++)\n'\
|
|
' table[i] = [{name: plist[i], span: 1}];\n'\
|
|
' deviceChildren(devid, devidx, 0);\n'\
|
|
' for(var i = 0; i < devidx; i++)\n'\
|
|
' table[i][0].span = table[devidx][0].span;\n'\
|
|
' for(var row = 0; row < table[0][0].span; row++) {\n'\
|
|
' html += "<tr>";\n'\
|
|
' for(var col = 0; col < table.length; col++)\n'\
|
|
' if(row in table[col]) {\n'\
|
|
' var cell = table[col][row];\n'\
|
|
' var args = "";\n'\
|
|
' if(cell.span > 1)\n'\
|
|
' args += " rowspan="+cell.span;\n'\
|
|
' if((col == devidx) && (row == 0))\n'\
|
|
' args += " class=tdhl";\n'\
|
|
' if(resume)\n'\
|
|
' html += "<td"+args+">"+cell.name+" →</td>";\n'\
|
|
' else\n'\
|
|
' html += "<td"+args+">← "+cell.name+"</td>";\n'\
|
|
' }\n'\
|
|
' html += "</tr>";\n'\
|
|
' }\n'\
|
|
' html += "</table>";\n'\
|
|
' return html;\n'\
|
|
' }\n'\
|
|
' function zoomTimeline() {\n'\
|
|
' var timescale = document.getElementById("timescale");\n'\
|
|
' var dmesg = document.getElementById("dmesg");\n'\
|
|
' var zoombox = document.getElementById("dmesgzoombox");\n'\
|
|
' var val = parseFloat(dmesg.style.width);\n'\
|
|
' var newval = 100;\n'\
|
|
' var sh = window.outerWidth / 2;\n'\
|
|
' if(this.id == "zoomin") {\n'\
|
|
' newval = val * 1.2;\n'\
|
|
' if(newval > 40000) newval = 40000;\n'\
|
|
' dmesg.style.width = newval+"%";\n'\
|
|
' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
|
|
' } else if (this.id == "zoomout") {\n'\
|
|
' newval = val / 1.2;\n'\
|
|
' if(newval < 100) newval = 100;\n'\
|
|
' dmesg.style.width = newval+"%";\n'\
|
|
' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
|
|
' } else {\n'\
|
|
' zoombox.scrollLeft = 0;\n'\
|
|
' dmesg.style.width = "100%";\n'\
|
|
' }\n'\
|
|
' var html = "";\n'\
|
|
' var t0 = bounds[0];\n'\
|
|
' var tMax = bounds[1];\n'\
|
|
' var tTotal = tMax - t0;\n'\
|
|
' var wTotal = tTotal * 100.0 / newval;\n'\
|
|
' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\
|
|
' if(tS < 1) tS = 1;\n'\
|
|
' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
|
|
' var pos = (tMax - s) * 100.0 / tTotal;\n'\
|
|
' var name = (s == 0)?"S/R":(s+"ms");\n'\
|
|
' html += \"<div class=\\\"t\\\" style=\\\"right:\"+pos+\"%\\\">\"+name+\"</div>\";\n'\
|
|
' }\n'\
|
|
' timescale.innerHTML = html;\n'\
|
|
' }\n'\
|
|
' function deviceDetail() {\n'\
|
|
' var devtitle = document.getElementById("devicedetail");\n'\
|
|
' devtitle.innerHTML = "<h1>"+this.title+"</h1>";\n'\
|
|
' var devtree = document.getElementById("devicetree");\n'\
|
|
' devtree.innerHTML = deviceTree(this.id, (this.title.indexOf("resume") >= 0));\n'\
|
|
' var cglist = document.getElementById("callgraphs");\n'\
|
|
' if(!cglist) return;\n'\
|
|
' var cg = cglist.getElementsByClassName("atop");\n'\
|
|
' for (var i = 0; i < cg.length; i++) {\n'\
|
|
' if(filter.indexOf(cg[i].id) >= 0) {\n'\
|
|
' cg[i].style.display = "block";\n'\
|
|
' } else {\n'\
|
|
' cg[i].style.display = "none";\n'\
|
|
' }\n'\
|
|
' }\n'\
|
|
' }\n'\
|
|
' window.addEventListener("load", function () {\n'\
|
|
' var dmesg = document.getElementById("dmesg");\n'\
|
|
' dmesg.style.width = "100%"\n'\
|
|
' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
|
|
' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
|
|
' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
|
|
' var dev = dmesg.getElementsByClassName("thread");\n'\
|
|
' for (var i = 0; i < dev.length; i++) {\n'\
|
|
' dev[i].onclick = deviceDetail;\n'\
|
|
' }\n'\
|
|
' zoomTimeline();\n'\
|
|
' });\n'\
|
|
'</script>\n'
|
|
hf.write(script_code);
|
|
|
|
# Function: executeSuspend
|
|
# Description:
|
|
# Execute system suspend through the sysfs interface
|
|
def executeSuspend():
|
|
global sysvals, data
|
|
|
|
detectUSB()
|
|
pf = open(sysvals.powerfile, 'w')
|
|
# clear the kernel ring buffer just as we start
|
|
os.system("dmesg -C")
|
|
# start ftrace
|
|
if(data.useftrace):
|
|
print("START TRACING")
|
|
os.system("echo 1 > "+sysvals.tpath+"tracing_on")
|
|
os.system("echo SUSPEND START > "+sysvals.tpath+"trace_marker")
|
|
# initiate suspend
|
|
if(sysvals.rtcwake):
|
|
print("SUSPEND START")
|
|
os.system("rtcwake -s 10 -m "+sysvals.suspendmode)
|
|
else:
|
|
print("SUSPEND START (press a key to resume)")
|
|
pf.write(sysvals.suspendmode)
|
|
# execution will pause here
|
|
pf.close()
|
|
# return from suspend
|
|
print("RESUME COMPLETE")
|
|
# stop ftrace
|
|
if(data.useftrace):
|
|
os.system("echo RESUME COMPLETE > "+sysvals.tpath+"trace_marker")
|
|
os.system("echo 0 > "+sysvals.tpath+"tracing_on")
|
|
print("CAPTURING FTRACE")
|
|
os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.ftracefile)
|
|
os.system("cat "+sysvals.tpath+"trace >> "+sysvals.ftracefile)
|
|
# grab a copy of the dmesg output
|
|
print("CAPTURING DMESG")
|
|
os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.dmesgfile)
|
|
os.system("dmesg -c >> "+sysvals.dmesgfile)
|
|
|
|
# Function: detectUSB
|
|
# Description:
|
|
# Detect all the USB hosts and devices currently connected
|
|
def detectUSB():
|
|
global sysvals, data
|
|
|
|
for dirname, dirnames, filenames in os.walk("/sys/devices"):
|
|
if(re.match(r".*/usb[0-9]*.*", dirname) and
|
|
"idVendor" in filenames and "idProduct" in filenames):
|
|
vid = os.popen("cat %s/idVendor 2>/dev/null" % dirname).read().replace('\n', '')
|
|
pid = os.popen("cat %s/idProduct 2>/dev/null" % dirname).read().replace('\n', '')
|
|
product = os.popen("cat %s/product 2>/dev/null" % dirname).read().replace('\n', '')
|
|
name = dirname.split('/')[-1]
|
|
if(len(product) > 0):
|
|
data.altdevname[name] = "%s [%s]" % (product, name)
|
|
else:
|
|
data.altdevname[name] = "%s:%s [%s]" % (vid, pid, name)
|
|
|
|
def getModes():
|
|
global sysvals
|
|
modes = ""
|
|
if(os.path.exists(sysvals.powerfile)):
|
|
fp = open(sysvals.powerfile, 'r')
|
|
modes = string.split(fp.read())
|
|
fp.close()
|
|
return modes
|
|
|
|
# Function: statusCheck
|
|
# Description:
|
|
# Verify that the requested command and options will work
|
|
def statusCheck(dryrun):
|
|
global sysvals, data
|
|
res = dict()
|
|
|
|
if(data.notestrun):
|
|
print("SUCCESS: The command should run!")
|
|
return
|
|
|
|
# check we have root access
|
|
check = "YES"
|
|
if(os.environ['USER'] != "root"):
|
|
if(not dryrun):
|
|
doError("root access is required", False)
|
|
check = "NO"
|
|
res[" have root access: "] = check
|
|
|
|
# check sysfs is mounted
|
|
check = "YES"
|
|
if(not os.path.exists(sysvals.powerfile)):
|
|
if(not dryrun):
|
|
doError("sysfs must be mounted", False)
|
|
check = "NO"
|
|
res[" is sysfs mounted: "] = check
|
|
|
|
# check target mode is a valid mode
|
|
check = "YES"
|
|
modes = getModes()
|
|
if(sysvals.suspendmode not in modes):
|
|
if(not dryrun):
|
|
doError("%s is not a value power mode" % sysvals.suspendmode, False)
|
|
check = "NO"
|
|
res[" is "+sysvals.suspendmode+" a power mode: "] = check
|
|
|
|
# check if ftrace is available
|
|
if(data.useftrace):
|
|
check = "YES"
|
|
if(not verifyFtrace()):
|
|
if(not dryrun):
|
|
doError("ftrace is not configured", False)
|
|
check = "NO"
|
|
res[" is ftrace usable: "] = check
|
|
|
|
# check if rtcwake
|
|
if(sysvals.rtcwake):
|
|
check = "YES"
|
|
version = os.popen("rtcwake -V 2>/dev/null").read()
|
|
if(not version.startswith("rtcwake")):
|
|
if(not dryrun):
|
|
doError("rtcwake is not installed", False)
|
|
check = "NO"
|
|
res[" is rtcwake usable: "] = check
|
|
|
|
if(dryrun):
|
|
status = True
|
|
print("Checking if system can run the current command:")
|
|
for r in res:
|
|
print("%s\t%s" % (r, res[r]))
|
|
if(res[r] != "YES"):
|
|
status = False
|
|
if(status):
|
|
print("SUCCESS: The command should run!")
|
|
else:
|
|
print("FAILURE: The command won't run!")
|
|
|
|
def printHelp():
|
|
global sysvals
|
|
modes = getModes()
|
|
|
|
print("")
|
|
print("AnalyzeSuspend")
|
|
print("Usage: sudo analyze_suspend.py <options>")
|
|
print("")
|
|
print("Description:")
|
|
print(" Initiates a system suspend/resume while capturing dmesg")
|
|
print(" and (optionally) ftrace data to analyze device timing")
|
|
print("")
|
|
print(" Generates output files in subdirectory: suspend-mmddyy-HHMMSS")
|
|
print(" HTML output: <hostname>_<mode>.html")
|
|
print(" raw dmesg output: <hostname>_<mode>_dmesg.txt")
|
|
print(" raw ftrace output (with -f): <hostname>_<mode>_ftrace.txt")
|
|
print("")
|
|
print("Options:")
|
|
print(" [general]")
|
|
print(" -h Print this help text")
|
|
print(" -verbose Print extra information during execution and analysis")
|
|
print(" -status Test to see if the system is enabled to run this tool")
|
|
print(" -modes List available suspend modes")
|
|
print(" -m mode Mode to initiate for suspend %s (default: %s)") % (modes, sysvals.suspendmode)
|
|
print(" -rtcwake Use rtcwake to autoresume after 10 seconds (default: disabled)")
|
|
print(" -f Use ftrace to create device callgraphs (default: disabled)")
|
|
print(" [re-analyze data from previous runs]")
|
|
print(" -dmesg dmesgfile Create HTML timeline from dmesg file")
|
|
print(" -ftrace ftracefile Create HTML callgraph from ftrace file")
|
|
print("")
|
|
return True
|
|
|
|
def doError(msg, help):
|
|
print("ERROR: %s") % msg
|
|
if(help == True):
|
|
printHelp()
|
|
sys.exit()
|
|
|
|
# -- script main --
|
|
# loop through the command line arguments
|
|
cmd = ""
|
|
args = iter(sys.argv[1:])
|
|
for arg in args:
|
|
if(arg == "-m"):
|
|
try:
|
|
val = args.next()
|
|
except:
|
|
doError("No mode supplied", True)
|
|
sysvals.suspendmode = val
|
|
elif(arg == "-f"):
|
|
data.useftrace = True
|
|
elif(arg == "-modes"):
|
|
cmd = "modes"
|
|
elif(arg == "-status"):
|
|
cmd = "status"
|
|
elif(arg == "-verbose"):
|
|
data.verbose = True
|
|
elif(arg == "-rtcwake"):
|
|
sysvals.rtcwake = True
|
|
elif(arg == "-dmesg"):
|
|
try:
|
|
val = args.next()
|
|
except:
|
|
doError("No dmesg file supplied", True)
|
|
data.notestrun = True
|
|
data.usedmesg = True
|
|
sysvals.dmesgfile = val
|
|
elif(arg == "-ftrace"):
|
|
try:
|
|
val = args.next()
|
|
except:
|
|
doError("No ftrace file supplied", True)
|
|
data.notestrun = True
|
|
data.useftrace = True
|
|
sysvals.ftracefile = val
|
|
elif(arg == "-h"):
|
|
printHelp()
|
|
sys.exit()
|
|
else:
|
|
doError("Invalid argument: "+arg, True)
|
|
|
|
# just run a utility command and exit
|
|
if(cmd != ""):
|
|
if(cmd == "status"):
|
|
statusCheck(True)
|
|
elif(cmd == "modes"):
|
|
modes = getModes()
|
|
print modes
|
|
sys.exit()
|
|
|
|
data.initialize()
|
|
|
|
# if instructed, re-analyze existing data files
|
|
if(data.notestrun):
|
|
sysvals.setOutputFile()
|
|
data.vprint("Output file: %s" % sysvals.htmlfile)
|
|
if(sysvals.dmesgfile != ""):
|
|
analyzeKernelLog()
|
|
if(sysvals.ftracefile != ""):
|
|
analyzeTraceLog()
|
|
createHTML()
|
|
sys.exit()
|
|
|
|
# verify that we can run a test
|
|
data.usedmesg = True
|
|
statusCheck(False)
|
|
|
|
# prepare for the test
|
|
if(data.useftrace):
|
|
initFtrace()
|
|
sysvals.initTestOutput()
|
|
|
|
data.vprint("Output files:\n %s" % sysvals.dmesgfile)
|
|
if(data.useftrace):
|
|
data.vprint(" %s" % sysvals.ftracefile)
|
|
data.vprint(" %s" % sysvals.htmlfile)
|
|
|
|
# execute the test
|
|
executeSuspend()
|
|
analyzeKernelLog()
|
|
if(data.useftrace):
|
|
analyzeTraceLog()
|
|
createHTML()
|