diff options
author | Todd E Brandt <todd.e.brandt@linux.intel.com> | 2014-08-08 12:11:59 -0400 |
---|---|---|
committer | Rafael J. Wysocki <rafael.j.wysocki@intel.com> | 2014-08-08 20:47:58 -0400 |
commit | b8432c6fc12bdf4a6921e1640d3ead23fcd04c10 (patch) | |
tree | d1aa177cf8a1ee8717d8fa1e9812b1e7537059ca /scripts/analyze_suspend.py | |
parent | 059802f961db9717412b6958111ca1cd1865726e (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-x | scripts/analyze_suspend.py | 3817 |
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 | |||
44 | import sys | 47 | import sys |
45 | import time | 48 | import time |
46 | import os | 49 | import os |
47 | import string | 50 | import string |
48 | import re | 51 | import re |
49 | import array | ||
50 | import platform | 52 | import platform |
51 | import datetime | 53 | from datetime import datetime |
52 | import struct | 54 | import 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 | ||
56 | class SystemValues: | 62 | class 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 | ||
176 | sysvals = 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() | ||
182 | class 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 | # | ||
92 | class Data: | 214 | class 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 | ||
596 | class 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 | ||
253 | class FTraceLine: | 620 | class 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 | ||
306 | class FTraceCallGraph: | 702 | class 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. | ||
388 | class Timeline: | 824 | class 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. | ||
850 | class 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 | ||
412 | sysvals = SystemValues() | 884 | # ----------------- FUNCTIONS -------------------- |
413 | data = 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 | ||
891 | def 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 |
420 | def initFtrace(): | 899 | def 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 | ||
937 | def 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 | ||
445 | def verifyFtrace(): | 963 | def 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 | ||
455 | def 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: |
476 | def analyzeTraceLog(): | 991 | # m: the valid re.match output for the stamp line |
477 | global sysvals, data | 992 | def 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 | ||
1014 | def 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 | ||
1031 | def 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 | ||
1053 | def 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 | ||
1278 | def 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 |
558 | def sortKernelLog(): | 1603 | # Output: |
559 | global sysvals, data | 1604 | # An array of empty Data objects with only their dmesgtext attributes set |
1605 | def 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 |
597 | def 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 | ||
1682 | def 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 | ||
772 | def setTimelineRows(list, sortedkeys): | 1941 | def 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 | ||
811 | def createTimeScale(t0, tMax, tSuspended): | 1982 | def 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 | ||
2023 | def 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 |
851 | def 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 | ||
2156 | def 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}"> {2}</div>\n' | 2175 | html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {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, "_", " ") | 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, '_', ' ') | ||
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 | ||
1043 | def 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 | ||
2468 | def 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+" →</td>";\n'\ | ||
1118 | ' else\n'\ | ||
1119 | ' html += "<td"+args+">← "+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. | ||
1195 | def executeSuspend(): | 2685 | def 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 | |||
2751 | def 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. | ||
2769 | def 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 | ||
2829 | def 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 | ||
2849 | def 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" | ||
2863 | def 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 |
1233 | def 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"): | 2879 | def 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 | ||
1248 | def getModes(): | 2945 | def 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 | ||
2964 | def 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 |
1260 | def 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 |
3093 | def 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 | ||
1324 | def 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 | ||
1356 | def doError(msg, help): | 3217 | def 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: |
1364 | cmd = "" | 3225 | # generic warning function for non-catastrophic anomalies |
1365 | args = iter(sys.argv[1:]) | 3226 | # Arguments: |
1366 | for 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: | 3229 | def 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"): | 3238 | def 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 | ||
1406 | if(cmd != ""): | ||
1407 | if(cmd == "status"): | ||
1408 | statusCheck(True) | ||
1409 | elif(cmd == "modes"): | ||
1410 | modes = getModes() | ||
1411 | print modes | ||
1412 | sys.exit() | ||
1413 | 3241 | ||
1414 | data.initialize() | 3242 | # Function: getArgInt |
3243 | # Description: | ||
3244 | # pull out an integer argument from the command line with checks | ||
3245 | def 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 | ||
3261 | def rerunTest(): | ||
3262 | global sysvals | ||
1415 | 3263 | ||
1416 | # if instructed, re-analyze existing data files | 3264 | if(sysvals.ftracefile != ''): |
1417 | if(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 | ||
3285 | def 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 | ||
3325 | def 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 | ||
3373 | def 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 -------------------- |
1428 | data.usedmesg = True | 3428 | # exec start (skipped if script is loaded as library) |
1429 | statusCheck(False) | 3429 | if __name__ == '__main__': |
1430 | 3430 | cmd = '' | |
1431 | # prepare for the test | 3431 | cmdarg = '' |
1432 | if(data.useftrace): | 3432 | multitest = {'run': False, 'count': 0, 'delay': 0} |
1433 | initFtrace() | 3433 | # loop through the command line arguments |
1434 | sysvals.initTestOutput() | 3434 | args = iter(sys.argv[1:]) |
1435 | 3435 | for arg in args: | |
1436 | data.vprint("Output files:\n %s" % sysvals.dmesgfile) | 3436 | if(arg == '-m'): |
1437 | if(data.useftrace): | 3437 | try: |
1438 | data.vprint(" %s" % sysvals.ftracefile) | 3438 | val = args.next() |
1439 | data.vprint(" %s" % sysvals.htmlfile) | 3439 | except: |
1440 | 3440 | doError('No mode supplied', True) | |
1441 | # execute the test | 3441 | sysvals.suspendmode = val |
1442 | executeSuspend() | 3442 | elif(arg == '-adb'): |
1443 | analyzeKernelLog() | 3443 | try: |
1444 | if(data.useftrace): | 3444 | val = args.next() |
1445 | analyzeTraceLog() | 3445 | except: |
1446 | createHTML() | 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(".") | ||