aboutsummaryrefslogtreecommitdiffstats
path: root/scripts/analyze_suspend.py
diff options
context:
space:
mode:
authorTodd E Brandt <todd.e.brandt@linux.intel.com>2014-08-08 12:11:59 -0400
committerRafael J. Wysocki <rafael.j.wysocki@intel.com>2014-08-08 20:47:58 -0400
commitb8432c6fc12bdf4a6921e1640d3ead23fcd04c10 (patch)
treed1aa177cf8a1ee8717d8fa1e9812b1e7537059ca /scripts/analyze_suspend.py
parent059802f961db9717412b6958111ca1cd1865726e (diff)
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 <todd.e.brandt@intel.com> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Diffstat (limited to 'scripts/analyze_suspend.py')
-rwxr-xr-xscripts/analyze_suspend.py3817
1 files 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 @@
36# CONFIG_FUNCTION_TRACER=y 36# CONFIG_FUNCTION_TRACER=y
37# CONFIG_FUNCTION_GRAPH_TRACER=y 37# CONFIG_FUNCTION_GRAPH_TRACER=y
38# 38#
39# For kernel versions older than 3.15:
39# The following additional kernel parameters are required: 40# The following additional kernel parameters are required:
40# (e.g. in file /etc/default/grub) 41# (e.g. in file /etc/default/grub)
41# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." 42# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
42# 43#
43 44
45# ----------------- LIBRARIES --------------------
46
44import sys 47import sys
45import time 48import time
46import os 49import os
47import string 50import string
48import re 51import re
49import array
50import platform 52import platform
51import datetime 53from datetime import datetime
52import struct 54import struct
53 55
54# -- classes -- 56# ----------------- CLASSES --------------------
55 57
58# Class: SystemValues
59# Description:
60# A global, single-instance container used to
61# store system values and test parameters
56class SystemValues: 62class SystemValues:
57 testdir = "." 63 version = 3.0
58 tpath = "/sys/kernel/debug/tracing/" 64 verbose = False
59 mempath = "/dev/mem" 65 testdir = '.'
60 powerfile = "/sys/power/state" 66 tpath = '/sys/kernel/debug/tracing/'
61 suspendmode = "mem" 67 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
62 prefix = "test" 68 epath = '/sys/kernel/debug/tracing/events/power/'
63 teststamp = "" 69 traceevents = [
64 dmesgfile = "" 70 'suspend_resume',
65 ftracefile = "" 71 'device_pm_callback_end',
66 htmlfile = "" 72 'device_pm_callback_start'
73 ]
74 modename = {
75 'freeze': 'Suspend-To-Idle (S0)',
76 'standby': 'Power-On Suspend (S1)',
77 'mem': 'Suspend-to-RAM (S3)',
78 'disk': 'Suspend-to-disk (S4)'
79 }
80 mempath = '/dev/mem'
81 powerfile = '/sys/power/state'
82 suspendmode = 'mem'
83 hostname = 'localhost'
84 prefix = 'test'
85 teststamp = ''
86 dmesgfile = ''
87 ftracefile = ''
88 htmlfile = ''
67 rtcwake = False 89 rtcwake = False
90 rtcwaketime = 10
91 rtcpath = ''
92 android = False
93 adb = 'adb'
94 devicefilter = []
95 stamp = 0
96 execcount = 1
97 x2delay = 0
98 usecallgraph = False
99 usetraceevents = False
100 usetraceeventsonly = False
101 notestrun = False
102 altdevname = dict()
103 postresumetime = 0
104 tracertypefmt = '# tracer: (?P<t>.*)'
105 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
106 postresumefmt = '# post resume time (?P<t>[0-9]*)$'
107 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
108 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
109 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
110 def __init__(self):
111 self.hostname = platform.node()
112 if(self.hostname == ''):
113 self.hostname = 'localhost'
114 rtc = "rtc0"
115 if os.path.exists('/dev/rtc'):
116 rtc = os.readlink('/dev/rtc')
117 rtc = '/sys/class/rtc/'+rtc
118 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
119 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
120 self.rtcpath = rtc
68 def setOutputFile(self): 121 def setOutputFile(self):
69 if((self.htmlfile == "") and (self.dmesgfile != "")): 122 if((self.htmlfile == '') and (self.dmesgfile != '')):
70 m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile) 123 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
71 if(m): 124 if(m):
72 self.htmlfile = m.group("name")+".html" 125 self.htmlfile = m.group('name')+'.html'
73 if((self.htmlfile == "") and (self.ftracefile != "")): 126 if((self.htmlfile == '') and (self.ftracefile != '')):
74 m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile) 127 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
75 if(m): 128 if(m):
76 self.htmlfile = m.group("name")+".html" 129 self.htmlfile = m.group('name')+'.html'
77 if(self.htmlfile == ""): 130 if(self.htmlfile == ''):
78 self.htmlfile = "output.html" 131 self.htmlfile = 'output.html'
79 def initTestOutput(self): 132 def initTestOutput(self, subdir):
80 hostname = platform.node() 133 if(not self.android):
81 if(hostname != ""): 134 self.prefix = self.hostname
82 self.prefix = hostname 135 v = open('/proc/version', 'r').read().strip()
83 v = os.popen("cat /proc/version").read().strip() 136 kver = string.split(v)[2]
84 kver = string.split(v)[2] 137 else:
85 self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip() 138 self.prefix = 'android'
86 self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver 139 v = os.popen(self.adb+' shell cat /proc/version').read().strip()
87 self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt" 140 kver = string.split(v)[2]
88 self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt" 141 testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S')
89 self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html" 142 if(subdir != "."):
143 self.testdir = subdir+"/"+testtime
144 else:
145 self.testdir = testtime
146 self.teststamp = \
147 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
148 self.dmesgfile = \
149 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
150 self.ftracefile = \
151 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
152 self.htmlfile = \
153 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
90 os.mkdir(self.testdir) 154 os.mkdir(self.testdir)
155 def setDeviceFilter(self, devnames):
156 self.devicefilter = string.split(devnames)
157 def rtcWakeAlarm(self):
158 os.system('echo 0 > '+self.rtcpath+'/wakealarm')
159 outD = open(self.rtcpath+'/date', 'r').read().strip()
160 outT = open(self.rtcpath+'/time', 'r').read().strip()
161 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
162 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
163 if(mD and mT):
164 # get the current time from hardware
165 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
166 dt = datetime(\
167 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
168 int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
169 nowtime = int(dt.strftime('%s')) + utcoffset
170 else:
171 # if hardware time fails, use the software time
172 nowtime = int(datetime.now().strftime('%s'))
173 alarm = nowtime + self.rtcwaketime
174 os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
91 175
176sysvals = SystemValues()
177
178# Class: DeviceNode
179# Description:
180# A container used to create a device hierachy, with a single root node
181# and a tree of child nodes. Used by Data.deviceTopology()
182class DeviceNode:
183 name = ''
184 children = 0
185 depth = 0
186 def __init__(self, nodename, nodedepth):
187 self.name = nodename
188 self.children = []
189 self.depth = nodedepth
190
191# Class: Data
192# Description:
193# The primary container for suspend/resume test data. There is one for
194# each test run. The data is organized into a cronological hierarchy:
195# Data.dmesg {
196# root structure, started as dmesg & ftrace, but now only ftrace
197# contents: times for suspend start/end, resume start/end, fwdata
198# phases {
199# 10 sequential, non-overlapping phases of S/R
200# contents: times for phase start/end, order/color data for html
201# devlist {
202# device callback or action list for this phase
203# device {
204# a single device callback or generic action
205# contents: start/stop times, pid/cpu/driver info
206# parents/children, html id for timeline/callgraph
207# optionally includes an ftrace callgraph
208# optionally includes intradev trace events
209# }
210# }
211# }
212# }
213#
92class Data: 214class Data:
93 altdevname = dict() 215 dmesg = {} # root data structure
94 usedmesg = False 216 phases = [] # ordered list of phases
95 useftrace = False 217 start = 0.0 # test start
96 notestrun = False 218 end = 0.0 # test end
97 verbose = False 219 tSuspended = 0.0 # low-level suspend start
98 phases = [] 220 tResumed = 0.0 # low-level resume start
99 dmesg = {} # root data structure 221 tLow = 0.0 # time spent in low-level suspend (standby/freeze)
100 start = 0.0 222 fwValid = False # is firmware data available
101 end = 0.0 223 fwSuspend = 0 # time spent in firmware suspend
102 stamp = {'time': "", 'host': "", 'mode': ""} 224 fwResume = 0 # time spent in firmware resume
103 id = 0 225 dmesgtext = [] # dmesg text file in memory
104 tSuspended = 0.0 226 testnumber = 0
105 fwValid = False 227 idstr = ''
106 fwSuspend = 0 228 html_device_id = 0
107 fwResume = 0 229 stamp = 0
108 def initialize(self): 230 outfile = ''
109 self.dmesg = { # dmesg log data 231 def __init__(self, num):
110 'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0, 232 idchar = 'abcdefghijklmnopqrstuvwxyz'
111 'row': 0, 'color': "#CCFFCC", 'order': 0}, 233 self.testnumber = num
112 'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0, 234 self.idstr = idchar[num]
113 'row': 0, 'color': "green", 'order': 1}, 235 self.dmesgtext = []
236 self.phases = []
237 self.dmesg = { # fixed list of 10 phases
238 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
239 'row': 0, 'color': '#CCFFCC', 'order': 0},
240 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
241 'row': 0, 'color': '#88FF88', 'order': 1},
242 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
243 'row': 0, 'color': '#00AA00', 'order': 2},
114 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 244 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
115 'row': 0, 'color': "#00FFFF", 'order': 2}, 245 'row': 0, 'color': '#008888', 'order': 3},
116 'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0, 246 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
117 'row': 0, 'color': "blue", 'order': 3}, 247 'row': 0, 'color': '#0000FF', 'order': 4},
118 'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0, 248 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
119 'row': 0, 'color': "red", 'order': 4}, 249 'row': 0, 'color': '#FF0000', 'order': 5},
120 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 250 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
121 'row': 0, 'color': "orange", 'order': 5}, 251 'row': 0, 'color': '#FF9900', 'order': 6},
122 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0, 252 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
123 'row': 0, 'color': "yellow", 'order': 6}, 253 'row': 0, 'color': '#FFCC00', 'order': 7},
124 'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0, 254 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
125 'row': 0, 'color': "#FFFFCC", 'order': 7} 255 'row': 0, 'color': '#FFFF88', 'order': 8},
256 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
257 'row': 0, 'color': '#FFFFCC', 'order': 9}
126 } 258 }
127 self.phases = self.sortedPhases() 259 self.phases = self.sortedPhases()
128 def normalizeTime(self): 260 def getStart(self):
129 tSus = tRes = self.tSuspended 261 return self.dmesg[self.phases[0]]['start']
130 if self.fwValid: 262 def setStart(self, time):
131 tSus -= -self.fwSuspend / 1000000000.0 263 self.start = time
132 tRes -= self.fwResume / 1000000000.0 264 self.dmesg[self.phases[0]]['start'] = time
133 self.tSuspended = 0.0 265 def getEnd(self):
134 self.start -= tSus 266 return self.dmesg[self.phases[-1]]['end']
135 self.end -= tRes 267 def setEnd(self, time):
268 self.end = time
269 self.dmesg[self.phases[-1]]['end'] = time
270 def isTraceEventOutsideDeviceCalls(self, pid, time):
271 for phase in self.phases:
272 list = self.dmesg[phase]['list']
273 for dev in list:
274 d = list[dev]
275 if(d['pid'] == pid and time >= d['start'] and
276 time <= d['end']):
277 return False
278 return True
279 def addIntraDevTraceEvent(self, action, name, pid, time):
280 if(action == 'mutex_lock_try'):
281 color = 'red'
282 elif(action == 'mutex_lock_pass'):
283 color = 'green'
284 elif(action == 'mutex_unlock'):
285 color = 'blue'
286 else:
287 # create separate colors based on the name
288 v1 = len(name)*10 % 256
289 v2 = string.count(name, 'e')*100 % 256
290 v3 = ord(name[0])*20 % 256
291 color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3)
292 for phase in self.phases:
293 list = self.dmesg[phase]['list']
294 for dev in list:
295 d = list[dev]
296 if(d['pid'] == pid and time >= d['start'] and
297 time <= d['end']):
298 e = TraceEvent(action, name, color, time)
299 if('traceevents' not in d):
300 d['traceevents'] = []
301 d['traceevents'].append(e)
302 return d
303 break
304 return 0
305 def capIntraDevTraceEvent(self, action, name, pid, time):
306 for phase in self.phases:
307 list = self.dmesg[phase]['list']
308 for dev in list:
309 d = list[dev]
310 if(d['pid'] == pid and time >= d['start'] and
311 time <= d['end']):
312 if('traceevents' not in d):
313 return
314 for e in d['traceevents']:
315 if(e.action == action and
316 e.name == name and not e.ready):
317 e.length = time - e.time
318 e.ready = True
319 break
320 return
321 def trimTimeVal(self, t, t0, dT, left):
322 if left:
323 if(t > t0):
324 if(t - dT < t0):
325 return t0
326 return t - dT
327 else:
328 return t
329 else:
330 if(t < t0 + dT):
331 if(t > t0):
332 return t0 + dT
333 return t + dT
334 else:
335 return t
336 def trimTime(self, t0, dT, left):
337 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
338 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
339 self.start = self.trimTimeVal(self.start, t0, dT, left)
340 self.end = self.trimTimeVal(self.end, t0, dT, left)
136 for phase in self.phases: 341 for phase in self.phases:
137 zero = tRes
138 if "suspend" in phase:
139 zero = tSus
140 p = self.dmesg[phase] 342 p = self.dmesg[phase]
141 p['start'] -= zero 343 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
142 p['end'] -= zero 344 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
143 list = p['list'] 345 list = p['list']
144 for name in list: 346 for name in list:
145 d = list[name] 347 d = list[name]
146 d['start'] -= zero 348 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
147 d['end'] -= zero 349 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
148 if('ftrace' in d): 350 if('ftrace' in d):
149 cg = d['ftrace'] 351 cg = d['ftrace']
150 cg.start -= zero 352 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
151 cg.end -= zero 353 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
152 for line in cg.list: 354 for line in cg.list:
153 line.time -= zero 355 line.time = self.trimTimeVal(line.time, t0, dT, left)
154 if self.fwValid: 356 if('traceevents' in d):
155 fws = -self.fwSuspend / 1000000000.0 357 for e in d['traceevents']:
156 fwr = self.fwResume / 1000000000.0 358 e.time = self.trimTimeVal(e.time, t0, dT, left)
157 list = dict() 359 def normalizeTime(self, tZero):
158 self.id += 1 360 # first trim out any standby or freeze clock time
159 devid = "dc%d" % self.id 361 if(self.tSuspended != self.tResumed):
160 list["firmware-suspend"] = \ 362 if(self.tResumed > tZero):
161 {'start': fws, 'end': 0, 'pid': 0, 'par': "", 363 self.trimTime(self.tSuspended, \
162 'length': -fws, 'row': 0, 'id': devid }; 364 self.tResumed-self.tSuspended, True)
163 self.id += 1 365 else:
164 devid = "dc%d" % self.id 366 self.trimTime(self.tSuspended, \
165 list["firmware-resume"] = \ 367 self.tResumed-self.tSuspended, False)
166 {'start': 0, 'end': fwr, 'pid': 0, 'par': "", 368 # shift the timeline so that tZero is the new 0
167 'length': fwr, 'row': 0, 'id': devid }; 369 self.tSuspended -= tZero
168 self.dmesg['BIOS'] = \ 370 self.tResumed -= tZero
169 {'list': list, 'start': fws, 'end': fwr, 371 self.start -= tZero
170 'row': 0, 'color': "purple", 'order': 4} 372 self.end -= tZero
171 self.dmesg['resume_cpu']['order'] += 1 373 for phase in self.phases:
172 self.dmesg['resume_noirq']['order'] += 1 374 p = self.dmesg[phase]
173 self.dmesg['resume_early']['order'] += 1 375 p['start'] -= tZero
174 self.dmesg['resume_general']['order'] += 1 376 p['end'] -= tZero
175 self.phases = self.sortedPhases() 377 list = p['list']
176 def vprint(self, msg): 378 for name in list:
177 if(self.verbose): 379 d = list[name]
178 print(msg) 380 d['start'] -= tZero
381 d['end'] -= tZero
382 if('ftrace' in d):
383 cg = d['ftrace']
384 cg.start -= tZero
385 cg.end -= tZero
386 for line in cg.list:
387 line.time -= tZero
388 if('traceevents' in d):
389 for e in d['traceevents']:
390 e.time -= tZero
391 def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
392 for phase in self.phases:
393 self.dmesg[phase]['order'] += 1
394 self.html_device_id += 1
395 devid = '%s%d' % (self.idstr, self.html_device_id)
396 list = dict()
397 list[devname] = \
398 {'start': start, 'end': end, 'pid': 0, 'par': '',
399 'length': (end-start), 'row': 0, 'id': devid, 'drv': '' };
400 self.dmesg[phasename] = \
401 {'list': list, 'start': start, 'end': end,
402 'row': 0, 'color': color, 'order': 0}
403 self.phases = self.sortedPhases()
404 def newPhase(self, phasename, start, end, color, order):
405 if(order < 0):
406 order = len(self.phases)
407 for phase in self.phases[order:]:
408 self.dmesg[phase]['order'] += 1
409 if(order > 0):
410 p = self.phases[order-1]
411 self.dmesg[p]['end'] = start
412 if(order < len(self.phases)):
413 p = self.phases[order]
414 self.dmesg[p]['start'] = end
415 list = dict()
416 self.dmesg[phasename] = \
417 {'list': list, 'start': start, 'end': end,
418 'row': 0, 'color': color, 'order': order}
419 self.phases = self.sortedPhases()
420 def setPhase(self, phase, ktime, isbegin):
421 if(isbegin):
422 self.dmesg[phase]['start'] = ktime
423 else:
424 self.dmesg[phase]['end'] = ktime
179 def dmesgSortVal(self, phase): 425 def dmesgSortVal(self, phase):
180 return self.dmesg[phase]['order'] 426 return self.dmesg[phase]['order']
181 def sortedPhases(self): 427 def sortedPhases(self):
@@ -197,59 +443,180 @@ class Data:
197 dev = phaselist[devname] 443 dev = phaselist[devname]
198 if(dev['end'] < 0): 444 if(dev['end'] < 0):
199 dev['end'] = end 445 dev['end'] = end
200 self.vprint("%s (%s): callback didn't return" % (devname, phase)) 446 vprint('%s (%s): callback didnt return' % (devname, phase))
447 def deviceFilter(self, devicefilter):
448 # remove all by the relatives of the filter devnames
449 filter = []
450 for phase in self.phases:
451 list = self.dmesg[phase]['list']
452 for name in devicefilter:
453 dev = name
454 while(dev in list):
455 if(dev not in filter):
456 filter.append(dev)
457 dev = list[dev]['par']
458 children = self.deviceDescendants(name, phase)
459 for dev in children:
460 if(dev not in filter):
461 filter.append(dev)
462 for phase in self.phases:
463 list = self.dmesg[phase]['list']
464 rmlist = []
465 for name in list:
466 pid = list[name]['pid']
467 if(name not in filter and pid >= 0):
468 rmlist.append(name)
469 for name in rmlist:
470 del list[name]
201 def fixupInitcallsThatDidntReturn(self): 471 def fixupInitcallsThatDidntReturn(self):
202 # if any calls never returned, clip them at system resume end 472 # if any calls never returned, clip them at system resume end
203 for phase in self.phases: 473 for phase in self.phases:
204 self.fixupInitcalls(phase, self.dmesg['resume_general']['end']) 474 self.fixupInitcalls(phase, self.getEnd())
205 if(phase == "resume_general"): 475 def newActionGlobal(self, name, start, end):
206 break 476 # which phase is this device callback or action "in"
207 def newAction(self, phase, name, pid, parent, start, end): 477 targetphase = "none"
208 self.id += 1 478 overlap = 0.0
209 devid = "dc%d" % self.id 479 for phase in self.phases:
480 pstart = self.dmesg[phase]['start']
481 pend = self.dmesg[phase]['end']
482 o = max(0, min(end, pend) - max(start, pstart))
483 if(o > overlap):
484 targetphase = phase
485 overlap = o
486 if targetphase in self.phases:
487 self.newAction(targetphase, name, -1, '', start, end, '')
488 return True
489 return False
490 def newAction(self, phase, name, pid, parent, start, end, drv):
491 # new device callback for a specific phase
492 self.html_device_id += 1
493 devid = '%s%d' % (self.idstr, self.html_device_id)
210 list = self.dmesg[phase]['list'] 494 list = self.dmesg[phase]['list']
211 length = -1.0 495 length = -1.0
212 if(start >= 0 and end >= 0): 496 if(start >= 0 and end >= 0):
213 length = end - start 497 length = end - start
214 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, 498 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
215 'length': length, 'row': 0, 'id': devid } 499 'length': length, 'row': 0, 'id': devid, 'drv': drv }
216 def deviceIDs(self, devlist, phase): 500 def deviceIDs(self, devlist, phase):
217 idlist = [] 501 idlist = []
218 for p in self.phases: 502 list = self.dmesg[phase]['list']
219 if(p[0] != phase[0]): 503 for devname in list:
220 continue 504 if devname in devlist:
221 list = data.dmesg[p]['list'] 505 idlist.append(list[devname]['id'])
222 for devname in list:
223 if devname in devlist:
224 idlist.append(list[devname]['id'])
225 return idlist 506 return idlist
226 def deviceParentID(self, devname, phase): 507 def deviceParentID(self, devname, phase):
227 pdev = "" 508 pdev = ''
228 pdevid = "" 509 pdevid = ''
229 for p in self.phases: 510 list = self.dmesg[phase]['list']
230 if(p[0] != phase[0]): 511 if devname in list:
231 continue 512 pdev = list[devname]['par']
232 list = data.dmesg[p]['list'] 513 if pdev in list:
233 if devname in list: 514 return list[pdev]['id']
234 pdev = list[devname]['par']
235 for p in self.phases:
236 if(p[0] != phase[0]):
237 continue
238 list = data.dmesg[p]['list']
239 if pdev in list:
240 return list[pdev]['id']
241 return pdev 515 return pdev
242 def deviceChildrenIDs(self, devname, phase): 516 def deviceChildren(self, devname, phase):
243 devlist = [] 517 devlist = []
244 for p in self.phases: 518 list = self.dmesg[phase]['list']
245 if(p[0] != phase[0]): 519 for child in list:
246 continue 520 if(list[child]['par'] == devname):
247 list = data.dmesg[p]['list'] 521 devlist.append(child)
248 for child in list: 522 return devlist
249 if(list[child]['par'] == devname): 523 def deviceDescendants(self, devname, phase):
250 devlist.append(child) 524 children = self.deviceChildren(devname, phase)
525 family = children
526 for child in children:
527 family += self.deviceDescendants(child, phase)
528 return family
529 def deviceChildrenIDs(self, devname, phase):
530 devlist = self.deviceChildren(devname, phase)
251 return self.deviceIDs(devlist, phase) 531 return self.deviceIDs(devlist, phase)
252 532 def printDetails(self):
533 vprint(' test start: %f' % self.start)
534 for phase in self.phases:
535 dc = len(self.dmesg[phase]['list'])
536 vprint(' %16s: %f - %f (%d devices)' % (phase, \
537 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
538 vprint(' test end: %f' % self.end)
539 def masterTopology(self, name, list, depth):
540 node = DeviceNode(name, depth)
541 for cname in list:
542 clist = self.deviceChildren(cname, 'resume')
543 cnode = self.masterTopology(cname, clist, depth+1)
544 node.children.append(cnode)
545 return node
546 def printTopology(self, node):
547 html = ''
548 if node.name:
549 info = ''
550 drv = ''
551 for phase in self.phases:
552 list = self.dmesg[phase]['list']
553 if node.name in list:
554 s = list[node.name]['start']
555 e = list[node.name]['end']
556 if list[node.name]['drv']:
557 drv = ' {'+list[node.name]['drv']+'}'
558 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
559 html += '<li><b>'+node.name+drv+'</b>'
560 if info:
561 html += '<ul>'+info+'</ul>'
562 html += '</li>'
563 if len(node.children) > 0:
564 html += '<ul>'
565 for cnode in node.children:
566 html += self.printTopology(cnode)
567 html += '</ul>'
568 return html
569 def rootDeviceList(self):
570 # list of devices graphed
571 real = []
572 for phase in self.dmesg:
573 list = self.dmesg[phase]['list']
574 for dev in list:
575 if list[dev]['pid'] >= 0 and dev not in real:
576 real.append(dev)
577 # list of top-most root devices
578 rootlist = []
579 for phase in self.dmesg:
580 list = self.dmesg[phase]['list']
581 for dev in list:
582 pdev = list[dev]['par']
583 if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
584 continue
585 if pdev and pdev not in real and pdev not in rootlist:
586 rootlist.append(pdev)
587 return rootlist
588 def deviceTopology(self):
589 rootlist = self.rootDeviceList()
590 master = self.masterTopology('', rootlist, 0)
591 return self.printTopology(master)
592
593# Class: TraceEvent
594# Description:
595# A container for trace event data found in the ftrace file
596class TraceEvent:
597 ready = False
598 name = ''
599 time = 0.0
600 color = '#FFFFFF'
601 length = 0.0
602 action = ''
603 def __init__(self, a, n, c, t):
604 self.action = a
605 self.name = n
606 self.color = c
607 self.time = t
608
609# Class: FTraceLine
610# Description:
611# A container for a single line of ftrace data. There are six basic types:
612# callgraph line:
613# call: " dpm_run_callback() {"
614# return: " }"
615# leaf: " dpm_run_callback();"
616# trace event:
617# tracing_mark_write: SUSPEND START or RESUME COMPLETE
618# suspend_resume: phase or custom exec block data
619# device_pm_callback: device callback info
253class FTraceLine: 620class FTraceLine:
254 time = 0.0 621 time = 0.0
255 length = 0.0 622 length = 0.0
@@ -257,20 +624,33 @@ class FTraceLine:
257 freturn = False 624 freturn = False
258 fevent = False 625 fevent = False
259 depth = 0 626 depth = 0
260 name = "" 627 name = ''
628 type = ''
261 def __init__(self, t, m, d): 629 def __init__(self, t, m, d):
262 self.time = float(t) 630 self.time = float(t)
263 # check to see if this is a trace event 631 # is this a trace event
264 em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m) 632 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
265 if(em): 633 if(d == 'traceevent'):
266 self.name = em.group("msg") 634 # nop format trace event
635 msg = m
636 else:
637 # function_graph format trace event
638 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
639 msg = em.group('msg')
640
641 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
642 if(emm):
643 self.name = emm.group('msg')
644 self.type = emm.group('call')
645 else:
646 self.name = msg
267 self.fevent = True 647 self.fevent = True
268 return 648 return
269 # convert the duration to seconds 649 # convert the duration to seconds
270 if(d): 650 if(d):
271 self.length = float(d)/1000000 651 self.length = float(d)/1000000
272 # the indentation determines the depth 652 # the indentation determines the depth
273 match = re.match(r"^(?P<d> *)(?P<o>.*)$", m) 653 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
274 if(not match): 654 if(not match):
275 return 655 return
276 self.depth = self.getDepth(match.group('d')) 656 self.depth = self.getDepth(match.group('d'))
@@ -280,7 +660,7 @@ class FTraceLine:
280 self.freturn = True 660 self.freturn = True
281 if(len(m) > 1): 661 if(len(m) > 1):
282 # includes comment with function name 662 # includes comment with function name
283 match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m) 663 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
284 if(match): 664 if(match):
285 self.name = match.group('n') 665 self.name = match.group('n')
286 # function call 666 # function call
@@ -288,13 +668,13 @@ class FTraceLine:
288 self.fcall = True 668 self.fcall = True
289 # function call with children 669 # function call with children
290 if(m[-1] == '{'): 670 if(m[-1] == '{'):
291 match = re.match(r"^(?P<n>.*) *\(.*", m) 671 match = re.match('^(?P<n>.*) *\(.*', m)
292 if(match): 672 if(match):
293 self.name = match.group('n') 673 self.name = match.group('n')
294 # function call with no children (leaf) 674 # function call with no children (leaf)
295 elif(m[-1] == ';'): 675 elif(m[-1] == ';'):
296 self.freturn = True 676 self.freturn = True
297 match = re.match(r"^(?P<n>.*) *\(.*", m) 677 match = re.match('^(?P<n>.*) *\(.*', m)
298 if(match): 678 if(match):
299 self.name = match.group('n') 679 self.name = match.group('n')
300 # something else (possibly a trace marker) 680 # something else (possibly a trace marker)
@@ -302,7 +682,23 @@ class FTraceLine:
302 self.name = m 682 self.name = m
303 def getDepth(self, str): 683 def getDepth(self, str):
304 return len(str)/2 684 return len(str)/2
685 def debugPrint(self, dev):
686 if(self.freturn and self.fcall):
687 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
688 self.depth, self.name, self.length*1000000))
689 elif(self.freturn):
690 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
691 self.depth, self.name, self.length*1000000))
692 else:
693 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
694 self.depth, self.name, self.length*1000000))
305 695
696# Class: FTraceCallGraph
697# Description:
698# A container for the ftrace callgraph of a single recursive function.
699# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
700# Each instance is tied to a single device in a single phase, and is
701# comprised of an ordered list of FTraceLine objects
306class FTraceCallGraph: 702class FTraceCallGraph:
307 start = -1.0 703 start = -1.0
308 end = -1.0 704 end = -1.0
@@ -327,24 +723,53 @@ class FTraceCallGraph:
327 if(not self.invalid): 723 if(not self.invalid):
328 self.setDepth(line) 724 self.setDepth(line)
329 if(line.depth == 0 and line.freturn): 725 if(line.depth == 0 and line.freturn):
726 if(self.start < 0):
727 self.start = line.time
330 self.end = line.time 728 self.end = line.time
331 self.list.append(line) 729 self.list.append(line)
332 return True 730 return True
333 if(self.invalid): 731 if(self.invalid):
334 return False 732 return False
335 if(len(self.list) >= 1000000 or self.depth < 0): 733 if(len(self.list) >= 1000000 or self.depth < 0):
336 first = self.list[0] 734 if(len(self.list) > 0):
337 self.list = [] 735 first = self.list[0]
338 self.list.append(first) 736 self.list = []
339 self.invalid = True 737 self.list.append(first)
340 id = "task %s cpu %s" % (match.group("pid"), match.group("cpu")) 738 self.invalid = True
341 window = "(%f - %f)" % (self.start, line.time) 739 if(not match):
342 data.vprint("Too much data for "+id+" "+window+", ignoring this callback") 740 return False
343 return False 741 id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
742 window = '(%f - %f)' % (self.start, line.time)
743 if(self.depth < 0):
744 print('Too much data for '+id+\
745 ' (buffer overflow), ignoring this callback')
746 else:
747 print('Too much data for '+id+\
748 ' '+window+', ignoring this callback')
749 return False
344 self.list.append(line) 750 self.list.append(line)
345 if(self.start < 0): 751 if(self.start < 0):
346 self.start = line.time 752 self.start = line.time
347 return False 753 return False
754 def slice(self, t0, tN):
755 minicg = FTraceCallGraph()
756 count = -1
757 firstdepth = 0
758 for l in self.list:
759 if(l.time < t0 or l.time > tN):
760 continue
761 if(count < 0):
762 if(not l.fcall or l.name == 'dev_driver_string'):
763 continue
764 firstdepth = l.depth
765 count = 0
766 l.depth -= firstdepth
767 minicg.addLine(l, 0)
768 if((count == 0 and l.freturn and l.fcall) or
769 (count > 0 and l.depth <= 0)):
770 break
771 count += 1
772 return minicg
348 def sanityCheck(self): 773 def sanityCheck(self):
349 stack = dict() 774 stack = dict()
350 cnt = 0 775 cnt = 0
@@ -353,7 +778,7 @@ class FTraceCallGraph:
353 stack[l.depth] = l 778 stack[l.depth] = l
354 cnt += 1 779 cnt += 1
355 elif(l.freturn and not l.fcall): 780 elif(l.freturn and not l.fcall):
356 if(not stack[l.depth]): 781 if(l.depth not in stack):
357 return False 782 return False
358 stack[l.depth].length = l.length 783 stack[l.depth].length = l.length
359 stack[l.depth] = 0 784 stack[l.depth] = 0
@@ -363,40 +788,51 @@ class FTraceCallGraph:
363 return True 788 return True
364 return False 789 return False
365 def debugPrint(self, filename): 790 def debugPrint(self, filename):
366 if(filename == "stdout"): 791 if(filename == 'stdout'):
367 print("[%f - %f]") % (self.start, self.end) 792 print('[%f - %f]') % (self.start, self.end)
368 for l in self.list: 793 for l in self.list:
369 if(l.freturn and l.fcall): 794 if(l.freturn and l.fcall):
370 print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) 795 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
796 l.depth, l.name, l.length*1000000))
371 elif(l.freturn): 797 elif(l.freturn):
372 print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) 798 print('%f (%02d): %s} (%.3f us)' % (l.time, \
799 l.depth, l.name, l.length*1000000))
373 else: 800 else:
374 print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) 801 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
375 print(" ") 802 l.depth, l.name, l.length*1000000))
803 print(' ')
376 else: 804 else:
377 fp = open(filename, 'w') 805 fp = open(filename, 'w')
378 print(filename) 806 print(filename)
379 for l in self.list: 807 for l in self.list:
380 if(l.freturn and l.fcall): 808 if(l.freturn and l.fcall):
381 fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) 809 fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \
810 l.depth, l.name, l.length*1000000))
382 elif(l.freturn): 811 elif(l.freturn):
383 fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) 812 fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \
813 l.depth, l.name, l.length*1000000))
384 else: 814 else:
385 fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) 815 fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \
816 l.depth, l.name, l.length*1000000))
386 fp.close() 817 fp.close()
387 818
819# Class: Timeline
820# Description:
821# A container for a suspend/resume html timeline. In older versions
822# of the script there were multiple timelines, but in the latest
823# there is only one.
388class Timeline: 824class Timeline:
389 html = {} 825 html = {}
390 scaleH = 0.0 # height of the timescale row as a percent of the timeline height 826 scaleH = 0.0 # height of the row as a percent of the timeline height
391 rowH = 0.0 # height of each row in percent of the timeline height 827 rowH = 0.0 # height of each row in percent of the timeline height
392 row_height_pixels = 30 828 row_height_pixels = 30
393 maxrows = 0 829 maxrows = 0
394 height = 0 830 height = 0
395 def __init__(self): 831 def __init__(self):
396 self.html = { 832 self.html = {
397 'timeline': "", 833 'timeline': '',
398 'legend': "", 834 'legend': '',
399 'scale': "" 835 'scale': ''
400 } 836 }
401 def setRows(self, rows): 837 def setRows(self, rows):
402 self.maxrows = int(rows) 838 self.maxrows = int(rows)
@@ -407,104 +843,261 @@ class Timeline:
407 r = 1.0 843 r = 1.0
408 self.rowH = (100.0 - self.scaleH)/r 844 self.rowH = (100.0 - self.scaleH)/r
409 845
410# -- global objects -- 846# Class: TestRun
847# Description:
848# A container for a suspend/resume test run. This is necessary as
849# there could be more than one, and they need to be separate.
850class TestRun:
851 ftrace_line_fmt_fg = \
852 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
853 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
854 '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
855 ftrace_line_fmt_nop = \
856 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
857 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
858 '(?P<msg>.*)'
859 ftrace_line_fmt = ftrace_line_fmt_nop
860 cgformat = False
861 ftemp = dict()
862 ttemp = dict()
863 inthepipe = False
864 tracertype = ''
865 data = 0
866 def __init__(self, dataobj):
867 self.data = dataobj
868 self.ftemp = dict()
869 self.ttemp = dict()
870 def isReady(self):
871 if(tracertype == '' or not data):
872 return False
873 return True
874 def setTracerType(self, tracer):
875 self.tracertype = tracer
876 if(tracer == 'function_graph'):
877 self.cgformat = True
878 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
879 elif(tracer == 'nop'):
880 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
881 else:
882 doError('Invalid tracer format: [%s]' % tracer, False)
411 883
412sysvals = SystemValues() 884# ----------------- FUNCTIONS --------------------
413data = Data()
414 885
415# -- functions -- 886# Function: vprint
887# Description:
888# verbose print (prints only with -verbose option)
889# Arguments:
890# msg: the debug/log message to print
891def vprint(msg):
892 global sysvals
893 if(sysvals.verbose):
894 print(msg)
416 895
417# Function: initFtrace 896# Function: initFtrace
418# Description: 897# Description:
419# Configure ftrace to capture a function trace during suspend/resume 898# Configure ftrace to use trace events and/or a callgraph
420def initFtrace(): 899def initFtrace():
421 global sysvals 900 global sysvals
422 901
423 print("INITIALIZING FTRACE...") 902 tp = sysvals.tpath
424 # turn trace off 903 cf = 'dpm_run_callback'
425 os.system("echo 0 > "+sysvals.tpath+"tracing_on") 904 if(sysvals.usetraceeventsonly):
426 # set the trace clock to global 905 cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback'
427 os.system("echo global > "+sysvals.tpath+"trace_clock") 906 if(sysvals.usecallgraph or sysvals.usetraceevents):
428 # set trace buffer to a huge value 907 print('INITIALIZING FTRACE...')
429 os.system("echo nop > "+sysvals.tpath+"current_tracer") 908 # turn trace off
430 os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb") 909 os.system('echo 0 > '+tp+'tracing_on')
431 # clear the trace buffer 910 # set the trace clock to global
432 os.system("echo \"\" > "+sysvals.tpath+"trace") 911 os.system('echo global > '+tp+'trace_clock')
433 # set trace type 912 # set trace buffer to a huge value
434 os.system("echo function_graph > "+sysvals.tpath+"current_tracer") 913 os.system('echo nop > '+tp+'current_tracer')
435 os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter") 914 os.system('echo 100000 > '+tp+'buffer_size_kb')
436 # set trace format options 915 # initialize the callgraph trace, unless this is an x2 run
437 os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options") 916 if(sysvals.usecallgraph and sysvals.execcount == 1):
438 os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options") 917 # set trace type
439 # focus only on device suspend and resume 918 os.system('echo function_graph > '+tp+'current_tracer')
440 os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function") 919 os.system('echo "" > '+tp+'set_ftrace_filter')
920 # set trace format options
921 os.system('echo funcgraph-abstime > '+tp+'trace_options')
922 os.system('echo funcgraph-proc > '+tp+'trace_options')
923 # focus only on device suspend and resume
924 os.system('cat '+tp+'available_filter_functions | grep '+\
925 cf+' > '+tp+'set_graph_function')
926 if(sysvals.usetraceevents):
927 # turn trace events on
928 events = iter(sysvals.traceevents)
929 for e in events:
930 os.system('echo 1 > '+sysvals.epath+e+'/enable')
931 # clear the trace buffer
932 os.system('echo "" > '+tp+'trace')
933
934# Function: initFtraceAndroid
935# Description:
936# Configure ftrace to capture trace events
937def initFtraceAndroid():
938 global sysvals
939
940 tp = sysvals.tpath
941 if(sysvals.usetraceevents):
942 print('INITIALIZING FTRACE...')
943 # turn trace off
944 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
945 # set the trace clock to global
946 os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'")
947 # set trace buffer to a huge value
948 os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'")
949 os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'")
950 # turn trace events on
951 events = iter(sysvals.traceevents)
952 for e in events:
953 os.system(sysvals.adb+" shell 'echo 1 > "+\
954 sysvals.epath+e+"/enable'")
955 # clear the trace buffer
956 os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'")
441 957
442# Function: verifyFtrace 958# Function: verifyFtrace
443# Description: 959# Description:
444# Check that ftrace is working on the system 960# Check that ftrace is working on the system
961# Output:
962# True or False
445def verifyFtrace(): 963def verifyFtrace():
446 global sysvals 964 global sysvals
447 files = ["available_filter_functions", "buffer_size_kb", 965 # files needed for any trace data
448 "current_tracer", "set_ftrace_filter", 966 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
449 "trace", "trace_marker"] 967 'trace_marker', 'trace_options', 'tracing_on']
968 # files needed for callgraph trace data
969 tp = sysvals.tpath
970 if(sysvals.usecallgraph):
971 files += [
972 'available_filter_functions',
973 'set_ftrace_filter',
974 'set_graph_function'
975 ]
450 for f in files: 976 for f in files:
451 if(os.path.exists(sysvals.tpath+f) == False): 977 if(sysvals.android):
452 return False 978 out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip()
979 if(out != tp+f):
980 return False
981 else:
982 if(os.path.exists(tp+f) == False):
983 return False
453 return True 984 return True
454 985
455def parseStamp(line): 986# Function: parseStamp
456 global data, sysvals
457 stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\
458 "(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\
459 " (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$"
460 m = re.match(stampfmt, line)
461 if(m):
462 dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")),
463 int(m.group("d")), int(m.group("H")), int(m.group("M")),
464 int(m.group("S")))
465 data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p")
466 data.stamp['host'] = m.group("host")
467 data.stamp['mode'] = m.group("mode")
468 data.stamp['kernel'] = m.group("kernel")
469 sysvals.suspendmode = data.stamp['mode']
470
471# Function: analyzeTraceLog
472# Description: 987# Description:
473# Analyse an ftrace log output file generated from this app during 988# Pull in the stamp comment line from the data file(s),
474# the execution phase. Create an "ftrace" structure in memory for 989# create the stamp, and add it to the global sysvals object
475# subsequent formatting in the html output file 990# Arguments:
476def analyzeTraceLog(): 991# m: the valid re.match output for the stamp line
477 global sysvals, data 992def parseStamp(m, data):
478 993 global sysvals
479 # the ftrace data is tied to the dmesg data 994 data.stamp = {'time': '', 'host': '', 'mode': ''}
480 if(not data.usedmesg): 995 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
481 return 996 int(m.group('d')), int(m.group('H')), int(m.group('M')),
482 997 int(m.group('S')))
483 # read through the ftrace and parse the data 998 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
484 data.vprint("Analyzing the ftrace data...") 999 data.stamp['host'] = m.group('host')
485 ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\ 1000 data.stamp['mode'] = m.group('mode')
486 " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\ 1001 data.stamp['kernel'] = m.group('kernel')
487 "[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)" 1002 sysvals.suspendmode = data.stamp['mode']
488 ftemp = dict() 1003 if not sysvals.stamp:
489 inthepipe = False 1004 sysvals.stamp = data.stamp
1005
1006# Function: diffStamp
1007# Description:
1008# compare the host, kernel, and mode fields in 3 stamps
1009# Arguments:
1010# stamp1: string array with mode, kernel, and host
1011# stamp2: string array with mode, kernel, and host
1012# Return:
1013# True if stamps differ, False if they're the same
1014def diffStamp(stamp1, stamp2):
1015 if 'host' in stamp1 and 'host' in stamp2:
1016 if stamp1['host'] != stamp2['host']:
1017 return True
1018 if 'kernel' in stamp1 and 'kernel' in stamp2:
1019 if stamp1['kernel'] != stamp2['kernel']:
1020 return True
1021 if 'mode' in stamp1 and 'mode' in stamp2:
1022 if stamp1['mode'] != stamp2['mode']:
1023 return True
1024 return False
1025
1026# Function: doesTraceLogHaveTraceEvents
1027# Description:
1028# Quickly determine if the ftrace log has some or all of the trace events
1029# required for primary parsing. Set the usetraceevents and/or
1030# usetraceeventsonly flags in the global sysvals object
1031def doesTraceLogHaveTraceEvents():
1032 global sysvals
1033
1034 sysvals.usetraceeventsonly = True
1035 sysvals.usetraceevents = False
1036 for e in sysvals.traceevents:
1037 out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read()
1038 if(not out):
1039 sysvals.usetraceeventsonly = False
1040 if(e == 'suspend_resume' and out):
1041 sysvals.usetraceevents = True
1042
1043# Function: appendIncompleteTraceLog
1044# Description:
1045# [deprecated for kernel 3.15 or newer]
1046# Legacy support of ftrace outputs that lack the device_pm_callback
1047# and/or suspend_resume trace events. The primary data should be
1048# taken from dmesg, and this ftrace is used only for callgraph data
1049# or custom actions in the timeline. The data is appended to the Data
1050# objects provided.
1051# Arguments:
1052# testruns: the array of Data objects obtained from parseKernelLog
1053def appendIncompleteTraceLog(testruns):
1054 global sysvals
1055
1056 # create TestRun vessels for ftrace parsing
1057 testcnt = len(testruns)
1058 testidx = -1
1059 testrun = []
1060 for data in testruns:
1061 testrun.append(TestRun(data))
1062
1063 # extract the callgraph and traceevent data
1064 vprint('Analyzing the ftrace data...')
490 tf = open(sysvals.ftracefile, 'r') 1065 tf = open(sysvals.ftracefile, 'r')
491 count = 0
492 for line in tf: 1066 for line in tf:
493 count = count + 1 1067 # remove any latent carriage returns
494 # grab the time stamp if it's valid 1068 line = line.replace('\r\n', '')
495 if(count == 1): 1069 # grab the time stamp first (signifies the start of the test run)
496 parseStamp(line) 1070 m = re.match(sysvals.stampfmt, line)
1071 if(m):
1072 testidx += 1
1073 parseStamp(m, testrun[testidx].data)
1074 continue
1075 # pull out any firmware data
1076 if(re.match(sysvals.firmwarefmt, line)):
1077 continue
1078 # if we havent found a test time stamp yet keep spinning til we do
1079 if(testidx < 0):
1080 continue
1081 # determine the trace data type (required for further parsing)
1082 m = re.match(sysvals.tracertypefmt, line)
1083 if(m):
1084 tracer = m.group('t')
1085 testrun[testidx].setTracerType(tracer)
497 continue 1086 continue
498 # parse only valid lines 1087 # parse only valid lines, if this isnt one move on
499 m = re.match(ftrace_line_fmt, line) 1088 m = re.match(testrun[testidx].ftrace_line_fmt, line)
500 if(not m): 1089 if(not m):
501 continue 1090 continue
502 m_time = m.group("time") 1091 # gather the basic message data from the line
503 m_pid = m.group("pid") 1092 m_time = m.group('time')
504 m_msg = m.group("msg") 1093 m_pid = m.group('pid')
505 m_dur = m.group("dur") 1094 m_msg = m.group('msg')
1095 if(testrun[testidx].cgformat):
1096 m_param3 = m.group('dur')
1097 else:
1098 m_param3 = 'traceevent'
506 if(m_time and m_pid and m_msg): 1099 if(m_time and m_pid and m_msg):
507 t = FTraceLine(m_time, m_msg, m_dur) 1100 t = FTraceLine(m_time, m_msg, m_param3)
508 pid = int(m_pid) 1101 pid = int(m_pid)
509 else: 1102 else:
510 continue 1103 continue
@@ -512,265 +1105,840 @@ def analyzeTraceLog():
512 if(not t.fcall and not t.freturn and not t.fevent): 1105 if(not t.fcall and not t.freturn and not t.fevent):
513 continue 1106 continue
514 # only parse the ftrace data during suspend/resume 1107 # only parse the ftrace data during suspend/resume
515 if(not inthepipe): 1108 data = testrun[testidx].data
1109 if(not testrun[testidx].inthepipe):
516 # look for the suspend start marker 1110 # look for the suspend start marker
517 if(t.fevent): 1111 if(t.fevent):
518 if(t.name == "SUSPEND START"): 1112 if(t.name == 'SUSPEND START'):
519 data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count)) 1113 testrun[testidx].inthepipe = True
520 inthepipe = True 1114 data.setStart(t.time)
521 continue 1115 continue
522 else: 1116 else:
523 # look for the resume end marker 1117 # trace event processing
524 if(t.fevent): 1118 if(t.fevent):
525 if(t.name == "RESUME COMPLETE"): 1119 if(t.name == 'RESUME COMPLETE'):
526 data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count)) 1120 testrun[testidx].inthepipe = False
527 inthepipe = False 1121 data.setEnd(t.time)
528 break 1122 if(testidx == testcnt - 1):
1123 break
1124 continue
1125 # general trace events have two types, begin and end
1126 if(re.match('(?P<name>.*) begin$', t.name)):
1127 isbegin = True
1128 elif(re.match('(?P<name>.*) end$', t.name)):
1129 isbegin = False
1130 else:
1131 continue
1132 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1133 if(m):
1134 val = m.group('val')
1135 if val == '0':
1136 name = m.group('name')
1137 else:
1138 name = m.group('name')+'['+val+']'
1139 else:
1140 m = re.match('(?P<name>.*) .*', t.name)
1141 name = m.group('name')
1142 # special processing for trace events
1143 if re.match('dpm_prepare\[.*', name):
1144 continue
1145 elif re.match('machine_suspend.*', name):
1146 continue
1147 elif re.match('suspend_enter\[.*', name):
1148 if(not isbegin):
1149 data.dmesg['suspend_prepare']['end'] = t.time
1150 continue
1151 elif re.match('dpm_suspend\[.*', name):
1152 if(not isbegin):
1153 data.dmesg['suspend']['end'] = t.time
1154 continue
1155 elif re.match('dpm_suspend_late\[.*', name):
1156 if(isbegin):
1157 data.dmesg['suspend_late']['start'] = t.time
1158 else:
1159 data.dmesg['suspend_late']['end'] = t.time
1160 continue
1161 elif re.match('dpm_suspend_noirq\[.*', name):
1162 if(isbegin):
1163 data.dmesg['suspend_noirq']['start'] = t.time
1164 else:
1165 data.dmesg['suspend_noirq']['end'] = t.time
1166 continue
1167 elif re.match('dpm_resume_noirq\[.*', name):
1168 if(isbegin):
1169 data.dmesg['resume_machine']['end'] = t.time
1170 data.dmesg['resume_noirq']['start'] = t.time
1171 else:
1172 data.dmesg['resume_noirq']['end'] = t.time
1173 continue
1174 elif re.match('dpm_resume_early\[.*', name):
1175 if(isbegin):
1176 data.dmesg['resume_early']['start'] = t.time
1177 else:
1178 data.dmesg['resume_early']['end'] = t.time
1179 continue
1180 elif re.match('dpm_resume\[.*', name):
1181 if(isbegin):
1182 data.dmesg['resume']['start'] = t.time
1183 else:
1184 data.dmesg['resume']['end'] = t.time
1185 continue
1186 elif re.match('dpm_complete\[.*', name):
1187 if(isbegin):
1188 data.dmesg['resume_complete']['start'] = t.time
1189 else:
1190 data.dmesg['resume_complete']['end'] = t.time
1191 continue
1192 # is this trace event outside of the devices calls
1193 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1194 # global events (outside device calls) are simply graphed
1195 if(isbegin):
1196 # store each trace event in ttemp
1197 if(name not in testrun[testidx].ttemp):
1198 testrun[testidx].ttemp[name] = []
1199 testrun[testidx].ttemp[name].append(\
1200 {'begin': t.time, 'end': t.time})
1201 else:
1202 # finish off matching trace event in ttemp
1203 if(name in testrun[testidx].ttemp):
1204 testrun[testidx].ttemp[name][-1]['end'] = t.time
1205 else:
1206 if(isbegin):
1207 data.addIntraDevTraceEvent('', name, pid, t.time)
1208 else:
1209 data.capIntraDevTraceEvent('', name, pid, t.time)
1210 # call/return processing
1211 elif sysvals.usecallgraph:
1212 # create a callgraph object for the data
1213 if(pid not in testrun[testidx].ftemp):
1214 testrun[testidx].ftemp[pid] = []
1215 testrun[testidx].ftemp[pid].append(FTraceCallGraph())
1216 # when the call is finished, see which device matches it
1217 cg = testrun[testidx].ftemp[pid][-1]
1218 if(cg.addLine(t, m)):
1219 testrun[testidx].ftemp[pid].append(FTraceCallGraph())
1220 tf.close()
1221
1222 for test in testrun:
1223 # add the traceevent data to the device hierarchy
1224 if(sysvals.usetraceevents):
1225 for name in test.ttemp:
1226 for event in test.ttemp[name]:
1227 begin = event['begin']
1228 end = event['end']
1229 # if event starts before timeline start, expand timeline
1230 if(begin < test.data.start):
1231 test.data.setStart(begin)
1232 # if event ends after timeline end, expand the timeline
1233 if(end > test.data.end):
1234 test.data.setEnd(end)
1235 test.data.newActionGlobal(name, begin, end)
1236
1237 # add the callgraph data to the device hierarchy
1238 for pid in test.ftemp:
1239 for cg in test.ftemp[pid]:
1240 if(not cg.sanityCheck()):
1241 id = 'task %s cpu %s' % (pid, m.group('cpu'))
1242 vprint('Sanity check failed for '+\
1243 id+', ignoring this callback')
1244 continue
1245 callstart = cg.start
1246 callend = cg.end
1247 for p in test.data.phases:
1248 if(test.data.dmesg[p]['start'] <= callstart and
1249 callstart <= test.data.dmesg[p]['end']):
1250 list = test.data.dmesg[p]['list']
1251 for devname in list:
1252 dev = list[devname]
1253 if(pid == dev['pid'] and
1254 callstart <= dev['start'] and
1255 callend >= dev['end']):
1256 dev['ftrace'] = cg
1257 break
1258
1259 if(sysvals.verbose):
1260 test.data.printDetails()
1261
1262
1263 # add the time in between the tests as a new phase so we can see it
1264 if(len(testruns) > 1):
1265 t1e = testruns[0].getEnd()
1266 t2s = testruns[-1].getStart()
1267 testruns[-1].newPhaseWithSingleAction('user mode', \
1268 'user mode', t1e, t2s, '#FF9966')
1269
1270# Function: parseTraceLog
1271# Description:
1272# Analyze an ftrace log output file generated from this app during
1273# the execution phase. Used when the ftrace log is the primary data source
1274# and includes the suspend_resume and device_pm_callback trace events
1275# The ftrace filename is taken from sysvals
1276# Output:
1277# An array of Data objects
1278def parseTraceLog():
1279 global sysvals
1280
1281 vprint('Analyzing the ftrace data...')
1282 if(os.path.exists(sysvals.ftracefile) == False):
1283 doError('%s doesnt exist' % sysvals.ftracefile, False)
1284
1285 # extract the callgraph and traceevent data
1286 testruns = []
1287 testdata = []
1288 testrun = 0
1289 data = 0
1290 tf = open(sysvals.ftracefile, 'r')
1291 phase = 'suspend_prepare'
1292 for line in tf:
1293 # remove any latent carriage returns
1294 line = line.replace('\r\n', '')
1295 # stamp line: each stamp means a new test run
1296 m = re.match(sysvals.stampfmt, line)
1297 if(m):
1298 data = Data(len(testdata))
1299 testdata.append(data)
1300 testrun = TestRun(data)
1301 testruns.append(testrun)
1302 parseStamp(m, data)
1303 continue
1304 if(not data):
1305 continue
1306 # firmware line: pull out any firmware data
1307 m = re.match(sysvals.firmwarefmt, line)
1308 if(m):
1309 data.fwSuspend = int(m.group('s'))
1310 data.fwResume = int(m.group('r'))
1311 if(data.fwSuspend > 0 or data.fwResume > 0):
1312 data.fwValid = True
1313 continue
1314 # tracer type line: determine the trace data type
1315 m = re.match(sysvals.tracertypefmt, line)
1316 if(m):
1317 tracer = m.group('t')
1318 testrun.setTracerType(tracer)
1319 continue
1320 # post resume time line: did this test run include post-resume data
1321 m = re.match(sysvals.postresumefmt, line)
1322 if(m):
1323 t = int(m.group('t'))
1324 if(t > 0):
1325 sysvals.postresumetime = t
1326 continue
1327 # ftrace line: parse only valid lines
1328 m = re.match(testrun.ftrace_line_fmt, line)
1329 if(not m):
1330 continue
1331 # gather the basic message data from the line
1332 m_time = m.group('time')
1333 m_pid = m.group('pid')
1334 m_msg = m.group('msg')
1335 if(testrun.cgformat):
1336 m_param3 = m.group('dur')
1337 else:
1338 m_param3 = 'traceevent'
1339 if(m_time and m_pid and m_msg):
1340 t = FTraceLine(m_time, m_msg, m_param3)
1341 pid = int(m_pid)
1342 else:
1343 continue
1344 # the line should be a call, return, or event
1345 if(not t.fcall and not t.freturn and not t.fevent):
1346 continue
1347 # only parse the ftrace data during suspend/resume
1348 if(not testrun.inthepipe):
1349 # look for the suspend start marker
1350 if(t.fevent):
1351 if(t.name == 'SUSPEND START'):
1352 testrun.inthepipe = True
1353 data.setStart(t.time)
1354 continue
1355 # trace event processing
1356 if(t.fevent):
1357 if(t.name == 'RESUME COMPLETE'):
1358 if(sysvals.postresumetime > 0):
1359 phase = 'post_resume'
1360 data.newPhase(phase, t.time, t.time, '#FF9966', -1)
1361 else:
1362 testrun.inthepipe = False
1363 data.setEnd(t.time)
1364 continue
1365 if(phase == 'post_resume'):
1366 data.setEnd(t.time)
1367 if(t.type == 'suspend_resume'):
1368 # suspend_resume trace events have two types, begin and end
1369 if(re.match('(?P<name>.*) begin$', t.name)):
1370 isbegin = True
1371 elif(re.match('(?P<name>.*) end$', t.name)):
1372 isbegin = False
1373 else:
1374 continue
1375 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1376 if(m):
1377 val = m.group('val')
1378 if val == '0':
1379 name = m.group('name')
1380 else:
1381 name = m.group('name')+'['+val+']'
1382 else:
1383 m = re.match('(?P<name>.*) .*', t.name)
1384 name = m.group('name')
1385 # ignore these events
1386 if(re.match('acpi_suspend\[.*', t.name) or
1387 re.match('suspend_enter\[.*', name)):
1388 continue
1389 # -- phase changes --
1390 # suspend_prepare start
1391 if(re.match('dpm_prepare\[.*', t.name)):
1392 phase = 'suspend_prepare'
1393 if(not isbegin):
1394 data.dmesg[phase]['end'] = t.time
1395 continue
1396 # suspend start
1397 elif(re.match('dpm_suspend\[.*', t.name)):
1398 phase = 'suspend'
1399 data.setPhase(phase, t.time, isbegin)
1400 continue
1401 # suspend_late start
1402 elif(re.match('dpm_suspend_late\[.*', t.name)):
1403 phase = 'suspend_late'
1404 data.setPhase(phase, t.time, isbegin)
1405 continue
1406 # suspend_noirq start
1407 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
1408 phase = 'suspend_noirq'
1409 data.setPhase(phase, t.time, isbegin)
1410 if(not isbegin):
1411 phase = 'suspend_machine'
1412 data.dmesg[phase]['start'] = t.time
1413 continue
1414 # suspend_machine/resume_machine
1415 elif(re.match('machine_suspend\[.*', t.name)):
1416 if(isbegin):
1417 phase = 'suspend_machine'
1418 data.dmesg[phase]['end'] = t.time
1419 data.tSuspended = t.time
1420 else:
1421 if(sysvals.suspendmode in ['mem', 'disk']):
1422 data.dmesg['suspend_machine']['end'] = t.time
1423 data.tSuspended = t.time
1424 phase = 'resume_machine'
1425 data.dmesg[phase]['start'] = t.time
1426 data.tResumed = t.time
1427 data.tLow = data.tResumed - data.tSuspended
1428 continue
1429 # resume_noirq start
1430 elif(re.match('dpm_resume_noirq\[.*', t.name)):
1431 phase = 'resume_noirq'
1432 data.setPhase(phase, t.time, isbegin)
1433 if(isbegin):
1434 data.dmesg['resume_machine']['end'] = t.time
1435 continue
1436 # resume_early start
1437 elif(re.match('dpm_resume_early\[.*', t.name)):
1438 phase = 'resume_early'
1439 data.setPhase(phase, t.time, isbegin)
1440 continue
1441 # resume start
1442 elif(re.match('dpm_resume\[.*', t.name)):
1443 phase = 'resume'
1444 data.setPhase(phase, t.time, isbegin)
1445 continue
1446 # resume complete start
1447 elif(re.match('dpm_complete\[.*', t.name)):
1448 phase = 'resume_complete'
1449 if(isbegin):
1450 data.dmesg[phase]['start'] = t.time
1451 continue
1452
1453 # is this trace event outside of the devices calls
1454 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1455 # global events (outside device calls) are simply graphed
1456 if(name not in testrun.ttemp):
1457 testrun.ttemp[name] = []
1458 if(isbegin):
1459 # create a new list entry
1460 testrun.ttemp[name].append(\
1461 {'begin': t.time, 'end': t.time})
1462 else:
1463 if(len(testrun.ttemp[name]) > 0):
1464 # if an antry exists, assume this is its end
1465 testrun.ttemp[name][-1]['end'] = t.time
1466 elif(phase == 'post_resume'):
1467 # post resume events can just have ends
1468 testrun.ttemp[name].append({
1469 'begin': data.dmesg[phase]['start'],
1470 'end': t.time})
1471 else:
1472 if(isbegin):
1473 data.addIntraDevTraceEvent('', name, pid, t.time)
1474 else:
1475 data.capIntraDevTraceEvent('', name, pid, t.time)
1476 # device callback start
1477 elif(t.type == 'device_pm_callback_start'):
1478 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
1479 t.name);
1480 if(not m):
1481 continue
1482 drv = m.group('drv')
1483 n = m.group('d')
1484 p = m.group('p')
1485 if(n and p):
1486 data.newAction(phase, n, pid, p, t.time, -1, drv)
1487 # device callback finish
1488 elif(t.type == 'device_pm_callback_end'):
1489 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
1490 if(not m):
1491 continue
1492 n = m.group('d')
1493 list = data.dmesg[phase]['list']
1494 if(n in list):
1495 dev = list[n]
1496 dev['length'] = t.time - dev['start']
1497 dev['end'] = t.time
1498 # callgraph processing
1499 elif sysvals.usecallgraph:
1500 # this shouldn't happen, but JIC, ignore callgraph data post-res
1501 if(phase == 'post_resume'):
529 continue 1502 continue
530 # create a callgraph object for the data 1503 # create a callgraph object for the data
531 if(pid not in ftemp): 1504 if(pid not in testrun.ftemp):
532 ftemp[pid] = FTraceCallGraph() 1505 testrun.ftemp[pid] = []
1506 testrun.ftemp[pid].append(FTraceCallGraph())
533 # when the call is finished, see which device matches it 1507 # when the call is finished, see which device matches it
534 if(ftemp[pid].addLine(t, m)): 1508 cg = testrun.ftemp[pid][-1]
535 if(not ftemp[pid].sanityCheck()): 1509 if(cg.addLine(t, m)):
536 id = "task %s cpu %s" % (pid, m.group("cpu")) 1510 testrun.ftemp[pid].append(FTraceCallGraph())
537 data.vprint("Sanity check failed for "+id+", ignoring this callback") 1511 tf.close()
1512
1513 for test in testruns:
1514 # add the traceevent data to the device hierarchy
1515 if(sysvals.usetraceevents):
1516 for name in test.ttemp:
1517 for event in test.ttemp[name]:
1518 begin = event['begin']
1519 end = event['end']
1520 # if event starts before timeline start, expand timeline
1521 if(begin < test.data.start):
1522 test.data.setStart(begin)
1523 # if event ends after timeline end, expand the timeline
1524 if(end > test.data.end):
1525 test.data.setEnd(end)
1526 test.data.newActionGlobal(name, begin, end)
1527
1528 # add the callgraph data to the device hierarchy
1529 borderphase = {
1530 'dpm_prepare': 'suspend_prepare',
1531 'dpm_complete': 'resume_complete'
1532 }
1533 for pid in test.ftemp:
1534 for cg in test.ftemp[pid]:
1535 if len(cg.list) < 2:
1536 continue
1537 if(not cg.sanityCheck()):
1538 id = 'task %s cpu %s' % (pid, m.group('cpu'))
1539 vprint('Sanity check failed for '+\
1540 id+', ignoring this callback')
1541 continue
1542 callstart = cg.start
1543 callend = cg.end
1544 if(cg.list[0].name in borderphase):
1545 p = borderphase[cg.list[0].name]
1546 list = test.data.dmesg[p]['list']
1547 for devname in list:
1548 dev = list[devname]
1549 if(pid == dev['pid'] and
1550 callstart <= dev['start'] and
1551 callend >= dev['end']):
1552 dev['ftrace'] = cg.slice(dev['start'], dev['end'])
538 continue 1553 continue
539 callstart = ftemp[pid].start 1554 if(cg.list[0].name != 'dpm_run_callback'):
540 callend = ftemp[pid].end 1555 continue
541 for p in data.phases: 1556 for p in test.data.phases:
542 if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']): 1557 if(test.data.dmesg[p]['start'] <= callstart and
543 list = data.dmesg[p]['list'] 1558 callstart <= test.data.dmesg[p]['end']):
1559 list = test.data.dmesg[p]['list']
544 for devname in list: 1560 for devname in list:
545 dev = list[devname] 1561 dev = list[devname]
546 if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']): 1562 if(pid == dev['pid'] and
547 data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid)) 1563 callstart <= dev['start'] and
548 dev['ftrace'] = ftemp[pid] 1564 callend >= dev['end']):
1565 dev['ftrace'] = cg
549 break 1566 break
550 ftemp[pid] = FTraceCallGraph()
551 tf.close()
552 1567
553# Function: sortKernelLog 1568 # fill in any missing phases
1569 for data in testdata:
1570 lp = data.phases[0]
1571 for p in data.phases:
1572 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
1573 print('WARNING: phase "%s" is missing!' % p)
1574 if(data.dmesg[p]['start'] < 0):
1575 data.dmesg[p]['start'] = data.dmesg[lp]['end']
1576 if(p == 'resume_machine'):
1577 data.tSuspended = data.dmesg[lp]['end']
1578 data.tResumed = data.dmesg[lp]['end']
1579 data.tLow = 0
1580 if(data.dmesg[p]['end'] < 0):
1581 data.dmesg[p]['end'] = data.dmesg[p]['start']
1582 lp = p
1583
1584 if(len(sysvals.devicefilter) > 0):
1585 data.deviceFilter(sysvals.devicefilter)
1586 data.fixupInitcallsThatDidntReturn()
1587 if(sysvals.verbose):
1588 data.printDetails()
1589
1590 # add the time in between the tests as a new phase so we can see it
1591 if(len(testdata) > 1):
1592 t1e = testdata[0].getEnd()
1593 t2s = testdata[-1].getStart()
1594 testdata[-1].newPhaseWithSingleAction('user mode', \
1595 'user mode', t1e, t2s, '#FF9966')
1596 return testdata
1597
1598# Function: loadKernelLog
554# Description: 1599# Description:
555# The dmesg output log sometimes comes with with lines that have 1600# [deprecated for kernel 3.15.0 or newer]
556# timestamps out of order. This could cause issues since a call 1601# load the dmesg file into memory and fix up any ordering issues
557# could accidentally end up in the wrong phase 1602# The dmesg filename is taken from sysvals
558def sortKernelLog(): 1603# Output:
559 global sysvals, data 1604# An array of empty Data objects with only their dmesgtext attributes set
1605def loadKernelLog():
1606 global sysvals
1607
1608 vprint('Analyzing the dmesg data...')
1609 if(os.path.exists(sysvals.dmesgfile) == False):
1610 doError('%s doesnt exist' % sysvals.dmesgfile, False)
1611
1612 # there can be multiple test runs in a single file delineated by stamps
1613 testruns = []
1614 data = 0
560 lf = open(sysvals.dmesgfile, 'r') 1615 lf = open(sysvals.dmesgfile, 'r')
561 dmesglist = []
562 count = 0
563 for line in lf: 1616 for line in lf:
564 line = line.replace("\r\n", "") 1617 line = line.replace('\r\n', '')
565 if(count == 0): 1618 idx = line.find('[')
566 parseStamp(line) 1619 if idx > 1:
567 elif(count == 1): 1620 line = line[idx:]
568 m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line) 1621 m = re.match(sysvals.stampfmt, line)
569 if(m): 1622 if(m):
570 data.fwSuspend = int(m.group("s")) 1623 if(data):
571 data.fwResume = int(m.group("r")) 1624 testruns.append(data)
572 if(data.fwSuspend > 0 or data.fwResume > 0): 1625 data = Data(len(testruns))
573 data.fwValid = True 1626 parseStamp(m, data)
574 if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)): 1627 continue
575 dmesglist.append(line) 1628 if(not data):
576 count += 1 1629 continue
1630 m = re.match(sysvals.firmwarefmt, line)
1631 if(m):
1632 data.fwSuspend = int(m.group('s'))
1633 data.fwResume = int(m.group('r'))
1634 if(data.fwSuspend > 0 or data.fwResume > 0):
1635 data.fwValid = True
1636 continue
1637 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1638 if(m):
1639 data.dmesgtext.append(line)
1640 if(re.match('ACPI: resume from mwait', m.group('msg'))):
1641 print('NOTE: This suspend appears to be freeze rather than'+\
1642 ' %s, it will be treated as such' % sysvals.suspendmode)
1643 sysvals.suspendmode = 'freeze'
1644 else:
1645 vprint('ignoring dmesg line: %s' % line.replace('\n', ''))
1646 testruns.append(data)
577 lf.close() 1647 lf.close()
578 last = "" 1648
579 1649 if(not data):
580 # fix lines with the same time stamp and function with the call and return swapped 1650 print('ERROR: analyze_suspend header missing from dmesg log')
581 for line in dmesglist: 1651 sys.exit()
582 mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling (?P<f>.*)\+ @ .*, parent: .*", line) 1652
583 mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last) 1653 # fix lines with same timestamp/function with the call and return swapped
584 if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))): 1654 for data in testruns:
585 i = dmesglist.index(last) 1655 last = ''
586 j = dmesglist.index(line) 1656 for line in data.dmesgtext:
587 dmesglist[i] = line 1657 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
588 dmesglist[j] = last 1658 '(?P<f>.*)\+ @ .*, parent: .*', line)
589 last = line 1659 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
590 return dmesglist 1660 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
591 1661 if(mc and mr and (mc.group('t') == mr.group('t')) and
592# Function: analyzeKernelLog 1662 (mc.group('f') == mr.group('f'))):
1663 i = data.dmesgtext.index(last)
1664 j = data.dmesgtext.index(line)
1665 data.dmesgtext[i] = line
1666 data.dmesgtext[j] = last
1667 last = line
1668 return testruns
1669
1670# Function: parseKernelLog
593# Description: 1671# Description:
1672# [deprecated for kernel 3.15.0 or newer]
594# Analyse a dmesg log output file generated from this app during 1673# Analyse a dmesg log output file generated from this app during
595# the execution phase. Create a set of device structures in memory 1674# the execution phase. Create a set of device structures in memory
596# for subsequent formatting in the html output file 1675# for subsequent formatting in the html output file
597def analyzeKernelLog(): 1676# This call is only for legacy support on kernels where the ftrace
598 global sysvals, data 1677# data lacks the suspend_resume or device_pm_callbacks trace events.
1678# Arguments:
1679# data: an empty Data object (with dmesgtext) obtained from loadKernelLog
1680# Output:
1681# The filled Data object
1682def parseKernelLog(data):
1683 global sysvals
599 1684
600 print("PROCESSING DATA") 1685 phase = 'suspend_runtime'
601 data.vprint("Analyzing the dmesg data...")
602 if(os.path.exists(sysvals.dmesgfile) == False):
603 print("ERROR: %s doesn't exist") % sysvals.dmesgfile
604 return False
605 1686
606 lf = sortKernelLog() 1687 if(data.fwValid):
607 phase = "suspend_runtime" 1688 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
1689 (data.fwSuspend, data.fwResume))
608 1690
1691 # dmesg phase match table
609 dm = { 1692 dm = {
610 'suspend_general': r"PM: Syncing filesystems.*", 1693 'suspend_prepare': 'PM: Syncing filesystems.*',
611 'suspend_early': r"PM: suspend of devices complete after.*", 1694 'suspend': 'PM: Entering [a-z]* sleep.*',
612 'suspend_noirq': r"PM: late suspend of devices complete after.*", 1695 'suspend_late': 'PM: suspend of devices complete after.*',
613 'suspend_cpu': r"PM: noirq suspend of devices complete after.*", 1696 'suspend_noirq': 'PM: late suspend of devices complete after.*',
614 'resume_cpu': r"ACPI: Low-level resume complete.*", 1697 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
615 'resume_noirq': r"ACPI: Waking up from system sleep state.*", 1698 'resume_machine': 'ACPI: Low-level resume complete.*',
616 'resume_early': r"PM: noirq resume of devices complete after.*", 1699 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
617 'resume_general': r"PM: early resume of devices complete after.*", 1700 'resume_early': 'PM: noirq resume of devices complete after.*',
618 'resume_complete': r".*Restarting tasks \.\.\..*", 1701 'resume': 'PM: early resume of devices complete after.*',
1702 'resume_complete': 'PM: resume of devices complete after.*',
1703 'post_resume': '.*Restarting tasks \.\.\..*',
619 } 1704 }
620 if(sysvals.suspendmode == "standby"): 1705 if(sysvals.suspendmode == 'standby'):
621 dm['resume_cpu'] = r"PM: Restoring platform NVS memory" 1706 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
622 elif(sysvals.suspendmode == "disk"): 1707 elif(sysvals.suspendmode == 'disk'):
623 dm['suspend_early'] = r"PM: freeze of devices complete after.*" 1708 dm['suspend_late'] = 'PM: freeze of devices complete after.*'
624 dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*" 1709 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
625 dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*" 1710 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
626 dm['resume_cpu'] = r"PM: Restoring platform NVS memory" 1711 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
627 dm['resume_early'] = r"PM: noirq restore of devices complete after.*" 1712 dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
628 dm['resume_general'] = r"PM: early restore of devices complete after.*" 1713 dm['resume'] = 'PM: early restore of devices complete after.*'
629 1714 dm['resume_complete'] = 'PM: restore of devices complete after.*'
630 action_start = 0.0 1715 elif(sysvals.suspendmode == 'freeze'):
631 for line in lf: 1716 dm['resume_machine'] = 'ACPI: resume from mwait'
1717
1718 # action table (expected events that occur and show up in dmesg)
1719 at = {
1720 'sync_filesystems': {
1721 'smsg': 'PM: Syncing filesystems.*',
1722 'emsg': 'PM: Preparing system for mem sleep.*' },
1723 'freeze_user_processes': {
1724 'smsg': 'Freezing user space processes .*',
1725 'emsg': 'Freezing remaining freezable tasks.*' },
1726 'freeze_tasks': {
1727 'smsg': 'Freezing remaining freezable tasks.*',
1728 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
1729 'ACPI prepare': {
1730 'smsg': 'ACPI: Preparing to enter system sleep state.*',
1731 'emsg': 'PM: Saving platform NVS memory.*' },
1732 'PM vns': {
1733 'smsg': 'PM: Saving platform NVS memory.*',
1734 'emsg': 'Disabling non-boot CPUs .*' },
1735 }
1736
1737 t0 = -1.0
1738 cpu_start = -1.0
1739 prevktime = -1.0
1740 actions = dict()
1741 for line in data.dmesgtext:
632 # -- preprocessing -- 1742 # -- preprocessing --
633 # parse each dmesg line into the time and message 1743 # parse each dmesg line into the time and message
634 m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line) 1744 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
635 if(m): 1745 if(m):
636 ktime = float(m.group("ktime")) 1746 val = m.group('ktime')
637 msg = m.group("msg") 1747 try:
1748 ktime = float(val)
1749 except:
1750 doWarning('INVALID DMESG LINE: '+\
1751 line.replace('\n', ''), 'dmesg')
1752 continue
1753 msg = m.group('msg')
1754 # initialize data start to first line time
1755 if t0 < 0:
1756 data.setStart(ktime)
1757 t0 = ktime
638 else: 1758 else:
639 print line
640 continue 1759 continue
641 1760
1761 # hack for determining resume_machine end for freeze
1762 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
1763 and phase == 'resume_machine' and \
1764 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
1765 data.dmesg['resume_machine']['end'] = ktime
1766 phase = 'resume_noirq'
1767 data.dmesg[phase]['start'] = ktime
1768
642 # -- phase changes -- 1769 # -- phase changes --
643 # suspend_general start 1770 # suspend start
644 if(re.match(dm['suspend_general'], msg)): 1771 if(re.match(dm['suspend_prepare'], msg)):
645 phase = "suspend_general" 1772 phase = 'suspend_prepare'
1773 data.dmesg[phase]['start'] = ktime
1774 data.setStart(ktime)
1775 # suspend start
1776 elif(re.match(dm['suspend'], msg)):
1777 data.dmesg['suspend_prepare']['end'] = ktime
1778 phase = 'suspend'
646 data.dmesg[phase]['start'] = ktime 1779 data.dmesg[phase]['start'] = ktime
647 data.start = ktime 1780 # suspend_late start
648 # action start: syncing filesystems 1781 elif(re.match(dm['suspend_late'], msg)):
649 action_start = ktime 1782 data.dmesg['suspend']['end'] = ktime
650 # suspend_early start 1783 phase = 'suspend_late'
651 elif(re.match(dm['suspend_early'], msg)):
652 data.dmesg["suspend_general"]['end'] = ktime
653 phase = "suspend_early"
654 data.dmesg[phase]['start'] = ktime 1784 data.dmesg[phase]['start'] = ktime
655 # suspend_noirq start 1785 # suspend_noirq start
656 elif(re.match(dm['suspend_noirq'], msg)): 1786 elif(re.match(dm['suspend_noirq'], msg)):
657 data.dmesg["suspend_early"]['end'] = ktime 1787 data.dmesg['suspend_late']['end'] = ktime
658 phase = "suspend_noirq" 1788 phase = 'suspend_noirq'
659 data.dmesg[phase]['start'] = ktime 1789 data.dmesg[phase]['start'] = ktime
660 # suspend_cpu start 1790 # suspend_machine start
661 elif(re.match(dm['suspend_cpu'], msg)): 1791 elif(re.match(dm['suspend_machine'], msg)):
662 data.dmesg["suspend_noirq"]['end'] = ktime 1792 data.dmesg['suspend_noirq']['end'] = ktime
663 phase = "suspend_cpu" 1793 phase = 'suspend_machine'
664 data.dmesg[phase]['start'] = ktime 1794 data.dmesg[phase]['start'] = ktime
665 # resume_cpu start 1795 # resume_machine start
666 elif(re.match(dm['resume_cpu'], msg)): 1796 elif(re.match(dm['resume_machine'], msg)):
667 data.tSuspended = ktime 1797 if(sysvals.suspendmode in ['freeze', 'standby']):
668 data.dmesg["suspend_cpu"]['end'] = ktime 1798 data.tSuspended = prevktime
669 phase = "resume_cpu" 1799 data.dmesg['suspend_machine']['end'] = prevktime
1800 else:
1801 data.tSuspended = ktime
1802 data.dmesg['suspend_machine']['end'] = ktime
1803 phase = 'resume_machine'
1804 data.tResumed = ktime
1805 data.tLow = data.tResumed - data.tSuspended
670 data.dmesg[phase]['start'] = ktime 1806 data.dmesg[phase]['start'] = ktime
671 # resume_noirq start 1807 # resume_noirq start
672 elif(re.match(dm['resume_noirq'], msg)): 1808 elif(re.match(dm['resume_noirq'], msg)):
673 data.dmesg["resume_cpu"]['end'] = ktime 1809 data.dmesg['resume_machine']['end'] = ktime
674 phase = "resume_noirq" 1810 phase = 'resume_noirq'
675 data.dmesg[phase]['start'] = ktime 1811 data.dmesg[phase]['start'] = ktime
676 # action end: ACPI resume
677 data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime)
678 # resume_early start 1812 # resume_early start
679 elif(re.match(dm['resume_early'], msg)): 1813 elif(re.match(dm['resume_early'], msg)):
680 data.dmesg["resume_noirq"]['end'] = ktime 1814 data.dmesg['resume_noirq']['end'] = ktime
681 phase = "resume_early" 1815 phase = 'resume_early'
682 data.dmesg[phase]['start'] = ktime 1816 data.dmesg[phase]['start'] = ktime
683 # resume_general start 1817 # resume start
684 elif(re.match(dm['resume_general'], msg)): 1818 elif(re.match(dm['resume'], msg)):
685 data.dmesg["resume_early"]['end'] = ktime 1819 data.dmesg['resume_early']['end'] = ktime
686 phase = "resume_general" 1820 phase = 'resume'
687 data.dmesg[phase]['start'] = ktime 1821 data.dmesg[phase]['start'] = ktime
688 # resume complete start 1822 # resume complete start
689 elif(re.match(dm['resume_complete'], msg)): 1823 elif(re.match(dm['resume_complete'], msg)):
690 data.dmesg["resume_general"]['end'] = ktime 1824 data.dmesg['resume']['end'] = ktime
691 data.end = ktime 1825 phase = 'resume_complete'
692 phase = "resume_runtime" 1826 data.dmesg[phase]['start'] = ktime
1827 # post resume start
1828 elif(re.match(dm['post_resume'], msg)):
1829 data.dmesg['resume_complete']['end'] = ktime
1830 data.setEnd(ktime)
1831 phase = 'post_resume'
693 break 1832 break
694 1833
695 # -- device callbacks -- 1834 # -- device callbacks --
696 if(phase in data.phases): 1835 if(phase in data.phases):
697 # device init call 1836 # device init call
698 if(re.match(r"calling (?P<f>.*)\+ @ .*, parent: .*", msg)): 1837 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
699 sm = re.match(r"calling (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg); 1838 sm = re.match('calling (?P<f>.*)\+ @ '+\
700 f = sm.group("f") 1839 '(?P<n>.*), parent: (?P<p>.*)', msg);
701 n = sm.group("n") 1840 f = sm.group('f')
702 p = sm.group("p") 1841 n = sm.group('n')
1842 p = sm.group('p')
703 if(f and n and p): 1843 if(f and n and p):
704 data.newAction(phase, f, int(n), p, ktime, -1) 1844 data.newAction(phase, f, int(n), p, ktime, -1, '')
705 # device init return 1845 # device init return
706 elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)): 1846 elif(re.match('call (?P<f>.*)\+ returned .* after '+\
707 sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg); 1847 '(?P<t>.*) usecs', msg)):
708 f = sm.group("f") 1848 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
709 t = sm.group("t") 1849 '(?P<t>.*) usecs(?P<a>.*)', msg);
1850 f = sm.group('f')
1851 t = sm.group('t')
710 list = data.dmesg[phase]['list'] 1852 list = data.dmesg[phase]['list']
711 if(f in list): 1853 if(f in list):
712 dev = list[f] 1854 dev = list[f]
713 dev['length'] = int(t) 1855 dev['length'] = int(t)
714 dev['end'] = ktime 1856 dev['end'] = ktime
715 data.vprint("%15s [%f - %f] %s(%d) %s" % 1857
716 (phase, dev['start'], dev['end'], f, dev['pid'], dev['par'])) 1858 # -- non-devicecallback actions --
717 1859 # if trace events are not available, these are better than nothing
718 # -- phase specific actions -- 1860 if(not sysvals.usetraceevents):
719 if(phase == "suspend_general"): 1861 # look for known actions
720 if(re.match(r"PM: Preparing system for mem sleep.*", msg)): 1862 for a in at:
721 data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime) 1863 if(re.match(at[a]['smsg'], msg)):
722 elif(re.match(r"Freezing user space processes .*", msg)): 1864 if(a not in actions):
723 action_start = ktime 1865 actions[a] = []
724 elif(re.match(r"Freezing remaining freezable tasks.*", msg)): 1866 actions[a].append({'begin': ktime, 'end': ktime})
725 data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime) 1867 if(re.match(at[a]['emsg'], msg)):
726 action_start = ktime 1868 actions[a][-1]['end'] = ktime
727 elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)): 1869 # now look for CPU on/off events
728 data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime) 1870 if(re.match('Disabling non-boot CPUs .*', msg)):
729 elif(phase == "suspend_cpu"): 1871 # start of first cpu suspend
730 m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg) 1872 cpu_start = ktime
731 if(m): 1873 elif(re.match('Enabling non-boot CPUs .*', msg)):
732 cpu = "CPU"+m.group("cpu") 1874 # start of first cpu resume
733 data.newAction(phase, cpu, -1, "", action_start, ktime) 1875 cpu_start = ktime
734 action_start = ktime 1876 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
735 elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)): 1877 # end of a cpu suspend, start of the next
736 action_start = ktime 1878 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
737 elif(re.match(r"Disabling non-boot CPUs .*", msg)): 1879 cpu = 'CPU'+m.group('cpu')
738 data.newAction(phase, "ACPI", -1, "", action_start, ktime) 1880 if(cpu not in actions):
739 action_start = ktime 1881 actions[cpu] = []
740 elif(phase == "resume_cpu"): 1882 actions[cpu].append({'begin': cpu_start, 'end': ktime})
741 m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg) 1883 cpu_start = ktime
742 if(m): 1884 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
743 cpu = "CPU"+m.group("cpu") 1885 # end of a cpu resume, start of the next
744 data.newAction(phase, cpu, -1, "", action_start, ktime) 1886 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
745 action_start = ktime 1887 cpu = 'CPU'+m.group('cpu')
746 elif(re.match(r"Enabling non-boot CPUs .*", msg)): 1888 if(cpu not in actions):
747 action_start = ktime 1889 actions[cpu] = []
1890 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1891 cpu_start = ktime
1892 prevktime = ktime
748 1893
749 # fill in any missing phases 1894 # fill in any missing phases
750 lp = "suspend_general" 1895 lp = data.phases[0]
751 for p in data.phases: 1896 for p in data.phases:
752 if(p == "suspend_general"): 1897 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
753 continue 1898 print('WARNING: phase "%s" is missing, something went wrong!' % p)
1899 print(' In %s, this dmesg line denotes the start of %s:' % \
1900 (sysvals.suspendmode, p))
1901 print(' "%s"' % dm[p])
754 if(data.dmesg[p]['start'] < 0): 1902 if(data.dmesg[p]['start'] < 0):
755 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 1903 data.dmesg[p]['start'] = data.dmesg[lp]['end']
756 if(p == "resume_cpu"): 1904 if(p == 'resume_machine'):
757 data.tSuspended = data.dmesg[lp]['end'] 1905 data.tSuspended = data.dmesg[lp]['end']
1906 data.tResumed = data.dmesg[lp]['end']
1907 data.tLow = 0
758 if(data.dmesg[p]['end'] < 0): 1908 if(data.dmesg[p]['end'] < 0):
759 data.dmesg[p]['end'] = data.dmesg[p]['start'] 1909 data.dmesg[p]['end'] = data.dmesg[p]['start']
760 lp = p 1910 lp = p
761 1911
1912 # fill in any actions we've found
1913 for name in actions:
1914 for event in actions[name]:
1915 begin = event['begin']
1916 end = event['end']
1917 # if event starts before timeline start, expand timeline
1918 if(begin < data.start):
1919 data.setStart(begin)
1920 # if event ends after timeline end, expand the timeline
1921 if(end > data.end):
1922 data.setEnd(end)
1923 data.newActionGlobal(name, begin, end)
1924
1925 if(sysvals.verbose):
1926 data.printDetails()
1927 if(len(sysvals.devicefilter) > 0):
1928 data.deviceFilter(sysvals.devicefilter)
762 data.fixupInitcallsThatDidntReturn() 1929 data.fixupInitcallsThatDidntReturn()
763 return True 1930 return True
764 1931
765# Function: setTimelineRows 1932# Function: setTimelineRows
766# Description: 1933# Description:
767# Organize the device or thread lists into the smallest 1934# Organize the timeline entries into the smallest
768# number of rows possible, with no entry overlapping 1935# number of rows possible, with no entry overlapping
769# Arguments: 1936# Arguments:
770# list: the list to sort (dmesg or ftrace) 1937# list: the list of devices/actions for a single phase
771# sortedkeys: sorted key list to use 1938# sortedkeys: cronologically sorted key list to use
1939# Output:
1940# The total number of rows needed to display this phase of the timeline
772def setTimelineRows(list, sortedkeys): 1941def setTimelineRows(list, sortedkeys):
773 global data
774 1942
775 # clear all rows and set them to undefined 1943 # clear all rows and set them to undefined
776 remaining = len(list) 1944 remaining = len(list)
@@ -791,7 +1959,8 @@ def setTimelineRows(list, sortedkeys):
791 for ritem in rowdata[row]: 1959 for ritem in rowdata[row]:
792 rs = ritem['start'] 1960 rs = ritem['start']
793 re = ritem['end'] 1961 re = ritem['end']
794 if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))): 1962 if(not (((s <= rs) and (e <= rs)) or
1963 ((s >= re) and (e >= re)))):
795 valid = False 1964 valid = False
796 break 1965 break
797 if(valid): 1966 if(valid):
@@ -803,14 +1972,15 @@ def setTimelineRows(list, sortedkeys):
803 1972
804# Function: createTimeScale 1973# Function: createTimeScale
805# Description: 1974# Description:
806# Create timescale lines for the dmesg and ftrace timelines 1975# Create the timescale header for the html timeline
807# Arguments: 1976# Arguments:
808# t0: start time (suspend begin) 1977# t0: start time (suspend begin)
809# tMax: end time (resume end) 1978# tMax: end time (resume end)
810# tSuspend: time when suspend occurs 1979# tSuspend: time when suspend occurs, i.e. the zero time
1980# Output:
1981# The html code needed to display the time scale
811def createTimeScale(t0, tMax, tSuspended): 1982def createTimeScale(t0, tMax, tSuspended):
812 global data 1983 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
813 timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n"
814 output = '<div id="timescale">\n' 1984 output = '<div id="timescale">\n'
815 1985
816 # set scale for timeline 1986 # set scale for timeline
@@ -822,11 +1992,11 @@ def createTimeScale(t0, tMax, tSuspended):
822 tS = 1 1992 tS = 1
823 if(tSuspended < 0): 1993 if(tSuspended < 0):
824 for i in range(int(tTotal/tS)+1): 1994 for i in range(int(tTotal/tS)+1):
825 pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal)) 1995 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal))
826 if(i > 0): 1996 if(i > 0):
827 val = "%0.f" % (float(i)*tS*1000) 1997 val = '%0.fms' % (float(i)*tS*1000)
828 else: 1998 else:
829 val = "" 1999 val = ''
830 output += timescale.format(pos, val) 2000 output += timescale.format(pos, val)
831 else: 2001 else:
832 tSuspend = tSuspended - t0 2002 tSuspend = tSuspended - t0
@@ -834,69 +2004,253 @@ def createTimeScale(t0, tMax, tSuspended):
834 divSuspend = int(tSuspend/tS) 2004 divSuspend = int(tSuspend/tS)
835 s0 = (tSuspend - tS*divSuspend)*100/tTotal 2005 s0 = (tSuspend - tS*divSuspend)*100/tTotal
836 for i in range(divTotal): 2006 for i in range(divTotal):
837 pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0) 2007 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0)
838 if((i == 0) and (s0 < 3)): 2008 if((i == 0) and (s0 < 3)):
839 val = "" 2009 val = ''
840 elif(i == divSuspend): 2010 elif(i == divSuspend):
841 val = "S/R" 2011 val = 'S/R'
842 else: 2012 else:
843 val = "%0.f" % (float(i-divSuspend)*tS*1000) 2013 val = '%0.fms' % (float(i-divSuspend)*tS*1000)
844 output += timescale.format(pos, val) 2014 output += timescale.format(pos, val)
845 output += '</div>\n' 2015 output += '</div>\n'
846 return output 2016 return output
847 2017
2018# Function: createHTMLSummarySimple
2019# Description:
2020# Create summary html file for a series of tests
2021# Arguments:
2022# testruns: array of Data objects from parseTraceLog
2023def createHTMLSummarySimple(testruns, htmlfile):
2024 global sysvals
2025
2026 # print out the basic summary of all the tests
2027 hf = open(htmlfile, 'w')
2028
2029 # write the html header first (html head, css code, up to body start)
2030 html = '<!DOCTYPE html>\n<html>\n<head>\n\
2031 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2032 <title>AnalyzeSuspend Summary</title>\n\
2033 <style type=\'text/css\'>\n\
2034 body {overflow-y: scroll;}\n\
2035 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\
2036 table {width:100%;border-collapse: collapse;}\n\
2037 .summary {font: 22px Arial;border:1px solid;}\n\
2038 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\
2039 td {text-align: center;}\n\
2040 tr.alt td {background-color:#EAF2D3;}\n\
2041 tr.avg td {background-color:#BDE34C;}\n\
2042 a:link {color: #90B521;}\n\
2043 a:visited {color: #495E09;}\n\
2044 a:hover {color: #B1DF28;}\n\
2045 a:active {color: #FFFFFF;}\n\
2046 </style>\n</head>\n<body>\n'
2047
2048 # group test header
2049 count = len(testruns)
2050 headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n'
2051 html += headline_stamp.format(sysvals.stamp['host'],
2052 sysvals.stamp['kernel'], sysvals.stamp['mode'],
2053 sysvals.stamp['time'], count)
2054
2055 # check to see if all the tests have the same value
2056 stampcolumns = False
2057 for data in testruns:
2058 if diffStamp(sysvals.stamp, data.stamp):
2059 stampcolumns = True
2060 break
2061
2062 th = '\t<th>{0}</th>\n'
2063 td = '\t<td>{0}</td>\n'
2064 tdlink = '\t<td><a href="{0}">Click Here</a></td>\n'
2065
2066 # table header
2067 html += '<table class="summary">\n<tr>\n'
2068 html += th.format("Test #")
2069 if stampcolumns:
2070 html += th.format("Hostname")
2071 html += th.format("Kernel Version")
2072 html += th.format("Suspend Mode")
2073 html += th.format("Test Time")
2074 html += th.format("Suspend Time")
2075 html += th.format("Resume Time")
2076 html += th.format("Detail")
2077 html += '</tr>\n'
2078
2079 # test data, 1 row per test
2080 sTimeAvg = 0.0
2081 rTimeAvg = 0.0
2082 num = 1
2083 for data in testruns:
2084 # data.end is the end of post_resume
2085 resumeEnd = data.dmesg['resume_complete']['end']
2086 if num % 2 == 1:
2087 html += '<tr class="alt">\n'
2088 else:
2089 html += '<tr>\n'
2090
2091 # test num
2092 html += td.format("test %d" % num)
2093 num += 1
2094 if stampcolumns:
2095 # host name
2096 val = "unknown"
2097 if('host' in data.stamp):
2098 val = data.stamp['host']
2099 html += td.format(val)
2100 # host kernel
2101 val = "unknown"
2102 if('kernel' in data.stamp):
2103 val = data.stamp['kernel']
2104 html += td.format(val)
2105 # suspend mode
2106 val = "unknown"
2107 if('mode' in data.stamp):
2108 val = data.stamp['mode']
2109 html += td.format(val)
2110 # test time
2111 val = "unknown"
2112 if('time' in data.stamp):
2113 val = data.stamp['time']
2114 html += td.format(val)
2115 # suspend time
2116 sTime = (data.tSuspended - data.start)*1000
2117 sTimeAvg += sTime
2118 html += td.format("%3.3f ms" % sTime)
2119 # resume time
2120 rTime = (resumeEnd - data.tResumed)*1000
2121 rTimeAvg += rTime
2122 html += td.format("%3.3f ms" % rTime)
2123 # link to the output html
2124 html += tdlink.format(data.outfile)
2125
2126 html += '</tr>\n'
2127
2128 # last line: test average
2129 if(count > 0):
2130 sTimeAvg /= count
2131 rTimeAvg /= count
2132 html += '<tr class="avg">\n'
2133 html += td.format('Average') # name
2134 if stampcolumns:
2135 html += td.format('') # host
2136 html += td.format('') # kernel
2137 html += td.format('') # mode
2138 html += td.format('') # time
2139 html += td.format("%3.3f ms" % sTimeAvg) # suspend time
2140 html += td.format("%3.3f ms" % rTimeAvg) # resume time
2141 html += td.format('') # output link
2142 html += '</tr>\n'
2143
2144 # flush the data to file
2145 hf.write(html+'</table>\n')
2146 hf.write('</body>\n</html>\n')
2147 hf.close()
2148
848# Function: createHTML 2149# Function: createHTML
849# Description: 2150# Description:
850# Create the output html file. 2151# Create the output html file from the resident test data
851def createHTML(): 2152# Arguments:
852 global sysvals, data 2153# testruns: array of Data objects from parseKernelLog or parseTraceLog
2154# Output:
2155# True if the html file was created, false if it failed
2156def createHTML(testruns):
2157 global sysvals
853 2158
854 data.normalizeTime() 2159 for data in testruns:
2160 data.normalizeTime(testruns[-1].tSuspended)
855 2161
2162 x2changes = ['', 'absolute']
2163 if len(testruns) > 1:
2164 x2changes = ['1', 'relative']
856 # html function templates 2165 # html function templates
857 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' 2166 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
858 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' 2167 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
859 html_timeline = '<div id="{0}" class="timeline" style="height:{1}px">\n' 2168 html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
2169 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
2170 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
860 html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n' 2171 html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
2172 html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n'
861 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n' 2173 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
2174 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
862 html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n' 2175 html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
863 html_timetotal = '<table class="time1">\n<tr>'\ 2176 html_timetotal = '<table class="time1">\n<tr>'\
864 '<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\ 2177 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
865 '<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\ 2178 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
2179 '</tr>\n</table>\n'
2180 html_timetotal2 = '<table class="time1">\n<tr>'\
2181 '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\
2182 '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
2183 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
866 '</tr>\n</table>\n' 2184 '</tr>\n</table>\n'
867 html_timegroups = '<table class="time2">\n<tr>'\ 2185 html_timegroups = '<table class="time2">\n<tr>'\
868 '<td class="green">Kernel Suspend: {0} ms</td>'\ 2186 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\
869 '<td class="purple">Firmware Suspend: {1} ms</td>'\ 2187 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
870 '<td class="purple">Firmware Resume: {2} ms</td>'\ 2188 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
871 '<td class="yellow">Kernel Resume: {3} ms</td>'\ 2189 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
872 '</tr>\n</table>\n' 2190 '</tr>\n</table>\n'
873 2191
874 # device timeline (dmesg) 2192 # device timeline
875 if(data.usedmesg): 2193 vprint('Creating Device Timeline...')
876 data.vprint("Creating Device Timeline...") 2194 devtl = Timeline()
877 devtl = Timeline()
878 2195
879 # Generate the header for this timeline 2196 # Generate the header for this timeline
880 t0 = data.start 2197 textnum = ['First', 'Second']
881 tMax = data.end 2198 for data in testruns:
882 tTotal = tMax - t0 2199 tTotal = data.end - data.start
2200 tEnd = data.dmesg['resume_complete']['end']
883 if(tTotal == 0): 2201 if(tTotal == 0):
884 print("ERROR: No timeline data") 2202 print('ERROR: No timeline data')
885 sys.exit() 2203 sys.exit()
886 suspend_time = "%.0f"%(-data.start*1000) 2204 if(data.tLow > 0):
887 resume_time = "%.0f"%(data.end*1000) 2205 low_time = '%.0f'%(data.tLow*1000)
888 if data.fwValid: 2206 if data.fwValid:
889 devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total") 2207 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \
890 sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000) 2208 (data.fwSuspend/1000000.0))
891 sftime = "%.3f"%(data.fwSuspend / 1000000.0) 2209 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \
892 rftime = "%.3f"%(data.fwResume / 1000000.0) 2210 (data.fwResume/1000000.0))
893 rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000) 2211 testdesc1 = 'Total'
894 devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime) 2212 testdesc2 = ''
2213 if(len(testruns) > 1):
2214 testdesc1 = testdesc2 = textnum[data.testnumber]
2215 testdesc2 += ' '
2216 if(data.tLow == 0):
2217 thtml = html_timetotal.format(suspend_time, \
2218 resume_time, testdesc1)
2219 else:
2220 thtml = html_timetotal2.format(suspend_time, low_time, \
2221 resume_time, testdesc1)
2222 devtl.html['timeline'] += thtml
2223 sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \
2224 data.getStart())*1000)
2225 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
2226 rftime = '%.3f'%(data.fwResume / 1000000.0)
2227 rktime = '%.3f'%((data.getEnd() - \
2228 data.dmesg['resume_machine']['start'])*1000)
2229 devtl.html['timeline'] += html_timegroups.format(sktime, \
2230 sftime, rftime, rktime, testdesc2)
895 else: 2231 else:
896 devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel") 2232 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
2233 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
2234 testdesc = 'Kernel'
2235 if(len(testruns) > 1):
2236 testdesc = textnum[data.testnumber]+' '+testdesc
2237 if(data.tLow == 0):
2238 thtml = html_timetotal.format(suspend_time, \
2239 resume_time, testdesc)
2240 else:
2241 thtml = html_timetotal2.format(suspend_time, low_time, \
2242 resume_time, testdesc)
2243 devtl.html['timeline'] += thtml
2244
2245 # time scale for potentially multiple datasets
2246 t0 = testruns[0].start
2247 tMax = testruns[-1].end
2248 tSuspended = testruns[-1].tSuspended
2249 tTotal = tMax - t0
897 2250
898 # determine the maximum number of rows we need to draw 2251 # determine the maximum number of rows we need to draw
899 timelinerows = 0 2252 timelinerows = 0
2253 for data in testruns:
900 for phase in data.dmesg: 2254 for phase in data.dmesg:
901 list = data.dmesg[phase]['list'] 2255 list = data.dmesg[phase]['list']
902 rows = setTimelineRows(list, list) 2256 rows = setTimelineRows(list, list)
@@ -904,62 +2258,104 @@ def createHTML():
904 if(rows > timelinerows): 2258 if(rows > timelinerows):
905 timelinerows = rows 2259 timelinerows = rows
906 2260
907 # calculate the timeline height and create its bounding box 2261 # calculate the timeline height and create bounding box, add buttons
908 devtl.setRows(timelinerows + 1) 2262 devtl.setRows(timelinerows + 1)
909 devtl.html['timeline'] += html_zoombox; 2263 devtl.html['timeline'] += html_devlist1
910 devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height); 2264 if len(testruns) > 1:
2265 devtl.html['timeline'] += html_devlist2
2266 devtl.html['timeline'] += html_zoombox
2267 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
911 2268
912 # draw the colored boxes for each of the phases 2269 # draw the colored boxes for each of the phases
2270 for data in testruns:
913 for b in data.dmesg: 2271 for b in data.dmesg:
914 phase = data.dmesg[b] 2272 phase = data.dmesg[b]
915 left = "%.3f" % (((phase['start']-data.start)*100)/tTotal) 2273 length = phase['end']-phase['start']
916 width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal) 2274 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
917 devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "") 2275 width = '%.3f' % ((length*100.0)/tTotal)
918 2276 devtl.html['timeline'] += html_phase.format(left, width, \
919 # draw the time scale, try to make the number of labels readable 2277 '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \
920 devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended) 2278 data.dmesg[b]['color'], '')
921 devtl.html['timeline'] += devtl.html['scale'] 2279
2280 # draw the time scale, try to make the number of labels readable
2281 devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended)
2282 devtl.html['timeline'] += devtl.html['scale']
2283 for data in testruns:
922 for b in data.dmesg: 2284 for b in data.dmesg:
923 phaselist = data.dmesg[b]['list'] 2285 phaselist = data.dmesg[b]['list']
924 for d in phaselist: 2286 for d in phaselist:
925 name = d 2287 name = d
926 if(d in data.altdevname): 2288 drv = ''
927 name = data.altdevname[d]
928 dev = phaselist[d] 2289 dev = phaselist[d]
2290 if(d in sysvals.altdevname):
2291 name = sysvals.altdevname[d]
2292 if('drv' in dev and dev['drv']):
2293 drv = ' {%s}' % dev['drv']
929 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 2294 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
930 top = "%.3f" % ((dev['row']*height) + devtl.scaleH) 2295 top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
931 left = "%.3f" % (((dev['start']-data.start)*100)/tTotal) 2296 left = '%.3f' % (((dev['start']-t0)*100)/tTotal)
932 width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal) 2297 width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal)
933 len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000) 2298 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
934 color = "rgba(204,204,204,0.5)" 2299 color = 'rgba(204,204,204,0.5)'
935 devtl.html['timeline'] += html_device.format(dev['id'], name+len+b, left, top, "%.3f"%height, width, name) 2300 devtl.html['timeline'] += html_device.format(dev['id'], \
936 2301 d+drv+length+b, left, top, '%.3f'%height, width, name+drv)
937 # timeline is finished 2302
938 devtl.html['timeline'] += "</div>\n</div>\n" 2303 # draw any trace events found
939 2304 for data in testruns:
940 # draw a legend which describes the phases by color 2305 for b in data.dmesg:
941 devtl.html['legend'] = "<div class=\"legend\">\n" 2306 phaselist = data.dmesg[b]['list']
942 pdelta = 100.0/data.phases.__len__() 2307 for name in phaselist:
943 pmargin = pdelta / 4.0 2308 dev = phaselist[name]
944 for phase in data.phases: 2309 if('traceevents' in dev):
945 order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin) 2310 vprint('Debug trace events found for device %s' % name)
946 name = string.replace(phase, "_", " &nbsp;") 2311 vprint('%20s %20s %10s %8s' % ('action', \
947 devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name) 2312 'name', 'time(ms)', 'length(ms)'))
948 devtl.html['legend'] += "</div>\n" 2313 for e in dev['traceevents']:
2314 vprint('%20s %20s %10.3f %8.3f' % (e.action, \
2315 e.name, e.time*1000, e.length*1000))
2316 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
2317 top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
2318 left = '%.3f' % (((e.time-t0)*100)/tTotal)
2319 width = '%.3f' % (e.length*100/tTotal)
2320 color = 'rgba(204,204,204,0.5)'
2321 devtl.html['timeline'] += \
2322 html_traceevent.format(e.action+' '+e.name, \
2323 left, top, '%.3f'%height, \
2324 width, e.color, '')
2325
2326 # timeline is finished
2327 devtl.html['timeline'] += '</div>\n</div>\n'
2328
2329 # draw a legend which describes the phases by color
2330 data = testruns[-1]
2331 devtl.html['legend'] = '<div class="legend">\n'
2332 pdelta = 100.0/len(data.phases)
2333 pmargin = pdelta / 4.0
2334 for phase in data.phases:
2335 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
2336 name = string.replace(phase, '_', ' &nbsp;')
2337 devtl.html['legend'] += html_legend.format(order, \
2338 data.dmesg[phase]['color'], name)
2339 devtl.html['legend'] += '</div>\n'
949 2340
950 hf = open(sysvals.htmlfile, 'w') 2341 hf = open(sysvals.htmlfile, 'w')
951 thread_height = 0 2342 thread_height = 0
952 2343
953 # write the html header first (html head, css code, everything up to the start of body) 2344 # write the html header first (html head, css code, up to body start)
954 html_header = "<!DOCTYPE html>\n<html>\n<head>\n\ 2345 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
955 <meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\ 2346 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
956 <title>AnalyzeSuspend</title>\n\ 2347 <title>AnalyzeSuspend</title>\n\
957 <style type='text/css'>\n\ 2348 <style type=\'text/css\'>\n\
958 body {overflow-y: scroll;}\n\ 2349 body {overflow-y: scroll;}\n\
959 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\ 2350 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
960 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\ 2351 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
961 .callgraph article * {padding-left: 28px;}\n\ 2352 .callgraph article * {padding-left: 28px;}\n\
962 h1 {color:black;font: bold 30px Times;}\n\ 2353 h1 {color:black;font: bold 30px Times;}\n\
2354 t0 {color:black;font: bold 30px Times;}\n\
2355 t1 {color:black;font: 30px Times;}\n\
2356 t2 {color:black;font: 25px Times;}\n\
2357 t3 {color:black;font: 20px Times;white-space:nowrap;}\n\
2358 t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\
963 table {width:100%;}\n\ 2359 table {width:100%;}\n\
964 .gray {background-color:rgba(80,80,80,0.1);}\n\ 2360 .gray {background-color:rgba(80,80,80,0.1);}\n\
965 .green {background-color:rgba(204,255,204,0.4);}\n\ 2361 .green {background-color:rgba(204,255,204,0.4);}\n\
@@ -968,38 +2364,58 @@ def createHTML():
968 .time1 {font: 22px Arial;border:1px solid;}\n\ 2364 .time1 {font: 22px Arial;border:1px solid;}\n\
969 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ 2365 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
970 td {text-align: center;}\n\ 2366 td {text-align: center;}\n\
2367 r {color:#500000;font:15px Tahoma;}\n\
2368 n {color:#505050;font:15px Tahoma;}\n\
971 .tdhl {color: red;}\n\ 2369 .tdhl {color: red;}\n\
972 .hide {display: none;}\n\ 2370 .hide {display: none;}\n\
973 .pf {display: none;}\n\ 2371 .pf {display: none;}\n\
974 .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\ 2372 .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\
975 .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\ 2373 .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\
976 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\ 2374 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
977 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\ 2375 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
978 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\ 2376 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
979 .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\ 2377 .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\
980 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\ 2378 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
2379 .hover {background-color:white;border:1px solid red;z-index:10;}\n\
2380 .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\
981 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\ 2381 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
982 .t {position: absolute; top: 0%; height: 100%; border-right:1px solid black;}\n\ 2382 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
2383 .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\
983 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\ 2384 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
984 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\ 2385 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
985 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ 2386 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
986 </style>\n</head>\n<body>\n" 2387 .devlist {position:'+x2changes[1]+';width:190px;}\n\
2388 #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\
2389 </style>\n</head>\n<body>\n'
987 hf.write(html_header) 2390 hf.write(html_header)
988 2391
989 # write the test title and general info header 2392 # write the test title and general info header
990 if(data.stamp['time'] != ""): 2393 if(sysvals.stamp['time'] != ""):
991 hf.write(headline_stamp.format(data.stamp['host'], 2394 hf.write(headline_stamp.format(sysvals.stamp['host'],
992 data.stamp['kernel'], data.stamp['mode'], data.stamp['time'])) 2395 sysvals.stamp['kernel'], sysvals.stamp['mode'], \
993 2396 sysvals.stamp['time']))
994 # write the dmesg data (device timeline) 2397
995 if(data.usedmesg): 2398 # write the device timeline
996 hf.write(devtl.html['timeline']) 2399 hf.write(devtl.html['timeline'])
997 hf.write(devtl.html['legend']) 2400 hf.write(devtl.html['legend'])
998 hf.write('<div id="devicedetail"></div>\n') 2401 hf.write('<div id="devicedetailtitle"></div>\n')
999 hf.write('<div id="devicetree"></div>\n') 2402 hf.write('<div id="devicedetail" style="display:none;">\n')
2403 # draw the colored boxes for the device detail section
2404 for data in testruns:
2405 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
2406 for b in data.phases:
2407 phase = data.dmesg[b]
2408 length = phase['end']-phase['start']
2409 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
2410 width = '%.3f' % ((length*100.0)/tTotal)
2411 hf.write(html_phaselet.format(b, left, width, \
2412 data.dmesg[b]['color']))
2413 hf.write('</div>\n')
2414 hf.write('</div>\n')
1000 2415
1001 # write the ftrace data (callgraph) 2416 # write the ftrace data (callgraph)
1002 if(data.useftrace): 2417 data = testruns[-1]
2418 if(sysvals.usecallgraph):
1003 hf.write('<section id="callgraphs" class="callgraph">\n') 2419 hf.write('<section id="callgraphs" class="callgraph">\n')
1004 # write out the ftrace data converted to html 2420 # write out the ftrace data converted to html
1005 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' 2421 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'
@@ -1013,18 +2429,21 @@ def createHTML():
1013 if('ftrace' not in list[devname]): 2429 if('ftrace' not in list[devname]):
1014 continue 2430 continue
1015 name = devname 2431 name = devname
1016 if(devname in data.altdevname): 2432 if(devname in sysvals.altdevname):
1017 name = data.altdevname[devname] 2433 name = sysvals.altdevname[devname]
1018 devid = list[devname]['id'] 2434 devid = list[devname]['id']
1019 cg = list[devname]['ftrace'] 2435 cg = list[devname]['ftrace']
1020 flen = "(%.3f ms)" % ((cg.end - cg.start)*1000) 2436 flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \
1021 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], num, name+" "+p, flen)) 2437 ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000)
2438 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
2439 num, name+' '+p, flen))
1022 num += 1 2440 num += 1
1023 for line in cg.list: 2441 for line in cg.list:
1024 if(line.length < 0.000000001): 2442 if(line.length < 0.000000001):
1025 flen = "" 2443 flen = ''
1026 else: 2444 else:
1027 flen = "(%.3f ms)" % (line.length*1000) 2445 flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \
2446 line.time*1000)
1028 if(line.freturn and line.fcall): 2447 if(line.freturn and line.fcall):
1029 hf.write(html_func_leaf.format(line.name, flen)) 2448 hf.write(html_func_leaf.format(line.name, flen))
1030 elif(line.freturn): 2449 elif(line.freturn):
@@ -1033,96 +2452,31 @@ def createHTML():
1033 hf.write(html_func_start.format(num, line.name, flen)) 2452 hf.write(html_func_start.format(num, line.name, flen))
1034 num += 1 2453 num += 1
1035 hf.write(html_func_end) 2454 hf.write(html_func_end)
1036 hf.write("\n\n </section>\n") 2455 hf.write('\n\n </section>\n')
1037 # write the footer and close 2456 # write the footer and close
1038 addScriptCode(hf) 2457 addScriptCode(hf, testruns)
1039 hf.write("</body>\n</html>\n") 2458 hf.write('</body>\n</html>\n')
1040 hf.close() 2459 hf.close()
1041 return True 2460 return True
1042 2461
1043def addScriptCode(hf): 2462# Function: addScriptCode
1044 global data 2463# Description:
1045 2464# Adds the javascript code to the output html
1046 t0 = (data.start - data.tSuspended) * 1000 2465# Arguments:
1047 tMax = (data.end - data.tSuspended) * 1000 2466# hf: the open html file pointer
2467# testruns: array of Data objects from parseKernelLog or parseTraceLog
2468def addScriptCode(hf, testruns):
2469 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
2470 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
1048 # create an array in javascript memory with the device details 2471 # create an array in javascript memory with the device details
1049 detail = ' var bounds = [%f,%f];\n' % (t0, tMax) 2472 detail = ' var devtable = [];\n'
1050 detail += ' var d = [];\n' 2473 for data in testruns:
1051 dfmt = ' d["%s"] = { n:"%s", p:"%s", c:[%s] };\n'; 2474 topo = data.deviceTopology()
1052 for p in data.dmesg: 2475 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
1053 list = data.dmesg[p]['list'] 2476 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
1054 for d in list:
1055 parent = data.deviceParentID(d, p)
1056 idlist = data.deviceChildrenIDs(d, p)
1057 idstr = ""
1058 for i in idlist:
1059 if(idstr == ""):
1060 idstr += '"'+i+'"'
1061 else:
1062 idstr += ', '+'"'+i+'"'
1063 detail += dfmt % (list[d]['id'], d, parent, idstr)
1064
1065 # add the code which will manipulate the data in the browser 2477 # add the code which will manipulate the data in the browser
1066 script_code = \ 2478 script_code = \
1067 '<script type="text/javascript">\n'+detail+\ 2479 '<script type="text/javascript">\n'+detail+\
1068 ' var filter = [];\n'\
1069 ' var table = [];\n'\
1070 ' function deviceParent(devid) {\n'\
1071 ' var devlist = [];\n'\
1072 ' if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
1073 ' if(d[devid].p in d)\n'\
1074 ' devlist = deviceParent(d[devid].p);\n'\
1075 ' else if(d[devid].p != "")\n'\
1076 ' devlist = [d[devid].p];\n'\
1077 ' devlist[devlist.length] = d[devid].n;\n'\
1078 ' return devlist;\n'\
1079 ' }\n'\
1080 ' function deviceChildren(devid, column, row) {\n'\
1081 ' if(!(devid in d)) return;\n'\
1082 ' if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
1083 ' var cell = {name: d[devid].n, span: 1};\n'\
1084 ' var span = 0;\n'\
1085 ' if(column >= table.length) table[column] = [];\n'\
1086 ' table[column][row] = cell;\n'\
1087 ' for(var i = 0; i < d[devid].c.length; i++) {\n'\
1088 ' var cid = d[devid].c[i];\n'\
1089 ' span += deviceChildren(cid, column+1, row+span);\n'\
1090 ' }\n'\
1091 ' if(span == 0) span = 1;\n'\
1092 ' table[column][row].span = span;\n'\
1093 ' return span;\n'\
1094 ' }\n'\
1095 ' function deviceTree(devid, resume) {\n'\
1096 ' var html = "<table border=1>";\n'\
1097 ' filter = [];\n'\
1098 ' table = [];\n'\
1099 ' plist = deviceParent(devid);\n'\
1100 ' var devidx = plist.length - 1;\n'\
1101 ' for(var i = 0; i < devidx; i++)\n'\
1102 ' table[i] = [{name: plist[i], span: 1}];\n'\
1103 ' deviceChildren(devid, devidx, 0);\n'\
1104 ' for(var i = 0; i < devidx; i++)\n'\
1105 ' table[i][0].span = table[devidx][0].span;\n'\
1106 ' for(var row = 0; row < table[0][0].span; row++) {\n'\
1107 ' html += "<tr>";\n'\
1108 ' for(var col = 0; col < table.length; col++)\n'\
1109 ' if(row in table[col]) {\n'\
1110 ' var cell = table[col][row];\n'\
1111 ' var args = "";\n'\
1112 ' if(cell.span > 1)\n'\
1113 ' args += " rowspan="+cell.span;\n'\
1114 ' if((col == devidx) && (row == 0))\n'\
1115 ' args += " class=tdhl";\n'\
1116 ' if(resume)\n'\
1117 ' html += "<td"+args+">"+cell.name+" &rarr;</td>";\n'\
1118 ' else\n'\
1119 ' html += "<td"+args+">&larr; "+cell.name+"</td>";\n'\
1120 ' }\n'\
1121 ' html += "</tr>";\n'\
1122 ' }\n'\
1123 ' html += "</table>";\n'\
1124 ' return html;\n'\
1125 ' }\n'\
1126 ' function zoomTimeline() {\n'\ 2480 ' function zoomTimeline() {\n'\
1127 ' var timescale = document.getElementById("timescale");\n'\ 2481 ' var timescale = document.getElementById("timescale");\n'\
1128 ' var dmesg = document.getElementById("dmesg");\n'\ 2482 ' var dmesg = document.getElementById("dmesg");\n'\
@@ -1154,35 +2508,170 @@ def addScriptCode(hf):
1154 ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\ 2508 ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
1155 ' var pos = (tMax - s) * 100.0 / tTotal;\n'\ 2509 ' var pos = (tMax - s) * 100.0 / tTotal;\n'\
1156 ' var name = (s == 0)?"S/R":(s+"ms");\n'\ 2510 ' var name = (s == 0)?"S/R":(s+"ms");\n'\
1157 ' html += \"<div class=\\\"t\\\" style=\\\"right:\"+pos+\"%\\\">\"+name+\"</div>\";\n'\ 2511 ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\
1158 ' }\n'\ 2512 ' }\n'\
1159 ' timescale.innerHTML = html;\n'\ 2513 ' timescale.innerHTML = html;\n'\
1160 ' }\n'\ 2514 ' }\n'\
2515 ' function deviceHover() {\n'\
2516 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
2517 ' var dmesg = document.getElementById("dmesg");\n'\
2518 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2519 ' var cpu = -1;\n'\
2520 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
2521 ' cpu = parseInt(name.slice(7));\n'\
2522 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
2523 ' cpu = parseInt(name.slice(8));\n'\
2524 ' for (var i = 0; i < dev.length; i++) {\n'\
2525 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
2526 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2527 ' (name == dname))\n'\
2528 ' {\n'\
2529 ' dev[i].className = "thread hover";\n'\
2530 ' } else {\n'\
2531 ' dev[i].className = "thread";\n'\
2532 ' }\n'\
2533 ' }\n'\
2534 ' }\n'\
2535 ' function deviceUnhover() {\n'\
2536 ' var dmesg = document.getElementById("dmesg");\n'\
2537 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2538 ' for (var i = 0; i < dev.length; i++) {\n'\
2539 ' dev[i].className = "thread";\n'\
2540 ' }\n'\
2541 ' }\n'\
2542 ' function deviceTitle(title, total, cpu) {\n'\
2543 ' var prefix = "Total";\n'\
2544 ' if(total.length > 3) {\n'\
2545 ' prefix = "Average";\n'\
2546 ' total[1] = (total[1]+total[3])/2;\n'\
2547 ' total[2] = (total[2]+total[4])/2;\n'\
2548 ' }\n'\
2549 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
2550 ' var name = title.slice(0, title.indexOf(" "));\n'\
2551 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
2552 ' var driver = "";\n'\
2553 ' var tS = "<t2>(</t2>";\n'\
2554 ' var tR = "<t2>)</t2>";\n'\
2555 ' if(total[1] > 0)\n'\
2556 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
2557 ' if(total[2] > 0)\n'\
2558 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
2559 ' var s = title.indexOf("{");\n'\
2560 ' var e = title.indexOf("}");\n'\
2561 ' if((s >= 0) && (e >= 0))\n'\
2562 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
2563 ' if(total[1] > 0 && total[2] > 0)\n'\
2564 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
2565 ' else\n'\
2566 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
2567 ' return name;\n'\
2568 ' }\n'\
1161 ' function deviceDetail() {\n'\ 2569 ' function deviceDetail() {\n'\
1162 ' var devtitle = document.getElementById("devicedetail");\n'\ 2570 ' var devinfo = document.getElementById("devicedetail");\n'\
1163 ' devtitle.innerHTML = "<h1>"+this.title+"</h1>";\n'\ 2571 ' devinfo.style.display = "block";\n'\
1164 ' var devtree = document.getElementById("devicetree");\n'\ 2572 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
1165 ' devtree.innerHTML = deviceTree(this.id, (this.title.indexOf("resume") >= 0));\n'\ 2573 ' var cpu = -1;\n'\
2574 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
2575 ' cpu = parseInt(name.slice(7));\n'\
2576 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
2577 ' cpu = parseInt(name.slice(8));\n'\
2578 ' var dmesg = document.getElementById("dmesg");\n'\
2579 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2580 ' var idlist = [];\n'\
2581 ' var pdata = [[]];\n'\
2582 ' var pd = pdata[0];\n'\
2583 ' var total = [0.0, 0.0, 0.0];\n'\
2584 ' for (var i = 0; i < dev.length; i++) {\n'\
2585 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
2586 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2587 ' (name == dname))\n'\
2588 ' {\n'\
2589 ' idlist[idlist.length] = dev[i].id;\n'\
2590 ' var tidx = 1;\n'\
2591 ' if(dev[i].id[0] == "a") {\n'\
2592 ' pd = pdata[0];\n'\
2593 ' } else {\n'\
2594 ' if(pdata.length == 1) pdata[1] = [];\n'\
2595 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
2596 ' pd = pdata[1];\n'\
2597 ' tidx = 3;\n'\
2598 ' }\n'\
2599 ' var info = dev[i].title.split(" ");\n'\
2600 ' var pname = info[info.length-1];\n'\
2601 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
2602 ' total[0] += pd[pname];\n'\
2603 ' if(pname.indexOf("suspend") >= 0)\n'\
2604 ' total[tidx] += pd[pname];\n'\
2605 ' else\n'\
2606 ' total[tidx+1] += pd[pname];\n'\
2607 ' }\n'\
2608 ' }\n'\
2609 ' var devname = deviceTitle(this.title, total, cpu);\n'\
2610 ' var left = 0.0;\n'\
2611 ' for (var t = 0; t < pdata.length; t++) {\n'\
2612 ' pd = pdata[t];\n'\
2613 ' devinfo = document.getElementById("devicedetail"+t);\n'\
2614 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
2615 ' for (var i = 0; i < phases.length; i++) {\n'\
2616 ' if(phases[i].id in pd) {\n'\
2617 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
2618 ' var fs = 32;\n'\
2619 ' if(w < 8) fs = 4*w | 0;\n'\
2620 ' var fs2 = fs*3/4;\n'\
2621 ' phases[i].style.width = w+"%";\n'\
2622 ' phases[i].style.left = left+"%";\n'\
2623 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
2624 ' left += w;\n'\
2625 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
2626 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\
2627 ' phases[i].innerHTML = time+pname;\n'\
2628 ' } else {\n'\
2629 ' phases[i].style.width = "0%";\n'\
2630 ' phases[i].style.left = left+"%";\n'\
2631 ' }\n'\
2632 ' }\n'\
2633 ' }\n'\
1166 ' var cglist = document.getElementById("callgraphs");\n'\ 2634 ' var cglist = document.getElementById("callgraphs");\n'\
1167 ' if(!cglist) return;\n'\ 2635 ' if(!cglist) return;\n'\
1168 ' var cg = cglist.getElementsByClassName("atop");\n'\ 2636 ' var cg = cglist.getElementsByClassName("atop");\n'\
1169 ' for (var i = 0; i < cg.length; i++) {\n'\ 2637 ' for (var i = 0; i < cg.length; i++) {\n'\
1170 ' if(filter.indexOf(cg[i].id) >= 0) {\n'\ 2638 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
1171 ' cg[i].style.display = "block";\n'\ 2639 ' cg[i].style.display = "block";\n'\
1172 ' } else {\n'\ 2640 ' } else {\n'\
1173 ' cg[i].style.display = "none";\n'\ 2641 ' cg[i].style.display = "none";\n'\
1174 ' }\n'\ 2642 ' }\n'\
1175 ' }\n'\ 2643 ' }\n'\
1176 ' }\n'\ 2644 ' }\n'\
2645 ' function devListWindow(e) {\n'\
2646 ' var sx = e.clientX;\n'\
2647 ' if(sx > window.innerWidth - 440)\n'\
2648 ' sx = window.innerWidth - 440;\n'\
2649 ' var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\
2650 ' var win = window.open("", "_blank", cfg);\n'\
2651 ' if(window.chrome) win.moveBy(sx, 0);\n'\
2652 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
2653 ' "<style type=\\"text/css\\">"+\n'\
2654 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
2655 ' "</style>"\n'\
2656 ' var dt = devtable[0];\n'\
2657 ' if(e.target.id != "devlist1")\n'\
2658 ' dt = devtable[1];\n'\
2659 ' win.document.write(html+dt);\n'\
2660 ' }\n'\
1177 ' window.addEventListener("load", function () {\n'\ 2661 ' window.addEventListener("load", function () {\n'\
1178 ' var dmesg = document.getElementById("dmesg");\n'\ 2662 ' var dmesg = document.getElementById("dmesg");\n'\
1179 ' dmesg.style.width = "100%"\n'\ 2663 ' dmesg.style.width = "100%"\n'\
1180 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ 2664 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
1181 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ 2665 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
1182 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ 2666 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
2667 ' var devlist = document.getElementsByClassName("devlist");\n'\
2668 ' for (var i = 0; i < devlist.length; i++)\n'\
2669 ' devlist[i].onclick = devListWindow;\n'\
1183 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 2670 ' var dev = dmesg.getElementsByClassName("thread");\n'\
1184 ' for (var i = 0; i < dev.length; i++) {\n'\ 2671 ' for (var i = 0; i < dev.length; i++) {\n'\
1185 ' dev[i].onclick = deviceDetail;\n'\ 2672 ' dev[i].onclick = deviceDetail;\n'\
2673 ' dev[i].onmouseover = deviceHover;\n'\
2674 ' dev[i].onmouseout = deviceUnhover;\n'\
1186 ' }\n'\ 2675 ' }\n'\
1187 ' zoomTimeline();\n'\ 2676 ' zoomTimeline();\n'\
1188 ' });\n'\ 2677 ' });\n'\
@@ -1191,256 +2680,912 @@ def addScriptCode(hf):
1191 2680
1192# Function: executeSuspend 2681# Function: executeSuspend
1193# Description: 2682# Description:
1194# Execute system suspend through the sysfs interface 2683# Execute system suspend through the sysfs interface, then copy the output
2684# dmesg and ftrace files to the test output directory.
1195def executeSuspend(): 2685def executeSuspend():
1196 global sysvals, data 2686 global sysvals
1197 2687
1198 detectUSB() 2688 detectUSB(False)
1199 pf = open(sysvals.powerfile, 'w') 2689 t0 = time.time()*1000
1200 # clear the kernel ring buffer just as we start 2690 tp = sysvals.tpath
1201 os.system("dmesg -C") 2691 # execute however many s/r runs requested
1202 # start ftrace 2692 for count in range(1,sysvals.execcount+1):
1203 if(data.useftrace): 2693 # clear the kernel ring buffer just as we start
1204 print("START TRACING") 2694 os.system('dmesg -C')
1205 os.system("echo 1 > "+sysvals.tpath+"tracing_on") 2695 # enable callgraph ftrace only for the second run
1206 os.system("echo SUSPEND START > "+sysvals.tpath+"trace_marker") 2696 if(sysvals.usecallgraph and count == 2):
1207 # initiate suspend 2697 # set trace type
1208 if(sysvals.rtcwake): 2698 os.system('echo function_graph > '+tp+'current_tracer')
1209 print("SUSPEND START") 2699 os.system('echo "" > '+tp+'set_ftrace_filter')
1210 os.system("rtcwake -s 10 -m "+sysvals.suspendmode) 2700 # set trace format options
1211 else: 2701 os.system('echo funcgraph-abstime > '+tp+'trace_options')
1212 print("SUSPEND START (press a key to resume)") 2702 os.system('echo funcgraph-proc > '+tp+'trace_options')
2703 # focus only on device suspend and resume
2704 os.system('cat '+tp+'available_filter_functions | '+\
2705 'grep dpm_run_callback > '+tp+'set_graph_function')
2706 # if this is test2 and there's a delay, start here
2707 if(count > 1 and sysvals.x2delay > 0):
2708 tN = time.time()*1000
2709 while (tN - t0) < sysvals.x2delay:
2710 tN = time.time()*1000
2711 time.sleep(0.001)
2712 # start ftrace
2713 if(sysvals.usecallgraph or sysvals.usetraceevents):
2714 print('START TRACING')
2715 os.system('echo 1 > '+tp+'tracing_on')
2716 # initiate suspend
2717 if(sysvals.usecallgraph or sysvals.usetraceevents):
2718 os.system('echo SUSPEND START > '+tp+'trace_marker')
2719 if(sysvals.rtcwake):
2720 print('SUSPEND START')
2721 print('will autoresume in %d seconds' % sysvals.rtcwaketime)
2722 sysvals.rtcWakeAlarm()
2723 else:
2724 print('SUSPEND START (press a key to resume)')
2725 pf = open(sysvals.powerfile, 'w')
1213 pf.write(sysvals.suspendmode) 2726 pf.write(sysvals.suspendmode)
1214 # execution will pause here 2727 # execution will pause here
1215 pf.close() 2728 pf.close()
1216 # return from suspend 2729 t0 = time.time()*1000
1217 print("RESUME COMPLETE") 2730 # return from suspend
1218 # stop ftrace 2731 print('RESUME COMPLETE')
1219 if(data.useftrace): 2732 if(sysvals.usecallgraph or sysvals.usetraceevents):
1220 os.system("echo RESUME COMPLETE > "+sysvals.tpath+"trace_marker") 2733 os.system('echo RESUME COMPLETE > '+tp+'trace_marker')
1221 os.system("echo 0 > "+sysvals.tpath+"tracing_on") 2734 # see if there's firmware timing data to be had
1222 print("CAPTURING FTRACE") 2735 t = sysvals.postresumetime
1223 os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.ftracefile) 2736 if(t > 0):
1224 os.system("cat "+sysvals.tpath+"trace >> "+sysvals.ftracefile) 2737 print('Waiting %d seconds for POST-RESUME trace events...' % t)
1225 # grab a copy of the dmesg output 2738 time.sleep(t)
1226 print("CAPTURING DMESG") 2739 # stop ftrace
1227 os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.dmesgfile) 2740 if(sysvals.usecallgraph or sysvals.usetraceevents):
1228 os.system("dmesg -c >> "+sysvals.dmesgfile) 2741 os.system('echo 0 > '+tp+'tracing_on')
2742 print('CAPTURING TRACE')
2743 writeDatafileHeader(sysvals.ftracefile)
2744 os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
2745 os.system('echo "" > '+tp+'trace')
2746 # grab a copy of the dmesg output
2747 print('CAPTURING DMESG')
2748 writeDatafileHeader(sysvals.dmesgfile)
2749 os.system('dmesg -c >> '+sysvals.dmesgfile)
2750
2751def writeDatafileHeader(filename):
2752 global sysvals
2753
2754 fw = getFPDT(False)
2755 prt = sysvals.postresumetime
2756 fp = open(filename, 'a')
2757 fp.write(sysvals.teststamp+'\n')
2758 if(fw):
2759 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
2760 if(prt > 0):
2761 fp.write('# post resume time %u\n' % prt)
2762 fp.close()
2763
2764# Function: executeAndroidSuspend
2765# Description:
2766# Execute system suspend through the sysfs interface
2767# on a remote android device, then transfer the output
2768# dmesg and ftrace files to the local output directory.
2769def executeAndroidSuspend():
2770 global sysvals
2771
2772 # check to see if the display is currently off
2773 tp = sysvals.tpath
2774 out = os.popen(sysvals.adb+\
2775 ' shell dumpsys power | grep mScreenOn').read().strip()
2776 # if so we need to turn it on so we can issue a new suspend
2777 if(out.endswith('false')):
2778 print('Waking the device up for the test...')
2779 # send the KEYPAD_POWER keyevent to wake it up
2780 os.system(sysvals.adb+' shell input keyevent 26')
2781 # wait a few seconds so the user can see the device wake up
2782 time.sleep(3)
2783 # execute however many s/r runs requested
2784 for count in range(1,sysvals.execcount+1):
2785 # clear the kernel ring buffer just as we start
2786 os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1')
2787 # start ftrace
2788 if(sysvals.usetraceevents):
2789 print('START TRACING')
2790 os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'")
2791 # initiate suspend
2792 for count in range(1,sysvals.execcount+1):
2793 if(sysvals.usetraceevents):
2794 os.system(sysvals.adb+\
2795 " shell 'echo SUSPEND START > "+tp+"trace_marker'")
2796 print('SUSPEND START (press a key on the device to resume)')
2797 os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\
2798 " > "+sysvals.powerfile+"'")
2799 # execution will pause here, then adb will exit
2800 while(True):
2801 check = os.popen(sysvals.adb+\
2802 ' shell pwd 2>/dev/null').read().strip()
2803 if(len(check) > 0):
2804 break
2805 time.sleep(1)
2806 if(sysvals.usetraceevents):
2807 os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\
2808 "trace_marker'")
2809 # return from suspend
2810 print('RESUME COMPLETE')
2811 # stop ftrace
2812 if(sysvals.usetraceevents):
2813 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
2814 print('CAPTURING TRACE')
2815 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile)
2816 os.system(sysvals.adb+' shell cat '+tp+\
2817 'trace >> '+sysvals.ftracefile)
2818 # grab a copy of the dmesg output
2819 print('CAPTURING DMESG')
2820 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile)
2821 os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile)
2822
2823# Function: setUSBDevicesAuto
2824# Description:
2825# Set the autosuspend control parameter of all USB devices to auto
2826# This can be dangerous, so use at your own risk, most devices are set
2827# to always-on since the kernel cant determine if the device can
2828# properly autosuspend
2829def setUSBDevicesAuto():
2830 global sysvals
2831
2832 rootCheck()
2833 for dirname, dirnames, filenames in os.walk('/sys/devices'):
2834 if(re.match('.*/usb[0-9]*.*', dirname) and
2835 'idVendor' in filenames and 'idProduct' in filenames):
2836 os.system('echo auto > %s/power/control' % dirname)
2837 name = dirname.split('/')[-1]
2838 desc = os.popen('cat %s/product 2>/dev/null' % \
2839 dirname).read().replace('\n', '')
2840 ctrl = os.popen('cat %s/power/control 2>/dev/null' % \
2841 dirname).read().replace('\n', '')
2842 print('control is %s for %6s: %s' % (ctrl, name, desc))
2843
2844# Function: yesno
2845# Description:
2846# Print out an equivalent Y or N for a set of known parameter values
2847# Output:
2848# 'Y', 'N', or ' ' if the value is unknown
2849def yesno(val):
2850 yesvals = ['auto', 'enabled', 'active', '1']
2851 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
2852 if val in yesvals:
2853 return 'Y'
2854 elif val in novals:
2855 return 'N'
2856 return ' '
2857
2858# Function: ms2nice
2859# Description:
2860# Print out a very concise time string in minutes and seconds
2861# Output:
2862# The time string, e.g. "1901m16s"
2863def ms2nice(val):
2864 ms = 0
2865 try:
2866 ms = int(val)
2867 except:
2868 return 0.0
2869 m = ms / 60000
2870 s = (ms / 1000) - (m * 60)
2871 return '%3dm%2ds' % (m, s)
1229 2872
1230# Function: detectUSB 2873# Function: detectUSB
1231# Description: 2874# Description:
1232# Detect all the USB hosts and devices currently connected 2875# Detect all the USB hosts and devices currently connected and add
1233def detectUSB(): 2876# a list of USB device names to sysvals for better timeline readability
1234 global sysvals, data 2877# Arguments:
1235 2878# output: True to output the info to stdout, False otherwise
1236 for dirname, dirnames, filenames in os.walk("/sys/devices"): 2879def detectUSB(output):
1237 if(re.match(r".*/usb[0-9]*.*", dirname) and 2880 global sysvals
1238 "idVendor" in filenames and "idProduct" in filenames): 2881
1239 vid = os.popen("cat %s/idVendor 2>/dev/null" % dirname).read().replace('\n', '') 2882 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
1240 pid = os.popen("cat %s/idProduct 2>/dev/null" % dirname).read().replace('\n', '') 2883 power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
1241 product = os.popen("cat %s/product 2>/dev/null" % dirname).read().replace('\n', '') 2884 'control':'', 'persist':'', 'runtime_enabled':'',
2885 'runtime_status':'', 'runtime_usage':'',
2886 'runtime_active_time':'',
2887 'runtime_suspended_time':'',
2888 'active_duration':'',
2889 'connected_duration':''}
2890 if(output):
2891 print('LEGEND')
2892 print('---------------------------------------------------------------------------------------------')
2893 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
2894 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
2895 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
2896 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
2897 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
2898 print(' U = runtime usage count')
2899 print('---------------------------------------------------------------------------------------------')
2900 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
2901 print('---------------------------------------------------------------------------------------------')
2902
2903 for dirname, dirnames, filenames in os.walk('/sys/devices'):
2904 if(re.match('.*/usb[0-9]*.*', dirname) and
2905 'idVendor' in filenames and 'idProduct' in filenames):
2906 for i in field:
2907 field[i] = os.popen('cat %s/%s 2>/dev/null' % \
2908 (dirname, i)).read().replace('\n', '')
1242 name = dirname.split('/')[-1] 2909 name = dirname.split('/')[-1]
1243 if(len(product) > 0): 2910 if(len(field['product']) > 0):
1244 data.altdevname[name] = "%s [%s]" % (product, name) 2911 sysvals.altdevname[name] = \
2912 '%s [%s]' % (field['product'], name)
1245 else: 2913 else:
1246 data.altdevname[name] = "%s:%s [%s]" % (vid, pid, name) 2914 sysvals.altdevname[name] = \
1247 2915 '%s:%s [%s]' % (field['idVendor'], \
2916 field['idProduct'], name)
2917 if(output):
2918 for i in power:
2919 power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
2920 (dirname, i)).read().replace('\n', '')
2921 if(re.match('usb[0-9]*', name)):
2922 first = '%-8s' % name
2923 else:
2924 first = '%8s' % name
2925 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
2926 (first, field['idVendor'], field['idProduct'], \
2927 field['product'][0:20], field['speed'], \
2928 yesno(power['async']), \
2929 yesno(power['control']), \
2930 yesno(power['persist']), \
2931 yesno(power['runtime_enabled']), \
2932 yesno(power['runtime_status']), \
2933 power['runtime_usage'], \
2934 power['autosuspend'], \
2935 ms2nice(power['runtime_active_time']), \
2936 ms2nice(power['runtime_suspended_time']), \
2937 ms2nice(power['active_duration']), \
2938 ms2nice(power['connected_duration'])))
2939
2940# Function: getModes
2941# Description:
2942# Determine the supported power modes on this system
2943# Output:
2944# A string list of the available modes
1248def getModes(): 2945def getModes():
1249 global sysvals 2946 global sysvals
1250 modes = "" 2947 modes = ''
1251 if(os.path.exists(sysvals.powerfile)): 2948 if(not sysvals.android):
1252 fp = open(sysvals.powerfile, 'r') 2949 if(os.path.exists(sysvals.powerfile)):
1253 modes = string.split(fp.read()) 2950 fp = open(sysvals.powerfile, 'r')
1254 fp.close() 2951 modes = string.split(fp.read())
2952 fp.close()
2953 else:
2954 line = os.popen(sysvals.adb+' shell cat '+\
2955 sysvals.powerfile).read().strip()
2956 modes = string.split(line)
1255 return modes 2957 return modes
1256 2958
2959# Function: getFPDT
2960# Description:
2961# Read the acpi bios tables and pull out FPDT, the firmware data
2962# Arguments:
2963# output: True to output the info to stdout, False otherwise
2964def getFPDT(output):
2965 global sysvals
2966
2967 rectype = {}
2968 rectype[0] = 'Firmware Basic Boot Performance Record'
2969 rectype[1] = 'S3 Performance Table Record'
2970 prectype = {}
2971 prectype[0] = 'Basic S3 Resume Performance Record'
2972 prectype[1] = 'Basic S3 Suspend Performance Record'
2973
2974 rootCheck()
2975 if(not os.path.exists(sysvals.fpdtpath)):
2976 if(output):
2977 doError('file doesnt exist: %s' % sysvals.fpdtpath, False)
2978 return False
2979 if(not os.access(sysvals.fpdtpath, os.R_OK)):
2980 if(output):
2981 doError('file isnt readable: %s' % sysvals.fpdtpath, False)
2982 return False
2983 if(not os.path.exists(sysvals.mempath)):
2984 if(output):
2985 doError('file doesnt exist: %s' % sysvals.mempath, False)
2986 return False
2987 if(not os.access(sysvals.mempath, os.R_OK)):
2988 if(output):
2989 doError('file isnt readable: %s' % sysvals.mempath, False)
2990 return False
2991
2992 fp = open(sysvals.fpdtpath, 'rb')
2993 buf = fp.read()
2994 fp.close()
2995
2996 if(len(buf) < 36):
2997 if(output):
2998 doError('Invalid FPDT table data, should '+\
2999 'be at least 36 bytes', False)
3000 return False
3001
3002 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
3003 if(output):
3004 print('')
3005 print('Firmware Performance Data Table (%s)' % table[0])
3006 print(' Signature : %s' % table[0])
3007 print(' Table Length : %u' % table[1])
3008 print(' Revision : %u' % table[2])
3009 print(' Checksum : 0x%x' % table[3])
3010 print(' OEM ID : %s' % table[4])
3011 print(' OEM Table ID : %s' % table[5])
3012 print(' OEM Revision : %u' % table[6])
3013 print(' Creator ID : %s' % table[7])
3014 print(' Creator Revision : 0x%x' % table[8])
3015 print('')
3016
3017 if(table[0] != 'FPDT'):
3018 if(output):
3019 doError('Invalid FPDT table')
3020 return False
3021 if(len(buf) <= 36):
3022 return False
3023 i = 0
3024 fwData = [0, 0]
3025 records = buf[36:]
3026 fp = open(sysvals.mempath, 'rb')
3027 while(i < len(records)):
3028 header = struct.unpack('HBB', records[i:i+4])
3029 if(header[0] not in rectype):
3030 continue
3031 if(header[1] != 16):
3032 continue
3033 addr = struct.unpack('Q', records[i+8:i+16])[0]
3034 try:
3035 fp.seek(addr)
3036 first = fp.read(8)
3037 except:
3038 doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False)
3039 rechead = struct.unpack('4sI', first)
3040 recdata = fp.read(rechead[1]-8)
3041 if(rechead[0] == 'FBPT'):
3042 record = struct.unpack('HBBIQQQQQ', recdata)
3043 if(output):
3044 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3045 print(' Reset END : %u ns' % record[4])
3046 print(' OS Loader LoadImage Start : %u ns' % record[5])
3047 print(' OS Loader StartImage Start : %u ns' % record[6])
3048 print(' ExitBootServices Entry : %u ns' % record[7])
3049 print(' ExitBootServices Exit : %u ns' % record[8])
3050 elif(rechead[0] == 'S3PT'):
3051 if(output):
3052 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3053 j = 0
3054 while(j < len(recdata)):
3055 prechead = struct.unpack('HBB', recdata[j:j+4])
3056 if(prechead[0] not in prectype):
3057 continue
3058 if(prechead[0] == 0):
3059 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
3060 fwData[1] = record[2]
3061 if(output):
3062 print(' %s' % prectype[prechead[0]])
3063 print(' Resume Count : %u' % \
3064 record[1])
3065 print(' FullResume : %u ns' % \
3066 record[2])
3067 print(' AverageResume : %u ns' % \
3068 record[3])
3069 elif(prechead[0] == 1):
3070 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
3071 fwData[0] = record[1] - record[0]
3072 if(output):
3073 print(' %s' % prectype[prechead[0]])
3074 print(' SuspendStart : %u ns' % \
3075 record[0])
3076 print(' SuspendEnd : %u ns' % \
3077 record[1])
3078 print(' SuspendTime : %u ns' % \
3079 fwData[0])
3080 j += prechead[1]
3081 if(output):
3082 print('')
3083 i += header[1]
3084 fp.close()
3085 return fwData
3086
1257# Function: statusCheck 3087# Function: statusCheck
1258# Description: 3088# Description:
1259# Verify that the requested command and options will work 3089# Verify that the requested command and options will work, and
1260def statusCheck(dryrun): 3090# print the results to the terminal
1261 global sysvals, data 3091# Output:
1262 res = dict() 3092# True if the test will work, False if not
3093def statusCheck():
3094 global sysvals
3095 status = True
1263 3096
1264 if(data.notestrun): 3097 if(sysvals.android):
1265 print("SUCCESS: The command should run!") 3098 print('Checking the android system ...')
1266 return 3099 else:
3100 print('Checking this system (%s)...' % platform.node())
3101
3102 # check if adb is connected to a device
3103 if(sysvals.android):
3104 res = 'NO'
3105 out = os.popen(sysvals.adb+' get-state').read().strip()
3106 if(out == 'device'):
3107 res = 'YES'
3108 print(' is android device connected: %s' % res)
3109 if(res != 'YES'):
3110 print(' Please connect the device before using this tool')
3111 return False
1267 3112
1268 # check we have root access 3113 # check we have root access
1269 check = "YES" 3114 res = 'NO (No features of this tool will work!)'
1270 if(os.environ['USER'] != "root"): 3115 if(sysvals.android):
1271 if(not dryrun): 3116 out = os.popen(sysvals.adb+' shell id').read().strip()
1272 doError("root access is required", False) 3117 if('root' in out):
1273 check = "NO" 3118 res = 'YES'
1274 res[" have root access: "] = check 3119 else:
3120 if(os.environ['USER'] == 'root'):
3121 res = 'YES'
3122 print(' have root access: %s' % res)
3123 if(res != 'YES'):
3124 if(sysvals.android):
3125 print(' Try running "adb root" to restart the daemon as root')
3126 else:
3127 print(' Try running this script with sudo')
3128 return False
1275 3129
1276 # check sysfs is mounted 3130 # check sysfs is mounted
1277 check = "YES" 3131 res = 'NO (No features of this tool will work!)'
1278 if(not os.path.exists(sysvals.powerfile)): 3132 if(sysvals.android):
1279 if(not dryrun): 3133 out = os.popen(sysvals.adb+' shell ls '+\
1280 doError("sysfs must be mounted", False) 3134 sysvals.powerfile).read().strip()
1281 check = "NO" 3135 if(out == sysvals.powerfile):
1282 res[" is sysfs mounted: "] = check 3136 res = 'YES'
3137 else:
3138 if(os.path.exists(sysvals.powerfile)):
3139 res = 'YES'
3140 print(' is sysfs mounted: %s' % res)
3141 if(res != 'YES'):
3142 return False
1283 3143
1284 # check target mode is a valid mode 3144 # check target mode is a valid mode
1285 check = "YES" 3145 res = 'NO'
1286 modes = getModes() 3146 modes = getModes()
1287 if(sysvals.suspendmode not in modes): 3147 if(sysvals.suspendmode in modes):
1288 if(not dryrun): 3148 res = 'YES'
1289 doError("%s is not a value power mode" % sysvals.suspendmode, False) 3149 else:
1290 check = "NO" 3150 status = False
1291 res[" is "+sysvals.suspendmode+" a power mode: "] = check 3151 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
3152 if(res == 'NO'):
3153 print(' valid power modes are: %s' % modes)
3154 print(' please choose one with -m')
3155
3156 # check if the tool can unlock the device
3157 if(sysvals.android):
3158 res = 'YES'
3159 out1 = os.popen(sysvals.adb+\
3160 ' shell dumpsys power | grep mScreenOn').read().strip()
3161 out2 = os.popen(sysvals.adb+\
3162 ' shell input').read().strip()
3163 if(not out1.startswith('mScreenOn') or not out2.startswith('usage')):
3164 res = 'NO (wake the android device up before running the test)'
3165 print(' can I unlock the screen: %s' % res)
1292 3166
1293 # check if ftrace is available 3167 # check if ftrace is available
1294 if(data.useftrace): 3168 res = 'NO'
1295 check = "YES" 3169 ftgood = verifyFtrace()
1296 if(not verifyFtrace()): 3170 if(ftgood):
1297 if(not dryrun): 3171 res = 'YES'
1298 doError("ftrace is not configured", False) 3172 elif(sysvals.usecallgraph):
1299 check = "NO" 3173 status = False
1300 res[" is ftrace usable: "] = check 3174 print(' is ftrace supported: %s' % res)
3175
3176 # what data source are we using
3177 res = 'DMESG'
3178 if(ftgood):
3179 sysvals.usetraceeventsonly = True
3180 sysvals.usetraceevents = False
3181 for e in sysvals.traceevents:
3182 check = False
3183 if(sysvals.android):
3184 out = os.popen(sysvals.adb+' shell ls -d '+\
3185 sysvals.epath+e).read().strip()
3186 if(out == sysvals.epath+e):
3187 check = True
3188 else:
3189 if(os.path.exists(sysvals.epath+e)):
3190 check = True
3191 if(not check):
3192 sysvals.usetraceeventsonly = False
3193 if(e == 'suspend_resume' and check):
3194 sysvals.usetraceevents = True
3195 if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
3196 res = 'FTRACE (all trace events found)'
3197 elif(sysvals.usetraceevents):
3198 res = 'DMESG and FTRACE (suspend_resume trace event found)'
3199 print(' timeline data source: %s' % res)
1301 3200
1302 # check if rtcwake 3201 # check if rtcwake
1303 if(sysvals.rtcwake): 3202 res = 'NO'
1304 check = "YES" 3203 if(sysvals.rtcpath != ''):
1305 version = os.popen("rtcwake -V 2>/dev/null").read() 3204 res = 'YES'
1306 if(not version.startswith("rtcwake")): 3205 elif(sysvals.rtcwake):
1307 if(not dryrun): 3206 status = False
1308 doError("rtcwake is not installed", False) 3207 print(' is rtcwake supported: %s' % res)
1309 check = "NO"
1310 res[" is rtcwake usable: "] = check
1311
1312 if(dryrun):
1313 status = True
1314 print("Checking if system can run the current command:")
1315 for r in res:
1316 print("%s\t%s" % (r, res[r]))
1317 if(res[r] != "YES"):
1318 status = False
1319 if(status):
1320 print("SUCCESS: The command should run!")
1321 else:
1322 print("FAILURE: The command won't run!")
1323 3208
1324def printHelp(): 3209 return status
1325 global sysvals
1326 modes = getModes()
1327
1328 print("")
1329 print("AnalyzeSuspend")
1330 print("Usage: sudo analyze_suspend.py <options>")
1331 print("")
1332 print("Description:")
1333 print(" Initiates a system suspend/resume while capturing dmesg")
1334 print(" and (optionally) ftrace data to analyze device timing")
1335 print("")
1336 print(" Generates output files in subdirectory: suspend-mmddyy-HHMMSS")
1337 print(" HTML output: <hostname>_<mode>.html")
1338 print(" raw dmesg output: <hostname>_<mode>_dmesg.txt")
1339 print(" raw ftrace output (with -f): <hostname>_<mode>_ftrace.txt")
1340 print("")
1341 print("Options:")
1342 print(" [general]")
1343 print(" -h Print this help text")
1344 print(" -verbose Print extra information during execution and analysis")
1345 print(" -status Test to see if the system is enabled to run this tool")
1346 print(" -modes List available suspend modes")
1347 print(" -m mode Mode to initiate for suspend %s (default: %s)") % (modes, sysvals.suspendmode)
1348 print(" -rtcwake Use rtcwake to autoresume after 10 seconds (default: disabled)")
1349 print(" -f Use ftrace to create device callgraphs (default: disabled)")
1350 print(" [re-analyze data from previous runs]")
1351 print(" -dmesg dmesgfile Create HTML timeline from dmesg file")
1352 print(" -ftrace ftracefile Create HTML callgraph from ftrace file")
1353 print("")
1354 return True
1355 3210
3211# Function: doError
3212# Description:
3213# generic error function for catastrphic failures
3214# Arguments:
3215# msg: the error message to print
3216# help: True if printHelp should be called after, False otherwise
1356def doError(msg, help): 3217def doError(msg, help):
1357 print("ERROR: %s") % msg
1358 if(help == True): 3218 if(help == True):
1359 printHelp() 3219 printHelp()
3220 print('ERROR: %s\n') % msg
1360 sys.exit() 3221 sys.exit()
1361 3222
1362# -- script main -- 3223# Function: doWarning
1363# loop through the command line arguments 3224# Description:
1364cmd = "" 3225# generic warning function for non-catastrophic anomalies
1365args = iter(sys.argv[1:]) 3226# Arguments:
1366for arg in args: 3227# msg: the warning message to print
1367 if(arg == "-m"): 3228# file: If not empty, a filename to request be sent to the owner for debug
1368 try: 3229def doWarning(msg, file):
1369 val = args.next() 3230 print('/* %s */') % msg
1370 except: 3231 if(file):
1371 doError("No mode supplied", True) 3232 print('/* For a fix, please send this'+\
1372 sysvals.suspendmode = val 3233 ' %s file to <todd.e.brandt@intel.com> */' % file)
1373 elif(arg == "-f"): 3234
1374 data.useftrace = True 3235# Function: rootCheck
1375 elif(arg == "-modes"): 3236# Description:
1376 cmd = "modes" 3237# quick check to see if we have root access
1377 elif(arg == "-status"): 3238def rootCheck():
1378 cmd = "status" 3239 if(os.environ['USER'] != 'root'):
1379 elif(arg == "-verbose"): 3240 doError('This script must be run as root', False)
1380 data.verbose = True
1381 elif(arg == "-rtcwake"):
1382 sysvals.rtcwake = True
1383 elif(arg == "-dmesg"):
1384 try:
1385 val = args.next()
1386 except:
1387 doError("No dmesg file supplied", True)
1388 data.notestrun = True
1389 data.usedmesg = True
1390 sysvals.dmesgfile = val
1391 elif(arg == "-ftrace"):
1392 try:
1393 val = args.next()
1394 except:
1395 doError("No ftrace file supplied", True)
1396 data.notestrun = True
1397 data.useftrace = True
1398 sysvals.ftracefile = val
1399 elif(arg == "-h"):
1400 printHelp()
1401 sys.exit()
1402 else:
1403 doError("Invalid argument: "+arg, True)
1404
1405# just run a utility command and exit
1406if(cmd != ""):
1407 if(cmd == "status"):
1408 statusCheck(True)
1409 elif(cmd == "modes"):
1410 modes = getModes()
1411 print modes
1412 sys.exit()
1413 3241
1414data.initialize() 3242# Function: getArgInt
3243# Description:
3244# pull out an integer argument from the command line with checks
3245def getArgInt(name, args, min, max):
3246 try:
3247 arg = args.next()
3248 except:
3249 doError(name+': no argument supplied', True)
3250 try:
3251 val = int(arg)
3252 except:
3253 doError(name+': non-integer value given', True)
3254 if(val < min or val > max):
3255 doError(name+': value should be between %d and %d' % (min, max), True)
3256 return val
3257
3258# Function: rerunTest
3259# Description:
3260# generate an output from an existing set of ftrace/dmesg logs
3261def rerunTest():
3262 global sysvals
1415 3263
1416# if instructed, re-analyze existing data files 3264 if(sysvals.ftracefile != ''):
1417if(data.notestrun): 3265 doesTraceLogHaveTraceEvents()
3266 if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly):
3267 doError('recreating this html output '+\
3268 'requires a dmesg file', False)
1418 sysvals.setOutputFile() 3269 sysvals.setOutputFile()
1419 data.vprint("Output file: %s" % sysvals.htmlfile) 3270 vprint('Output file: %s' % sysvals.htmlfile)
1420 if(sysvals.dmesgfile != ""): 3271 print('PROCESSING DATA')
1421 analyzeKernelLog() 3272 if(sysvals.usetraceeventsonly):
1422 if(sysvals.ftracefile != ""): 3273 testruns = parseTraceLog()
1423 analyzeTraceLog() 3274 else:
1424 createHTML() 3275 testruns = loadKernelLog()
1425 sys.exit() 3276 for data in testruns:
3277 parseKernelLog(data)
3278 if(sysvals.ftracefile != ''):
3279 appendIncompleteTraceLog(testruns)
3280 createHTML(testruns)
3281
3282# Function: runTest
3283# Description:
3284# execute a suspend/resume, gather the logs, and generate the output
3285def runTest(subdir):
3286 global sysvals
3287
3288 # prepare for the test
3289 if(not sysvals.android):
3290 initFtrace()
3291 else:
3292 initFtraceAndroid()
3293 sysvals.initTestOutput(subdir)
3294
3295 vprint('Output files:\n %s' % sysvals.dmesgfile)
3296 if(sysvals.usecallgraph or
3297 sysvals.usetraceevents or
3298 sysvals.usetraceeventsonly):
3299 vprint(' %s' % sysvals.ftracefile)
3300 vprint(' %s' % sysvals.htmlfile)
3301
3302 # execute the test
3303 if(not sysvals.android):
3304 executeSuspend()
3305 else:
3306 executeAndroidSuspend()
3307
3308 # analyze the data and create the html output
3309 print('PROCESSING DATA')
3310 if(sysvals.usetraceeventsonly):
3311 # data for kernels 3.15 or newer is entirely in ftrace
3312 testruns = parseTraceLog()
3313 else:
3314 # data for kernels older than 3.15 is primarily in dmesg
3315 testruns = loadKernelLog()
3316 for data in testruns:
3317 parseKernelLog(data)
3318 if(sysvals.usecallgraph or sysvals.usetraceevents):
3319 appendIncompleteTraceLog(testruns)
3320 createHTML(testruns)
3321
3322# Function: runSummary
3323# Description:
3324# create a summary of tests in a sub-directory
3325def runSummary(subdir, output):
3326 global sysvals
3327
3328 # get a list of ftrace output files
3329 files = []
3330 for dirname, dirnames, filenames in os.walk(subdir):
3331 for filename in filenames:
3332 if(re.match('.*_ftrace.txt', filename)):
3333 files.append("%s/%s" % (dirname, filename))
3334
3335 # process the files in order and get an array of data objects
3336 testruns = []
3337 for file in sorted(files):
3338 if output:
3339 print("Test found in %s" % os.path.dirname(file))
3340 sysvals.ftracefile = file
3341 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt')
3342 doesTraceLogHaveTraceEvents()
3343 sysvals.usecallgraph = False
3344 if not sysvals.usetraceeventsonly:
3345 if(not os.path.exists(sysvals.dmesgfile)):
3346 print("Skipping %s: not a valid test input" % file)
3347 continue
3348 else:
3349 if output:
3350 f = os.path.basename(sysvals.ftracefile)
3351 d = os.path.basename(sysvals.dmesgfile)
3352 print("\tInput files: %s and %s" % (f, d))
3353 testdata = loadKernelLog()
3354 data = testdata[0]
3355 parseKernelLog(data)
3356 testdata = [data]
3357 appendIncompleteTraceLog(testdata)
3358 else:
3359 if output:
3360 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
3361 testdata = parseTraceLog()
3362 data = testdata[0]
3363 data.normalizeTime(data.tSuspended)
3364 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
3365 data.outfile = link
3366 testruns.append(data)
3367
3368 createHTMLSummarySimple(testruns, subdir+'/summary.html')
3369
3370# Function: printHelp
3371# Description:
3372# print out the help text
3373def printHelp():
3374 global sysvals
3375 modes = getModes()
3376
3377 print('')
3378 print('AnalyzeSuspend v%.1f' % sysvals.version)
3379 print('Usage: sudo analyze_suspend.py <options>')
3380 print('')
3381 print('Description:')
3382 print(' This tool is designed to assist kernel and OS developers in optimizing')
3383 print(' their linux stack\'s suspend/resume time. Using a kernel image built')
3384 print(' with a few extra options enabled, the tool will execute a suspend and')
3385 print(' capture dmesg and ftrace data until resume is complete. This data is')
3386 print(' transformed into a device timeline and an optional callgraph to give')
3387 print(' a detailed view of which devices/subsystems are taking the most')
3388 print(' time in suspend/resume.')
3389 print('')
3390 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
3391 print(' HTML output: <hostname>_<mode>.html')
3392 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
3393 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
3394 print('')
3395 print('Options:')
3396 print(' [general]')
3397 print(' -h Print this help text')
3398 print(' -v Print the current tool version')
3399 print(' -verbose Print extra information during execution and analysis')
3400 print(' -status Test to see if the system is enabled to run this tool')
3401 print(' -modes List available suspend modes')
3402 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
3403 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
3404 print(' [advanced]')
3405 print(' -f Use ftrace to create device callgraphs (default: disabled)')
3406 print(' -filter "d1 d2 ..." Filter out all but this list of dev names')
3407 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
3408 print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
3409 print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)')
3410 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
3411 print(' be created in a new subdirectory with a summary page.')
3412 print(' [utilities]')
3413 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
3414 print(' -usbtopo Print out the current USB topology with power info')
3415 print(' -usbauto Enable autosuspend for all connected USB devices')
3416 print(' [android testing]')
3417 print(' -adb binary Use the given adb binary to run the test on an android device.')
3418 print(' The device should already be connected and with root access.')
3419 print(' Commands will be executed on the device using "adb shell"')
3420 print(' [re-analyze data from previous runs]')
3421 print(' -ftrace ftracefile Create HTML output using ftrace input')
3422 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)')
3423 print(' -summary directory Create a summary of all test in this dir')
3424 print('')
3425 return True
1426 3426
1427# verify that we can run a test 3427# ----------------- MAIN --------------------
1428data.usedmesg = True 3428# exec start (skipped if script is loaded as library)
1429statusCheck(False) 3429if __name__ == '__main__':
1430 3430 cmd = ''
1431# prepare for the test 3431 cmdarg = ''
1432if(data.useftrace): 3432 multitest = {'run': False, 'count': 0, 'delay': 0}
1433 initFtrace() 3433 # loop through the command line arguments
1434sysvals.initTestOutput() 3434 args = iter(sys.argv[1:])
1435 3435 for arg in args:
1436data.vprint("Output files:\n %s" % sysvals.dmesgfile) 3436 if(arg == '-m'):
1437if(data.useftrace): 3437 try:
1438 data.vprint(" %s" % sysvals.ftracefile) 3438 val = args.next()
1439data.vprint(" %s" % sysvals.htmlfile) 3439 except:
1440 3440 doError('No mode supplied', True)
1441# execute the test 3441 sysvals.suspendmode = val
1442executeSuspend() 3442 elif(arg == '-adb'):
1443analyzeKernelLog() 3443 try:
1444if(data.useftrace): 3444 val = args.next()
1445 analyzeTraceLog() 3445 except:
1446createHTML() 3446 doError('No adb binary supplied', True)
3447 if(not os.path.exists(val)):
3448 doError('file doesnt exist: %s' % val, False)
3449 if(not os.access(val, os.X_OK)):
3450 doError('file isnt executable: %s' % val, False)
3451 try:
3452 check = os.popen(val+' version').read().strip()
3453 except:
3454 doError('adb version failed to execute', False)
3455 if(not re.match('Android Debug Bridge .*', check)):
3456 doError('adb version failed to execute', False)
3457 sysvals.adb = val
3458 sysvals.android = True
3459 elif(arg == '-x2'):
3460 if(sysvals.postresumetime > 0):
3461 doError('-x2 is not compatible with -postres', False)
3462 sysvals.execcount = 2
3463 elif(arg == '-x2delay'):
3464 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
3465 elif(arg == '-postres'):
3466 if(sysvals.execcount != 1):
3467 doError('-x2 is not compatible with -postres', False)
3468 sysvals.postresumetime = getArgInt('-postres', args, 0, 3600)
3469 elif(arg == '-f'):
3470 sysvals.usecallgraph = True
3471 elif(arg == '-modes'):
3472 cmd = 'modes'
3473 elif(arg == '-fpdt'):
3474 cmd = 'fpdt'
3475 elif(arg == '-usbtopo'):
3476 cmd = 'usbtopo'
3477 elif(arg == '-usbauto'):
3478 cmd = 'usbauto'
3479 elif(arg == '-status'):
3480 cmd = 'status'
3481 elif(arg == '-verbose'):
3482 sysvals.verbose = True
3483 elif(arg == '-v'):
3484 print("Version %.1f" % sysvals.version)
3485 sys.exit()
3486 elif(arg == '-rtcwake'):
3487 sysvals.rtcwake = True
3488 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
3489 elif(arg == '-multi'):
3490 multitest['run'] = True
3491 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
3492 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
3493 elif(arg == '-dmesg'):
3494 try:
3495 val = args.next()
3496 except:
3497 doError('No dmesg file supplied', True)
3498 sysvals.notestrun = True
3499 sysvals.dmesgfile = val
3500 if(os.path.exists(sysvals.dmesgfile) == False):
3501 doError('%s doesnt exist' % sysvals.dmesgfile, False)
3502 elif(arg == '-ftrace'):
3503 try:
3504 val = args.next()
3505 except:
3506 doError('No ftrace file supplied', True)
3507 sysvals.notestrun = True
3508 sysvals.usecallgraph = True
3509 sysvals.ftracefile = val
3510 if(os.path.exists(sysvals.ftracefile) == False):
3511 doError('%s doesnt exist' % sysvals.ftracefile, False)
3512 elif(arg == '-summary'):
3513 try:
3514 val = args.next()
3515 except:
3516 doError('No directory supplied', True)
3517 cmd = 'summary'
3518 cmdarg = val
3519 sysvals.notestrun = True
3520 if(os.path.isdir(val) == False):
3521 doError('%s isnt accesible' % val, False)
3522 elif(arg == '-filter'):
3523 try:
3524 val = args.next()
3525 except:
3526 doError('No devnames supplied', True)
3527 sysvals.setDeviceFilter(val)
3528 elif(arg == '-h'):
3529 printHelp()
3530 sys.exit()
3531 else:
3532 doError('Invalid argument: '+arg, True)
3533
3534 # just run a utility command and exit
3535 if(cmd != ''):
3536 if(cmd == 'status'):
3537 statusCheck()
3538 elif(cmd == 'fpdt'):
3539 if(sysvals.android):
3540 doError('cannot read FPDT on android device', False)
3541 getFPDT(True)
3542 elif(cmd == 'usbtopo'):
3543 if(sysvals.android):
3544 doError('cannot read USB topology '+\
3545 'on an android device', False)
3546 detectUSB(True)
3547 elif(cmd == 'modes'):
3548 modes = getModes()
3549 print modes
3550 elif(cmd == 'usbauto'):
3551 setUSBDevicesAuto()
3552 elif(cmd == 'summary'):
3553 print("Generating a summary of folder \"%s\"" % cmdarg)
3554 runSummary(cmdarg, True)
3555 sys.exit()
3556
3557 # run test on android device
3558 if(sysvals.android):
3559 if(sysvals.usecallgraph):
3560 doError('ftrace (-f) is not yet supported '+\
3561 'in the android kernel', False)
3562 if(sysvals.notestrun):
3563 doError('cannot analyze test files on the '+\
3564 'android device', False)
3565
3566 # if instructed, re-analyze existing data files
3567 if(sysvals.notestrun):
3568 rerunTest()
3569 sys.exit()
3570
3571 # verify that we can run a test
3572 if(not statusCheck()):
3573 print('Check FAILED, aborting the test run!')
3574 sys.exit()
3575
3576 if multitest['run']:
3577 # run multiple tests in a separte subdirectory
3578 s = 'x%d' % multitest['count']
3579 subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
3580 os.mkdir(subdir)
3581 for i in range(multitest['count']):
3582 if(i != 0):
3583 print('Waiting %d seconds...' % (multitest['delay']))
3584 time.sleep(multitest['delay'])
3585 print('TEST (%d/%d) START' % (i+1, multitest['count']))
3586 runTest(subdir)
3587 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
3588 runSummary(subdir, False)
3589 else:
3590 # run the test in the current directory
3591 runTest(".")