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 = "" - rtcwake = False - def setOutputFile(self): - if((self.htmlfile == "") and (self.dmesgfile != "")): - m = re.match(r"(?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) - 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 + version = 3.0 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}, + 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('(?P.*)_dmesg\.txt$', self.dmesgfile) + if(m): + 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, 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: + 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