From b8432c6fc12bdf4a6921e1640d3ead23fcd04c10 Mon Sep 17 00:00:00 2001 From: Todd E Brandt Date: Fri, 8 Aug 2014 09:11:59 -0700 Subject: PM / tools: analyze_suspend.py: update to v3.0 Update of analyze_suspend.py to v3.0 New features include back-2-back suspend testing, device filters to reduce the html size, the inclusion of device_prepare and device_complete callbacks, a usb topography list, and the ability to control USB device autosuspend. UI upgrades include a device detail window and mini-timeline, the addition of a suspend_prepare and resume_complete phase to the timeline which includes the associated device callbacks, automatic highlight of related callbacks, and general color and name changes for better reability. The new version relies on two trace point patches that are already in the kernel: enable_trace_events_suspend_resume.patch enable_trace_events_device_pm_callback.patch It has legacy support for older kernels without these trace events, but when available the tool processes the ftrace output alone (dmesg has been deprecated as a tool input, and is only gathered for convenience). Link: https://01.org/suspendresume/downloads/analyzesuspend-v3.0 Signed-off-by: Todd Brandt Signed-off-by: Rafael J. Wysocki --- scripts/analyze_suspend.py | 3817 ++++++++++++++++++++++++++++++++++---------- 1 file changed, 2981 insertions(+), 836 deletions(-) diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py index 4f2cc12dc7c7..93e1fd40f430 100755 --- a/scripts/analyze_suspend.py +++ b/scripts/analyze_suspend.py @@ -36,146 +36,392 @@ # CONFIG_FUNCTION_TRACER=y # CONFIG_FUNCTION_GRAPH_TRACER=y # +# For kernel versions older than 3.15: # The following additional kernel parameters are required: # (e.g. in file /etc/default/grub) # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." # +# ----------------- LIBRARIES -------------------- + import sys import time import os import string import re -import array import platform -import datetime +from datetime import datetime import struct -# -- classes -- +# ----------------- CLASSES -------------------- +# Class: SystemValues +# Description: +# A global, single-instance container used to +# store system values and test parameters class SystemValues: - testdir = "." - tpath = "/sys/kernel/debug/tracing/" - mempath = "/dev/mem" - powerfile = "/sys/power/state" - suspendmode = "mem" - prefix = "test" - teststamp = "" - dmesgfile = "" - ftracefile = "" - htmlfile = "" + version = 3.0 + verbose = False + testdir = '.' + tpath = '/sys/kernel/debug/tracing/' + fpdtpath = '/sys/firmware/acpi/tables/FPDT' + epath = '/sys/kernel/debug/tracing/events/power/' + traceevents = [ + 'suspend_resume', + 'device_pm_callback_end', + 'device_pm_callback_start' + ] + modename = { + 'freeze': 'Suspend-To-Idle (S0)', + 'standby': 'Power-On Suspend (S1)', + 'mem': 'Suspend-to-RAM (S3)', + 'disk': 'Suspend-to-disk (S4)' + } + mempath = '/dev/mem' + powerfile = '/sys/power/state' + suspendmode = 'mem' + hostname = 'localhost' + prefix = 'test' + teststamp = '' + dmesgfile = '' + ftracefile = '' + htmlfile = '' rtcwake = False + rtcwaketime = 10 + rtcpath = '' + android = False + adb = 'adb' + devicefilter = [] + stamp = 0 + execcount = 1 + x2delay = 0 + usecallgraph = False + usetraceevents = False + usetraceeventsonly = False + notestrun = False + altdevname = dict() + postresumetime = 0 + tracertypefmt = '# tracer: (?P.*)' + firmwarefmt = '# fwsuspend (?P[0-9]*) fwresume (?P[0-9]*)$' + postresumefmt = '# post resume time (?P[0-9]*)$' + stampfmt = '# suspend-(?P[0-9]{2})(?P[0-9]{2})(?P[0-9]{2})-'+\ + '(?P[0-9]{2})(?P[0-9]{2})(?P[0-9]{2})'+\ + ' (?P.*) (?P.*) (?P.*)$' + def __init__(self): + self.hostname = platform.node() + if(self.hostname == ''): + self.hostname = 'localhost' + rtc = "rtc0" + if os.path.exists('/dev/rtc'): + rtc = os.readlink('/dev/rtc') + rtc = '/sys/class/rtc/'+rtc + if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \ + os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'): + self.rtcpath = rtc def setOutputFile(self): - if((self.htmlfile == "") and (self.dmesgfile != "")): - m = re.match(r"(?P.*)_dmesg\.txt$", self.dmesgfile) + if((self.htmlfile == '') and (self.dmesgfile != '')): + m = re.match('(?P.*)_dmesg\.txt$', self.dmesgfile) if(m): - self.htmlfile = m.group("name")+".html" - if((self.htmlfile == "") and (self.ftracefile != "")): - m = re.match(r"(?P.*)_ftrace\.txt$", self.ftracefile) + self.htmlfile = m.group('name')+'.html' + if((self.htmlfile == '') and (self.ftracefile != '')): + m = re.match('(?P.*)_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" + self.htmlfile = m.group('name')+'.html' + if(self.htmlfile == ''): + self.htmlfile = 'output.html' + def initTestOutput(self, subdir): + if(not self.android): + self.prefix = self.hostname + v = open('/proc/version', 'r').read().strip() + kver = string.split(v)[2] + else: + self.prefix = 'android' + v = os.popen(self.adb+' shell cat /proc/version').read().strip() + kver = string.split(v)[2] + testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S') + if(subdir != "."): + self.testdir = subdir+"/"+testtime + else: + self.testdir = testtime + self.teststamp = \ + '# '+testtime+' '+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) + def setDeviceFilter(self, devnames): + self.devicefilter = string.split(devnames) + def rtcWakeAlarm(self): + os.system('echo 0 > '+self.rtcpath+'/wakealarm') + outD = open(self.rtcpath+'/date', 'r').read().strip() + outT = open(self.rtcpath+'/time', 'r').read().strip() + mD = re.match('^(?P[0-9]*)-(?P[0-9]*)-(?P[0-9]*)', outD) + mT = re.match('^(?P[0-9]*):(?P[0-9]*):(?P[0-9]*)', outT) + if(mD and mT): + # get the current time from hardware + utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds()) + dt = datetime(\ + int(mD.group('y')), int(mD.group('m')), int(mD.group('d')), + int(mT.group('h')), int(mT.group('m')), int(mT.group('s'))) + nowtime = int(dt.strftime('%s')) + utcoffset + else: + # if hardware time fails, use the software time + nowtime = int(datetime.now().strftime('%s')) + alarm = nowtime + self.rtcwaketime + os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath)) +sysvals = SystemValues() + +# Class: DeviceNode +# Description: +# A container used to create a device hierachy, with a single root node +# and a tree of child nodes. Used by Data.deviceTopology() +class DeviceNode: + name = '' + children = 0 + depth = 0 + def __init__(self, nodename, nodedepth): + self.name = nodename + self.children = [] + self.depth = nodedepth + +# Class: Data +# Description: +# The primary container for suspend/resume test data. There is one for +# each test run. The data is organized into a cronological hierarchy: +# Data.dmesg { +# root structure, started as dmesg & ftrace, but now only ftrace +# contents: times for suspend start/end, resume start/end, fwdata +# phases { +# 10 sequential, non-overlapping phases of S/R +# contents: times for phase start/end, order/color data for html +# devlist { +# device callback or action list for this phase +# device { +# a single device callback or generic action +# contents: start/stop times, pid/cpu/driver info +# parents/children, html id for timeline/callgraph +# optionally includes an ftrace callgraph +# optionally includes intradev trace events +# } +# } +# } +# } +# 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}, + dmesg = {} # root data structure + phases = [] # ordered list of phases + start = 0.0 # test start + end = 0.0 # test end + tSuspended = 0.0 # low-level suspend start + tResumed = 0.0 # low-level resume start + tLow = 0.0 # time spent in low-level suspend (standby/freeze) + fwValid = False # is firmware data available + fwSuspend = 0 # time spent in firmware suspend + fwResume = 0 # time spent in firmware resume + dmesgtext = [] # dmesg text file in memory + testnumber = 0 + idstr = '' + html_device_id = 0 + stamp = 0 + outfile = '' + def __init__(self, num): + idchar = 'abcdefghijklmnopqrstuvwxyz' + self.testnumber = num + self.idstr = idchar[num] + self.dmesgtext = [] + self.phases = [] + self.dmesg = { # fixed list of 10 phases + 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#CCFFCC', 'order': 0}, + 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#88FF88', 'order': 1}, + 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#00AA00', 'order': 2}, '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}, + 'row': 0, 'color': '#008888', 'order': 3}, + 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#0000FF', 'order': 4}, + 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#FF0000', 'order': 5}, 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, - 'row': 0, 'color': "orange", 'order': 5}, + 'row': 0, 'color': '#FF9900', 'order': 6}, '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} + 'row': 0, 'color': '#FFCC00', 'order': 7}, + 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#FFFF88', 'order': 8}, + 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0, + 'row': 0, 'color': '#FFFFCC', 'order': 9} } 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 + def getStart(self): + return self.dmesg[self.phases[0]]['start'] + def setStart(self, time): + self.start = time + self.dmesg[self.phases[0]]['start'] = time + def getEnd(self): + return self.dmesg[self.phases[-1]]['end'] + def setEnd(self, time): + self.end = time + self.dmesg[self.phases[-1]]['end'] = time + def isTraceEventOutsideDeviceCalls(self, pid, time): + for phase in self.phases: + list = self.dmesg[phase]['list'] + for dev in list: + d = list[dev] + if(d['pid'] == pid and time >= d['start'] and + time <= d['end']): + return False + return True + def addIntraDevTraceEvent(self, action, name, pid, time): + if(action == 'mutex_lock_try'): + color = 'red' + elif(action == 'mutex_lock_pass'): + color = 'green' + elif(action == 'mutex_unlock'): + color = 'blue' + else: + # create separate colors based on the name + v1 = len(name)*10 % 256 + v2 = string.count(name, 'e')*100 % 256 + v3 = ord(name[0])*20 % 256 + color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3) + for phase in self.phases: + list = self.dmesg[phase]['list'] + for dev in list: + d = list[dev] + if(d['pid'] == pid and time >= d['start'] and + time <= d['end']): + e = TraceEvent(action, name, color, time) + if('traceevents' not in d): + d['traceevents'] = [] + d['traceevents'].append(e) + return d + break + return 0 + def capIntraDevTraceEvent(self, action, name, pid, time): + for phase in self.phases: + list = self.dmesg[phase]['list'] + for dev in list: + d = list[dev] + if(d['pid'] == pid and time >= d['start'] and + time <= d['end']): + if('traceevents' not in d): + return + for e in d['traceevents']: + if(e.action == action and + e.name == name and not e.ready): + e.length = time - e.time + e.ready = True + break + return + def trimTimeVal(self, t, t0, dT, left): + if left: + if(t > t0): + if(t - dT < t0): + return t0 + return t - dT + else: + return t + else: + if(t < t0 + dT): + if(t > t0): + return t0 + dT + return t + dT + else: + return t + def trimTime(self, t0, dT, left): + self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left) + self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left) + self.start = self.trimTimeVal(self.start, t0, dT, left) + self.end = self.trimTimeVal(self.end, t0, dT, left) for phase in self.phases: - zero = tRes - if "suspend" in phase: - zero = tSus p = self.dmesg[phase] - p['start'] -= zero - p['end'] -= zero + p['start'] = self.trimTimeVal(p['start'], t0, dT, left) + p['end'] = self.trimTimeVal(p['end'], t0, dT, left) list = p['list'] for name in list: d = list[name] - d['start'] -= zero - d['end'] -= zero + d['start'] = self.trimTimeVal(d['start'], t0, dT, left) + d['end'] = self.trimTimeVal(d['end'], t0, dT, left) if('ftrace' in d): cg = d['ftrace'] - cg.start -= zero - cg.end -= zero + cg.start = self.trimTimeVal(cg.start, t0, dT, left) + cg.end = self.trimTimeVal(cg.end, t0, dT, left) 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) + line.time = self.trimTimeVal(line.time, t0, dT, left) + if('traceevents' in d): + for e in d['traceevents']: + e.time = self.trimTimeVal(e.time, t0, dT, left) + def normalizeTime(self, tZero): + # first trim out any standby or freeze clock time + if(self.tSuspended != self.tResumed): + if(self.tResumed > tZero): + self.trimTime(self.tSuspended, \ + self.tResumed-self.tSuspended, True) + else: + self.trimTime(self.tSuspended, \ + self.tResumed-self.tSuspended, False) + # shift the timeline so that tZero is the new 0 + self.tSuspended -= tZero + self.tResumed -= tZero + self.start -= tZero + self.end -= tZero + for phase in self.phases: + p = self.dmesg[phase] + p['start'] -= tZero + p['end'] -= tZero + list = p['list'] + for name in list: + d = list[name] + d['start'] -= tZero + d['end'] -= tZero + if('ftrace' in d): + cg = d['ftrace'] + cg.start -= tZero + cg.end -= tZero + for line in cg.list: + line.time -= tZero + if('traceevents' in d): + for e in d['traceevents']: + e.time -= tZero + def newPhaseWithSingleAction(self, phasename, devname, start, end, color): + for phase in self.phases: + self.dmesg[phase]['order'] += 1 + self.html_device_id += 1 + devid = '%s%d' % (self.idstr, self.html_device_id) + list = dict() + list[devname] = \ + {'start': start, 'end': end, 'pid': 0, 'par': '', + 'length': (end-start), 'row': 0, 'id': devid, 'drv': '' }; + self.dmesg[phasename] = \ + {'list': list, 'start': start, 'end': end, + 'row': 0, 'color': color, 'order': 0} + self.phases = self.sortedPhases() + def newPhase(self, phasename, start, end, color, order): + if(order < 0): + order = len(self.phases) + for phase in self.phases[order:]: + self.dmesg[phase]['order'] += 1 + if(order > 0): + p = self.phases[order-1] + self.dmesg[p]['end'] = start + if(order < len(self.phases)): + p = self.phases[order] + self.dmesg[p]['start'] = end + list = dict() + self.dmesg[phasename] = \ + {'list': list, 'start': start, 'end': end, + 'row': 0, 'color': color, 'order': order} + self.phases = self.sortedPhases() + def setPhase(self, phase, ktime, isbegin): + if(isbegin): + self.dmesg[phase]['start'] = ktime + else: + self.dmesg[phase]['end'] = ktime def dmesgSortVal(self, phase): return self.dmesg[phase]['order'] def sortedPhases(self): @@ -197,59 +443,180 @@ class Data: dev = phaselist[devname] if(dev['end'] < 0): dev['end'] = end - self.vprint("%s (%s): callback didn't return" % (devname, phase)) + vprint('%s (%s): callback didnt return' % (devname, phase)) + def deviceFilter(self, devicefilter): + # remove all by the relatives of the filter devnames + filter = [] + for phase in self.phases: + list = self.dmesg[phase]['list'] + for name in devicefilter: + dev = name + while(dev in list): + if(dev not in filter): + filter.append(dev) + dev = list[dev]['par'] + children = self.deviceDescendants(name, phase) + for dev in children: + if(dev not in filter): + filter.append(dev) + for phase in self.phases: + list = self.dmesg[phase]['list'] + rmlist = [] + for name in list: + pid = list[name]['pid'] + if(name not in filter and pid >= 0): + rmlist.append(name) + for name in rmlist: + del list[name] 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 + self.fixupInitcalls(phase, self.getEnd()) + def newActionGlobal(self, name, start, end): + # which phase is this device callback or action "in" + targetphase = "none" + overlap = 0.0 + for phase in self.phases: + pstart = self.dmesg[phase]['start'] + pend = self.dmesg[phase]['end'] + o = max(0, min(end, pend) - max(start, pstart)) + if(o > overlap): + targetphase = phase + overlap = o + if targetphase in self.phases: + self.newAction(targetphase, name, -1, '', start, end, '') + return True + return False + def newAction(self, phase, name, pid, parent, start, end, drv): + # new device callback for a specific phase + self.html_device_id += 1 + devid = '%s%d' % (self.idstr, self.html_device_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 } + 'length': length, 'row': 0, 'id': devid, 'drv': drv } 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']) + list = self.dmesg[phase]['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'] + pdev = '' + pdevid = '' + list = self.dmesg[phase]['list'] + if devname in list: + pdev = list[devname]['par'] + if pdev in list: + return list[pdev]['id'] return pdev - def deviceChildrenIDs(self, devname, phase): + def deviceChildren(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) + list = self.dmesg[phase]['list'] + for child in list: + if(list[child]['par'] == devname): + devlist.append(child) + return devlist + def deviceDescendants(self, devname, phase): + children = self.deviceChildren(devname, phase) + family = children + for child in children: + family += self.deviceDescendants(child, phase) + return family + def deviceChildrenIDs(self, devname, phase): + devlist = self.deviceChildren(devname, phase) return self.deviceIDs(devlist, phase) - + def printDetails(self): + vprint(' test start: %f' % self.start) + for phase in self.phases: + dc = len(self.dmesg[phase]['list']) + vprint(' %16s: %f - %f (%d devices)' % (phase, \ + self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) + vprint(' test end: %f' % self.end) + def masterTopology(self, name, list, depth): + node = DeviceNode(name, depth) + for cname in list: + clist = self.deviceChildren(cname, 'resume') + cnode = self.masterTopology(cname, clist, depth+1) + node.children.append(cnode) + return node + def printTopology(self, node): + html = '' + if node.name: + info = '' + drv = '' + for phase in self.phases: + list = self.dmesg[phase]['list'] + if node.name in list: + s = list[node.name]['start'] + e = list[node.name]['end'] + if list[node.name]['drv']: + drv = ' {'+list[node.name]['drv']+'}' + info += ('
  • %s: %.3fms
    • ' % (phase, (e-s)*1000)) + html += '
  • '+node.name+drv+'' + if info: + html += '
      '+info+'
    ' + html += '
    • ' + if len(node.children) > 0: + html += '
      ' + for cnode in node.children: + html += self.printTopology(cnode) + html += '
    ' + return html + def rootDeviceList(self): + # list of devices graphed + real = [] + for phase in self.dmesg: + list = self.dmesg[phase]['list'] + for dev in list: + if list[dev]['pid'] >= 0 and dev not in real: + real.append(dev) + # list of top-most root devices + rootlist = [] + for phase in self.dmesg: + list = self.dmesg[phase]['list'] + for dev in list: + pdev = list[dev]['par'] + if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): + continue + if pdev and pdev not in real and pdev not in rootlist: + rootlist.append(pdev) + return rootlist + def deviceTopology(self): + rootlist = self.rootDeviceList() + master = self.masterTopology('', rootlist, 0) + return self.printTopology(master) + +# Class: TraceEvent +# Description: +# A container for trace event data found in the ftrace file +class TraceEvent: + ready = False + name = '' + time = 0.0 + color = '#FFFFFF' + length = 0.0 + action = '' + def __init__(self, a, n, c, t): + self.action = a + self.name = n + self.color = c + self.time = t + +# Class: FTraceLine +# Description: +# A container for a single line of ftrace data. There are six basic types: +# callgraph line: +# call: " dpm_run_callback() {" +# return: " }" +# leaf: " dpm_run_callback();" +# trace event: +# tracing_mark_write: SUSPEND START or RESUME COMPLETE +# suspend_resume: phase or custom exec block data +# device_pm_callback: device callback info class FTraceLine: time = 0.0 length = 0.0 @@ -257,20 +624,33 @@ class FTraceLine: freturn = False fevent = False depth = 0 - name = "" + name = '' + type = '' def __init__(self, t, m, d): self.time = float(t) - # check to see if this is a trace event - em = re.match(r"^ *\/\* *(?P.*) \*\/ *$", m) - if(em): - self.name = em.group("msg") + # is this a trace event + if(d == 'traceevent' or re.match('^ *\/\* *(?P.*) \*\/ *$', m)): + if(d == 'traceevent'): + # nop format trace event + msg = m + else: + # function_graph format trace event + em = re.match('^ *\/\* *(?P.*) \*\/ *$', m) + msg = em.group('msg') + + emm = re.match('^(?P.*?): (?P.*)', msg) + if(emm): + self.name = emm.group('msg') + self.type = emm.group('call') + else: + self.name = 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 *)(?P.*)$", m) + match = re.match('^(?P *)(?P.*)$', m) if(not match): return self.depth = self.getDepth(match.group('d')) @@ -280,7 +660,7 @@ class FTraceLine: self.freturn = True if(len(m) > 1): # includes comment with function name - match = re.match(r"^} *\/\* *(?P.*) *\*\/$", m) + match = re.match('^} *\/\* *(?P.*) *\*\/$', m) if(match): self.name = match.group('n') # function call @@ -288,13 +668,13 @@ class FTraceLine: self.fcall = True # function call with children if(m[-1] == '{'): - match = re.match(r"^(?P.*) *\(.*", m) + match = re.match('^(?P.*) *\(.*', 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.*) *\(.*", m) + match = re.match('^(?P.*) *\(.*', m) if(match): self.name = match.group('n') # something else (possibly a trace marker) @@ -302,7 +682,23 @@ class FTraceLine: self.name = m def getDepth(self, str): return len(str)/2 + def debugPrint(self, dev): + if(self.freturn and self.fcall): + print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ + self.depth, self.name, self.length*1000000)) + elif(self.freturn): + print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ + self.depth, self.name, self.length*1000000)) + else: + print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ + self.depth, self.name, self.length*1000000)) +# Class: FTraceCallGraph +# Description: +# A container for the ftrace callgraph of a single recursive function. +# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph +# Each instance is tied to a single device in a single phase, and is +# comprised of an ordered list of FTraceLine objects class FTraceCallGraph: start = -1.0 end = -1.0 @@ -327,24 +723,53 @@ class FTraceCallGraph: if(not self.invalid): self.setDepth(line) if(line.depth == 0 and line.freturn): + if(self.start < 0): + self.start = line.time 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 + if(len(self.list) > 0): + first = self.list[0] + self.list = [] + self.list.append(first) + self.invalid = True + if(not match): + return False + id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu')) + window = '(%f - %f)' % (self.start, line.time) + if(self.depth < 0): + print('Too much data for '+id+\ + ' (buffer overflow), ignoring this callback') + else: + print('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 slice(self, t0, tN): + minicg = FTraceCallGraph() + count = -1 + firstdepth = 0 + for l in self.list: + if(l.time < t0 or l.time > tN): + continue + if(count < 0): + if(not l.fcall or l.name == 'dev_driver_string'): + continue + firstdepth = l.depth + count = 0 + l.depth -= firstdepth + minicg.addLine(l, 0) + if((count == 0 and l.freturn and l.fcall) or + (count > 0 and l.depth <= 0)): + break + count += 1 + return minicg def sanityCheck(self): stack = dict() cnt = 0 @@ -353,7 +778,7 @@ class FTraceCallGraph: stack[l.depth] = l cnt += 1 elif(l.freturn and not l.fcall): - if(not stack[l.depth]): + if(l.depth not in stack): return False stack[l.depth].length = l.length stack[l.depth] = 0 @@ -363,40 +788,51 @@ class FTraceCallGraph: return True return False def debugPrint(self, filename): - if(filename == "stdout"): - print("[%f - %f]") % (self.start, self.end) + 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)) + 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)) + 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(" ") + 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)) + 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)) + 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.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \ + l.depth, l.name, l.length*1000000)) fp.close() +# Class: Timeline +# Description: +# A container for a suspend/resume html timeline. In older versions +# of the script there were multiple timelines, but in the latest +# there is only one. class Timeline: html = {} - scaleH = 0.0 # height of the timescale row as a percent of the timeline height + scaleH = 0.0 # height of the 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': "" + 'timeline': '', + 'legend': '', + 'scale': '' } def setRows(self, rows): self.maxrows = int(rows) @@ -407,104 +843,261 @@ class Timeline: r = 1.0 self.rowH = (100.0 - self.scaleH)/r -# -- global objects -- +# Class: TestRun +# Description: +# A container for a suspend/resume test run. This is necessary as +# there could be more than one, and they need to be separate. +class TestRun: + ftrace_line_fmt_fg = \ + '^ *(?P