diff options
Diffstat (limited to 'scripts')
| -rw-r--r-- | scripts/Makefile.lib | 13 | ||||
| -rwxr-xr-x | scripts/analyze_suspend.py | 1446 | ||||
| -rw-r--r-- | scripts/kconfig/confdata.c | 14 | ||||
| -rw-r--r-- | scripts/kconfig/expr.h | 3 | ||||
| -rw-r--r-- | scripts/kconfig/lkc.h | 1 | ||||
| -rw-r--r-- | scripts/kconfig/symbol.c | 11 | ||||
| -rwxr-xr-x | scripts/setlocalversion | 23 | ||||
| -rw-r--r-- | scripts/tracing/dma-api/.gitignore | 1 | ||||
| -rw-r--r-- | scripts/tracing/dma-api/README | 36 | ||||
| -rw-r--r-- | scripts/tracing/dma-api/plotting.py | 100 | ||||
| -rw-r--r-- | scripts/tracing/dma-api/smmu.py | 202 | ||||
| -rw-r--r-- | scripts/tracing/dma-api/trace.py | 349 |
12 files changed, 2175 insertions, 24 deletions
diff --git a/scripts/Makefile.lib b/scripts/Makefile.lib index f97869f1f09b..a92a23ceb4c5 100644 --- a/scripts/Makefile.lib +++ b/scripts/Makefile.lib @@ -152,6 +152,7 @@ ld_flags = $(LDFLAGS) $(ldflags-y) dtc_cpp_flags = -Wp,-MD,$(depfile).pre.tmp -nostdinc \ -I$(srctree)/arch/$(SRCARCH)/boot/dts \ -I$(srctree)/arch/$(SRCARCH)/boot/dts/include \ + $(DTCCPP_FLAGS) \ -undef -D__DTS__ # Finds the multi-part object the current object will be linked into @@ -273,6 +274,18 @@ $(obj)/%.dtb: $(src)/%.dts FORCE dtc-tmp = $(subst $(comma),_,$(dot-target).dts.tmp) +$(obj)/%.dtb: $(src)/%.dts FORCE + $(call if_changed_dep,dtc) + +dtc-tmp = $(subst $(comma),_,$(dot-target).dts) + +quiet_cmd_dtc_cpp = DTC+CPP $@ +cmd_dtc_cpp = $(CPP) $(dtc_cpp_flags) -x assembler-with-cpp -o $(dtc-tmp) $< ; \ + $(objtree)/scripts/dtc/dtc -O dtb -o $@ -b 0 $(DTC_FLAGS) $(dtc-tmp) + +$(obj)/%.dtb: $(src)/%.dtsp FORCE + $(call if_changed_dep,dtc_cpp) + # Bzip2 # --------------------------------------------------------------------------- diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py new file mode 100755 index 000000000000..4f2cc12dc7c7 --- /dev/null +++ b/scripts/analyze_suspend.py @@ -0,0 +1,1446 @@ +#!/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() diff --git a/scripts/kconfig/confdata.c b/scripts/kconfig/confdata.c index 43eda40c3838..35e0f164ef81 100644 --- a/scripts/kconfig/confdata.c +++ b/scripts/kconfig/confdata.c @@ -1083,7 +1083,7 @@ static void randomize_choice_values(struct symbol *csym) csym->flags &= ~(SYMBOL_VALID); } -static void set_all_choice_values(struct symbol *csym) +void set_all_choice_values(struct symbol *csym) { struct property *prop; struct symbol *sym; @@ -1100,7 +1100,7 @@ static void set_all_choice_values(struct symbol *csym) } csym->flags |= SYMBOL_DEF_USER; /* clear VALID to get value calculated */ - csym->flags &= ~(SYMBOL_VALID); + csym->flags &= ~(SYMBOL_VALID | SYMBOL_NEED_SET_CHOICE_VALUES); } void conf_set_all_new_symbols(enum conf_def_mode mode) @@ -1202,6 +1202,14 @@ void conf_set_all_new_symbols(enum conf_def_mode mode) * selected in a choice block and we set it to yes, * and the rest to no. */ + if (mode != def_random) { + for_all_symbols(i, csym) { + if ((sym_is_choice(csym) && !sym_has_value(csym)) || + sym_is_choice_value(csym)) + csym->flags |= SYMBOL_NEED_SET_CHOICE_VALUES; + } + } + for_all_symbols(i, csym) { if (sym_has_value(csym) || !sym_is_choice(csym)) continue; @@ -1209,7 +1217,5 @@ void conf_set_all_new_symbols(enum conf_def_mode mode) sym_calc_value(csym); if (mode == def_random) randomize_choice_values(csym); - else - set_all_choice_values(csym); } } diff --git a/scripts/kconfig/expr.h b/scripts/kconfig/expr.h index cdd48600e02a..df198a5f4822 100644 --- a/scripts/kconfig/expr.h +++ b/scripts/kconfig/expr.h @@ -106,6 +106,9 @@ struct symbol { #define SYMBOL_DEF3 0x40000 /* symbol.def[S_DEF_3] is valid */ #define SYMBOL_DEF4 0x80000 /* symbol.def[S_DEF_4] is valid */ +/* choice values need to be set before calculating this symbol value */ +#define SYMBOL_NEED_SET_CHOICE_VALUES 0x100000 + #define SYMBOL_MAXLENGTH 256 #define SYMBOL_HASHSIZE 9973 diff --git a/scripts/kconfig/lkc.h b/scripts/kconfig/lkc.h index f8aee5fc6d5e..0c8d4191ca87 100644 --- a/scripts/kconfig/lkc.h +++ b/scripts/kconfig/lkc.h @@ -87,6 +87,7 @@ char *conf_get_default_confname(void); void sym_set_change_count(int count); void sym_add_change_count(int count); void conf_set_all_new_symbols(enum conf_def_mode mode); +void set_all_choice_values(struct symbol *csym); struct conf_printer { void (*print_symbol)(FILE *, struct symbol *, const char *, void *); diff --git a/scripts/kconfig/symbol.c b/scripts/kconfig/symbol.c index ecc5aa5f865d..ab8f4c835933 100644 --- a/scripts/kconfig/symbol.c +++ b/scripts/kconfig/symbol.c @@ -300,6 +300,14 @@ void sym_calc_value(struct symbol *sym) if (sym->flags & SYMBOL_VALID) return; + + if (sym_is_choice_value(sym) && + sym->flags & SYMBOL_NEED_SET_CHOICE_VALUES) { + sym->flags &= ~SYMBOL_NEED_SET_CHOICE_VALUES; + prop = sym_get_choice_prop(sym); + sym_calc_value(prop_get_symbol(prop)); + } + sym->flags |= SYMBOL_VALID; oldval = sym->curr; @@ -425,6 +433,9 @@ void sym_calc_value(struct symbol *sym) if (sym->flags & SYMBOL_AUTO) sym->flags &= ~SYMBOL_WRITE; + + if (sym->flags & SYMBOL_NEED_SET_CHOICE_VALUES) + set_all_choice_values(sym); } void sym_clear_all_valid(void) diff --git a/scripts/setlocalversion b/scripts/setlocalversion index 84b88f109b80..b16a1849a160 100755 --- a/scripts/setlocalversion +++ b/scripts/setlocalversion @@ -45,26 +45,9 @@ scm_version() # Check for git and a git repo. if test -d .git && head=`git rev-parse --verify --short HEAD 2>/dev/null`; then - # If we are at a tagged commit (like "v2.6.30-rc6"), we ignore - # it, because this version is defined in the top level Makefile. - if [ -z "`git describe --exact-match 2>/dev/null`" ]; then - - # If only the short version is requested, don't bother - # running further git commands - if $short; then - echo "+" - return - fi - # If we are past a tagged commit (like - # "v2.6.30-rc5-302-g72357d5"), we pretty print it. - if atag="`git describe 2>/dev/null`"; then - echo "$atag" | awk -F- '{printf("-%05d-%s", $(NF-1),$(NF))}' - - # If we don't have a tag at all we print -g{commitish}. - else - printf '%s%s' -g $head - fi - fi + # Regardless whether it is a tagged commit (like "v2.6.30-rc6"), + # we will put the commit info in. + printf '%s%s' -g $head # Is this git on svn? if git config --get svn-remote.svn.url >/dev/null; then diff --git a/scripts/tracing/dma-api/.gitignore b/scripts/tracing/dma-api/.gitignore new file mode 100644 index 000000000000..0d20b6487c61 --- /dev/null +++ b/scripts/tracing/dma-api/.gitignore @@ -0,0 +1 @@ +*.pyc diff --git a/scripts/tracing/dma-api/README b/scripts/tracing/dma-api/README new file mode 100644 index 000000000000..caeb88f23ea2 --- /dev/null +++ b/scripts/tracing/dma-api/README @@ -0,0 +1,36 @@ + + DMA API trace BASIC USAGE + =========================== + + +Enable CONFIG_DMA_API_DEBUG +---------------------------- +$TOP/kernel/scripts/config \ + --file $OUT/obj/KERNEL/.config \ + -e DMA_API_DEBUG +make -C$TOP/kernel ARCH=arm O=$OUT/obj/KERNEL oldconfig +grep DMA_API_DEBUG $OUT/obj/KERNEL/.config + + + +Via debugfs +----------- +adb shell cat /d/dma-api/dump_{mappings,allocs,allocs_detail} + + +Via Ftrace +---------- +# All ftraces from boot, add "trace_event=dmadebug:*" to kernel command line +sed -i '/strlcpy(cmd_line, boot_command_line, /i \ + \tstrcat(boot_command_line, " trace_event=dmadebug:*");' \ + $TOP/kernel/arch/arm/kernel/setup.c + +Or + +adb shell "echo 'dmadebug:*' >> /d/tracing/set_event" + +adb shell <your_test_here> +adb shell "echo '\!dmadebug:*' >> /d/tracing/set_event" +adb pull /d/tracing/trace + +python $TOP/kernel/scripts/tracing/dma-api/trace.py trace diff --git a/scripts/tracing/dma-api/plotting.py b/scripts/tracing/dma-api/plotting.py new file mode 100644 index 000000000000..f3d69b6a36a4 --- /dev/null +++ b/scripts/tracing/dma-api/plotting.py @@ -0,0 +1,100 @@ +"""Ugly graph drawing tools""" +import matplotlib.pyplot as plt +import matplotlib.cm as cmap +#import numpy as np +from matplotlib import cbook + +# http://stackoverflow.com/questions/4652439/is-there-a-matplotlib-equivalent-of-matlabs-datacursormode +class DataCursor(object): + """A simple data cursor widget that displays the x,y location of a + matplotlib artist when it is selected.""" + def __init__(self, artists, tolerance=5, offsets=(-20, 20), + template='x: %0.2f\ny: %0.2f', display_all=False): + """Create the data cursor and connect it to the relevant figure. + "artists" is the matplotlib artist or sequence of artists that will be + selected. + "tolerance" is the radius (in points) that the mouse click must be + within to select the artist. + "offsets" is a tuple of (x,y) offsets in points from the selected + point to the displayed annotation box + "template" is the format string to be used. Note: For compatibility + with older versions of python, this uses the old-style (%) + formatting specification. + "display_all" controls whether more than one annotation box will + be shown if there are multiple axes. Only one will be shown + per-axis, regardless. + """ + self.template = template + self.offsets = offsets + self.display_all = display_all + if not cbook.iterable(artists): + artists = [artists] + self.artists = artists + self.axes = tuple(set(art.axes for art in self.artists)) + self.figures = tuple(set(ax.figure for ax in self.axes)) + + self.annotations = {} + for ax in self.axes: + self.annotations[ax] = self.annotate(ax) + + for artist in self.artists: + artist.set_picker(tolerance) + for fig in self.figures: + fig.canvas.mpl_connect('pick_event', self) + + def annotate(self, ax): + """Draws and hides the annotation box for the given axis "ax".""" + annotation = ax.annotate(self.template, xy=(0, 0), ha='right', + xytext=self.offsets, textcoords='offset points', va='bottom', + bbox=dict(boxstyle='round,pad=0.5', fc='yellow', alpha=0.5), + arrowprops=dict(arrowstyle='->', connectionstyle='arc3,rad=0') + ) + annotation.set_visible(False) + return annotation + + def __call__(self, event): + """Intended to be called through "mpl_connect".""" + # Rather than trying to interpolate, just display the clicked coords + # This will only be called if it's within "tolerance", anyway. + x, y = event.mouseevent.xdata, event.mouseevent.ydata + try: + annotation = self.annotations[event.artist.axes] + except KeyError: + return + if x is not None: + if not self.display_all: + # Hide any other annotation boxes... + for ann in self.annotations.values(): + ann.set_visible(False) + # Update the annotation in the current axis.. + annotation.xy = x, y + annotation.set_text(self.template % (x, y)) + annotation.set_visible(True) + event.canvas.draw() + +def plotseries(*serieslabels): + """Plot lists of series in separate axes, tie time axis together""" + global fig + fig, axes = plt.subplots(nrows=len(serieslabels), sharex=True) + + for subplot, ax in zip(serieslabels, axes): + for ser, lab in zip(*subplot): # subplot = ([x], [y]) + ax.step(ser[0], ser[1], label=lab, where="post") + ax.grid(True) + ax.legend() + + (DataCursor(ax.lines)) + plt.grid(True) + plt.show() + + + +def disp_pic(bitmap): + """Display the allocation bitmap. TODO.""" + fig=plt.figure() + a=fig.add_subplot(1,1,1) + fig.clf() + implt=plt.imshow(bitmap, extent=(0, len(bitmap[0]), 0, len(bitmap)), + interpolation="nearest", cmap=cmap.gist_heat) + fig.canvas.draw() + plt.show() diff --git a/scripts/tracing/dma-api/smmu.py b/scripts/tracing/dma-api/smmu.py new file mode 100644 index 000000000000..0fbadff7119f --- /dev/null +++ b/scripts/tracing/dma-api/smmu.py @@ -0,0 +1,202 @@ +"""Low-level memory management tracking""" + +VERBOSITY = 0 # TODO: use logging + +class Bitmap(object): + """Just a raw bitmap for reserving the pages""" + def __init__(self, size, verbosity): + self._size = size + self._bits = 0 + self._verbosity = verbosity + self._bits_allocd = 0 + + def _mask(self, offset, length): + """length amount of 1's, shifted left by offset""" + assert offset >= 0, "offset < 0" + assert offset < self._size, "offset 0x%d >= size %s" % (offset, self._size) + bitstring = (1 << length) - 1 + return bitstring << offset + + def _indices(self, offset, length): + """Bit numbers starting from offset""" + return range(offset, offset + length) + + def alloc(self, offset, length): + """Reserve the bits, warn if verbose and some set already""" + mask = self._mask(offset, length) + if (self._bits & mask) != 0 and self._verbosity >= 1: + print "warning: duplicate allocation" + self._bits |= mask + self._bits_allocd += length + return self._indices(offset, length) + + def free(self, offset, length): + """Free the bits, warn if verbose and some not set yet""" + mask = self._mask(offset, length) + if (self._bits & mask) != mask and self._verbosity >= 1: + print "warning: freeing freed memory, mapbits %x" % (self._bits & mask) + self._bits &= ~mask + self._bits_allocd -= length + return self._indices(offset, length) + + def contains(self, offset, length): + """Are some bits in the given range set?""" + mask = self._mask(offset, length) + return self._bits & mask + + def __repr__(self): + return "<bitmap, %d/%d allocd>" % (self._bits_allocd, self._size) + +class Memory(object): + """Store and handle raw bitmaps, check mapping collisions between devices""" + PAGESHIFT = 12 + PAGESIZE = 1 << PAGESHIFT + PAGEMASK = PAGESIZE - 1 + + def __init__(self, addr, size, asid): + """addr: lowest possible address, size: bytes, asid: arbitrary id""" + assert (addr & self.PAGEMASK) == 0, addr + assert (size & self.PAGEMASK) == 0, size + + self._addr = addr + self._size = size + self._end = addr + size + self._asid = asid + self._bitmap = Bitmap(size >> self.PAGESHIFT, VERBOSITY) + self._devmaps = {} + + if VERBOSITY >= 1: + print "memory at %08x-%08x" % (addr, addr + size) + + def to_bit(self, addr): + """Address to bitmap position""" + return addr >> self.PAGESHIFT + + def alloc(self, dev, addr, size): + """Allocate (map) for the given device, verify things""" + if addr >= self._end: + if VERBOSITY >= 1: + print "warning: %s mapping beyond bitmap: %08x" % (dev, addr) + return [] + + if (addr & self.PAGEMASK) != 0: + if VERBOSITY >= 1: + print "warning: alloc not aligned at 0x%x, size %d (new addr 0x%x, size %d)" % ( + addr, size, addr & ~self.PAGEMASK, size + (addr & self.PAGEMASK)) + addr &= ~self.PAGEMASK + size += addr & self.PAGEMASK + + if size < self.PAGESIZE: + size = self.PAGESIZE + + for user, bmp in self._devmaps.iteritems(): + if bmp.contains(self.to_bit(addr - self._addr), self.to_bit(size)): + if VERBOSITY >= 1: + print "warning: %s mapping [0x%x,0x%x) already used by %s" % ( + dev, addr, addr + size, user) + + devmap = self._devmaps.setdefault(dev, Bitmap(self._bitmap._size, 0)) + + self._alloc(devmap, addr, size) + bits = self._alloc(self._bitmap, addr, size) + return bits + + def _alloc(self, bitmap, addr, size): + """Allocate from an internal bitmap""" + return bitmap.alloc(self.to_bit(addr - self._addr), self.to_bit(size)) + + def free(self, dev, addr, size): + """Free (unmap) for the given device, verify things""" + if (addr & self.PAGEMASK) != 0: + if VERBOSITY >= 1: + print "warning: free not aligned at 0x%x, size %d (new addr 0x%x, size %d)" % ( + addr, size, addr & ~self.PAGEMASK, size + (addr & self.PAGEMASK)) + addr &= ~self.PAGEMASK + size += addr & self.PAGEMASK + + if size < self.PAGESIZE: + size = self.PAGESIZE + + devmap = self._devmaps.setdefault(dev, Bitmap(self._bitmap._size, 0)) + + owners = [] + for user, bmp in self._devmaps.iteritems(): + if bmp.contains(self.to_bit(addr - self._addr), self.to_bit(size)): + owners.append((user, bmp)) + + if len(owners) == 0: + if VERBOSITY >= 1: + print "warning: %s freeing 0x%x that nobody owns" % (dev, addr) + elif len(owners) == 1: + if owners[0][0] != dev and VERBOSITY >= 2: + print "note: %s freeing 0x%x allocd by %s" % ( + dev, addr, owners[0][0]) + devmap = owners[0][1] + + self._free(devmap, addr, size) + bits = self._free(self._bitmap, addr, size) + return bits + + def _free(self, bitmap, addr, size): + """Free from an internal bitmap""" + return bitmap.free(self.to_bit(addr - self._addr), self.to_bit(size)) + + +class Device(object): + """Keep track of allocations per device/process + + This needs more tricky work for tracking inter-process maps/unmaps :( + """ + + def __init__(self, name, mem): + self._name = name + self._mem = mem + self._max_alloc = 0 + self._cur_alloc = 0 + self._alloc_history = [] + self._addresses = [] + + def alloc(self, addr, size): + pages = self._mem.alloc(self, addr, size) + if pages is not False: + self._cur_alloc += size + self._max_alloc = max(self._max_alloc, self._cur_alloc) + self._alloc_history.append(self._cur_alloc) + if addr in self._addresses: + if VERBOSITY >= 1: + print "warning: %s allocing dupe address %x %s" % (self._name, addr, len([x for x in self._addresses if x == addr])) + self._addresses.append(addr) + return pages + + def free(self, addr, size): + pages = self._mem.free(self, addr, size) + self._cur_alloc -= size + if addr in self._addresses: + self._addresses.remove(addr) + else: + if VERBOSITY >= 1: + print "warning: %s freeing unallocated %x" % (self._name, addr) + return pages + + def history_at(self, i): + return self._alloc_history[i] + + @property + def name(self): + return self._name + + def __str__(self): + return self.name + + def __repr__(self): + return "<dev: %s>" % self.name + + @property + def max_allocated(self): + return self._max_alloc + + +class AsidSpace(object): + # TODO: don't pre-grep by archdata but put devices' mem maps here. + pass + diff --git a/scripts/tracing/dma-api/trace.py b/scripts/tracing/dma-api/trace.py new file mode 100644 index 000000000000..c4507b6c4d02 --- /dev/null +++ b/scripts/tracing/dma-api/trace.py @@ -0,0 +1,349 @@ +"""Main program and stuff""" + +#from pprint import pprint +from sys import stdin +import os.path +import re +from argparse import ArgumentParser +import cPickle as pickle +from collections import namedtuple +from plotting import plotseries, disp_pic +import smmu + +class TracelineParser(object): + """Parse the needed information out of an ftrace line""" + # <...>-6 [000] d..2 5.287079: dmadebug_iommu_map_page: device=sdhci-tegra.3, addr=0x01048000, size=4096 page=c13e7214 archdata=ed504640 + def __init__(self): + self.pattern = re.compile("device=(?P<dev>.*), addr=(?P<addr>.*), size=(?P<size>.*) page=(?P<page>.*) archdata=(?P<archdata>.*)") + def parse(self, args): + args = self.pattern.match(args) + return (args.group("dev"), int(args.group("addr"), 16), + int(args.group("size")), int(args.group("page"), 16), + int(args.group("archdata"), 16)) + +def biggest_indices(items, n): + """Return list of indices of n biggest elements in items""" + with_indices = [(x, i) for i, x in enumerate(items)] + ordered = sorted(with_indices) + return [i for x, i in ordered[-n:]] + +def by_indices(xs, ids): + """Get elements from the list xs by their indices""" + return [xs[i] for i in ids] + +"""Event represents one input line""" +Event = namedtuple("Event", ["time", "dev", "data", "delta"]) + +class Trace(object): + def __init__(self, args): + smmu.VERBOSITY = args.verbosity + self._args = args + self.devlist = [] + self.events = [] + self.metrics = { + "max_peak": self._usage_peak, + "activity_rate": self._usage_activity, + "average_mem": self._usage_avg + } + self.traceliner = TracelineParser() + + @staticmethod + def get_metrics(): + """What filter metrics to get max users""" + return ["max_peak", "activity_rate", "average_mem"] + + def show(self): + """Shuffle events around, build plots, and show them""" + if self._args.max_plots: + evs = self.merge_events() + else: + evs = self.events + series, devlist = self.unload(evs) + if not self._args.no_plots: + self.plot(series, devlist) + + def _get_usage(self, evs): + """Return a metric of how active the events in evs are""" + return self.metrics[self._args.max_metric](evs) + + def _usage_peak(self, evs): + """Return the biggest peak""" + return max(e.data for e in evs) + + def _usage_activity(self, evs): + """Return the activity count: simply the length of the event list""" + return len(evs) + + def _usage_avg(self, evs): + """Return the average over all points""" + # FIXME: the data points are not uniform in time, so this might be + # somewhat off. + return float(sum(e.data for e in evs)) / len(e) + + def merge_events(self): + """Find out biggest users, keep them and flatten others to a single user""" + sizes = [] + dev_evs = [] + for i, dev in enumerate(self.devlist): + dev_evs.append([e for e in self.events if e.dev == dev]) + sizes.append(self._get_usage(dev_evs[i])) + + # indices of the devices + biggestix = biggest_indices(sizes, self._args.max_plots) + print biggestix + is_big = {} + for i, dev in enumerate(self.devlist): + is_big[dev] = i in biggestix + + evs = [] + for e in self.events: + if not is_big[e.dev]: + e = Event(e.time, "others", e.data, e.delta) + evs.append(e) + + self.devlist.append("others") + return evs + + def unload(self, events): + """Prepare the event list for plotting + + series ends up as [([time0], [data0]), ([time1], [data1]), ...] + """ + # ([x], [y]) for matplotlib + series = [([], []) for x in self.devlist] + devidx = dict([(d, i) for i, d in enumerate(self.devlist)]) + + for event in events: + devid = devidx[event.dev] + series[devid][0].append(event.time) + series[devid][1].append(event.data) # self.dev_data(event.dev)) + + series_out = [] + devlist_out = [] + + for ser, dev in zip(series, self.devlist): + if len(ser[0]) > 0: + series_out.append(ser) + devlist_out.append(dev) + + return series_out, devlist_out + + def plot(self, series, devlist): + """Display the plots""" + #series, devlist = flatten_axes(self.series, self.devlist, + # self._args.max_plots) + devinfo = (series, map(str, devlist)) + allocfreeinfo = (self.allocsfrees, ["allocd", "freed", "current"]) + plotseries(devinfo, allocfreeinfo) + #plotseries(devinfo) + + def dev_data(self, dev): + """what data to plot against time""" + return dev._cur_alloc + + def _cache_hash(self, filename): + """The trace files are probably not of the same size""" + return str(os.path.getsize(filename)) + + def load_cache(self): + """Get the trace data from a database file, if one exists""" + has = self._cache_hash(self._args.filename) + try: + cache = open("trace." + has) + except IOError: + pass + else: + self._load_cache(pickle.load(cache)) + return True + return False + + def save_cache(self): + """Store the raw trace data to a database""" + data = self._save_cache() + fh = open("trace." + self._cache_hash(self._args.filename), "w") + pickle.dump(data, fh) + + def _save_cache(self): + """Return the internal data that is needed to be pickled""" + return self.events, self.devlist, self.allocsfrees + + def _load_cache(self, data): + """Get the data from an unpickled object""" + self.events, self.devlist, self.allocsfrees = data + + def load_events(self): + """Get the internal data from a trace file or cache""" + if self._args.filename: + if self._args.cache and self.load_cache(): + return + fh = open(self._args.filename) + else: + fh = stdin + + self.parse(fh) + + if self._args.cache and self._args.filename: + self.save_cache() + + def parse(self, fh): + """Parse the trace file in fh, store data to self""" + mems = {} + dev_by_name = {} + devlist = [] + buf_owners = {} + events = [] + allocsfrees = [([], []), ([], []), ([], [])] # allocs, frees, current + allocs = 0 + frees = 0 + curbufs = 0 + + mem_bytes = 1024 * 1024 * 1024 + npages = mem_bytes / 4096 + ncols = 512 + le_pic = [0] * npages + lastupd = 0 + + for lineidx, line in enumerate(fh): + # no comments + if line.startswith("#"): + continue + + taskpid, cpu, flags, timestamp, func, args = line.strip().split(None, 5) + func = func[:-len(":")] + # unneeded events may be there too + if not func.startswith("dmadebug"): + continue + + if self._args.verbosity >= 3: + print line.rstrip() + + timestamp = float(timestamp[:-1]) + if timestamp < self._args.start: + continue + if timestamp >= self._args.end: + break + + devname, addr, size, page, archdata = self.traceliner.parse(args) + if self._args.processes: + devname = taskpid.split("-")[0] + mapping = archdata + + try: + memmap = mems[mapping] + except KeyError: + memmap = mem(mapping) + mems[mapping] = memmap + + try: + dev = dev_by_name[devname] + except KeyError: + dev = smmu.Device(devname, memmap) + dev_by_name[devname] = dev + devlist.append(dev) + + allocfuncs = ["dmadebug_map_page", "dmadebug_map_sg", "dmadebug_alloc_coherent"] + freefuncs = ["dmadebug_unmap_page", "dmadebug_unmap_sg", "dmadebug_free_coherent"] + ignfuncs = [] + + if timestamp-lastupd > 0.1: + # just some debug prints for now + lastupd = timestamp + print lineidx,timestamp + le_pic2 = [le_pic[i:i+ncols] for i in range(0, npages, ncols)] + #disp_pic(le_pic2) + + # animating the bitmap would be cool + #for row in le_pic: + # for i, a in enumerate(row): + # pass + #row[i] = 0.09 * a + + if func in allocfuncs: + pages = dev_by_name[devname].alloc(addr, size) + for p in pages: + le_pic[p] = 1 + buf_owners[addr] = dev_by_name[devname] + allocs += 1 + curbufs += 1 + allocsfrees[0][0].append(timestamp) + allocsfrees[0][1].append(allocs) + elif func in freefuncs: + if addr not in buf_owners: + if self._args.verbosity >= 1: + print "warning: %s unmapping unmapped %s" % (dev, addr) + buf_owners[addr] = dev + # fixme: move this to bitmap handling + # get to know the owners of bits + # allocs/frees calls should be traced separately from maps? + # map_pages is traced per page :( + if buf_owners[addr] != dev and self._args.verbosity >= 2: + print "note: %s unmapping [%d,%d) mapped by %s" % ( + dev, addr, addr+size, buf_owners[addr]) + pages = buf_owners[addr].free(addr, size) + for p in pages: + le_pic[p] = 0 + frees -= 1 + curbufs -= 1 + allocsfrees[1][0].append(timestamp) + allocsfrees[1][1].append(frees) + elif func not in ignfuncs: + raise ValueError("unhandled %s" % func) + + allocsfrees[2][0].append(timestamp) + allocsfrees[2][1].append(curbufs) + + events.append(Event(timestamp, dev, self.dev_data(dev), size)) + + self.events = events + self.devlist = devlist + self.allocsfrees = allocsfrees + + le_pic2 = [le_pic[i:i+ncols] for i in range(0, npages, ncols)] + # FIXME: not quite ready yet + disp_pic(le_pic2) + + return + +def mem(asid): + """Create a new memory object for the given asid space""" + SZ_2G = 2 * 1024 * 1024 * 1024 + SZ_1M = 1 * 1024 * 1024 + # arch/arm/mach-tegra/include/mach/iomap.h TEGRA_SMMU_(BASE|SIZE) + base = 0x80000000 + size = SZ_2G - SZ_1M + return smmu.Memory(base, size, asid) + +def get_args(): + """Eat command line arguments, return argparse namespace for settings""" + parser = ArgumentParser() + parser.add_argument("filename", nargs="?", + help="trace file dump, stdin if not given") + parser.add_argument("-s", "--start", type=float, default=0, + help="start timestamp") + parser.add_argument("-e", "--end", type=float, default=1e9, + help="end timestamp") + parser.add_argument("-v", "--verbosity", action="count", default=0, + help="amount of extra information: once for warns (dup addrs), " + "twice for notices (different client in map/unmap), " + "three for echoing all back") + parser.add_argument("-p", "--processes", action="store_true", + help="use processes as memory clients instead of devices") + parser.add_argument("-n", "--no-plots", action="store_true", + help="Don't draw the plots, only read the trace") + parser.add_argument("-c", "--cache", action="store_true", + help="Pickle the data and make a cache file for fast reloading") + parser.add_argument("-m", "--max-plots", type=int, + help="Maximum number of clients to show; show biggest and sum others") + parser.add_argument("-M", "--max-metric", choices=Trace.get_metrics(), + default=Trace.get_metrics()[0], + help="Metric to use when choosing clients in --max-plots") + return parser.parse_args() + +def main(): + args = get_args() + trace = Trace(args) + trace.load_events() + trace.show() + +if __name__ == "__main__": + main() |