Commit | Line | Data |
---|---|---|
ee8b09cd TB |
1 | #!/usr/bin/python |
2 | # | |
3 | # Tool for analyzing suspend/resume timing | |
4 | # Copyright (c) 2013, Intel Corporation. | |
5 | # | |
6 | # This program is free software; you can redistribute it and/or modify it | |
7 | # under the terms and conditions of the GNU General Public License, | |
8 | # version 2, as published by the Free Software Foundation. | |
9 | # | |
10 | # This program is distributed in the hope it will be useful, but WITHOUT | |
11 | # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or | |
12 | # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for | |
13 | # more details. | |
14 | # | |
15 | # You should have received a copy of the GNU General Public License along with | |
16 | # this program; if not, write to the Free Software Foundation, Inc., | |
17 | # 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA. | |
18 | # | |
19 | # Authors: | |
20 | # Todd Brandt <todd.e.brandt@linux.intel.com> | |
21 | # | |
22 | # Description: | |
23 | # This tool is designed to assist kernel and OS developers in optimizing | |
24 | # their linux stack's suspend/resume time. Using a kernel image built | |
25 | # with a few extra options enabled, the tool will execute a suspend and | |
26 | # will capture dmesg and ftrace data until resume is complete. This data | |
27 | # is transformed into a device timeline and a callgraph to give a quick | |
28 | # and detailed view of which devices and callbacks are taking the most | |
29 | # time in suspend/resume. The output is a single html file which can be | |
30 | # viewed in firefox or chrome. | |
31 | # | |
32 | # The following kernel build options are required: | |
33 | # CONFIG_PM_DEBUG=y | |
34 | # CONFIG_PM_SLEEP_DEBUG=y | |
35 | # CONFIG_FTRACE=y | |
36 | # CONFIG_FUNCTION_TRACER=y | |
37 | # CONFIG_FUNCTION_GRAPH_TRACER=y | |
38 | # | |
39 | # The following additional kernel parameters are required: | |
40 | # (e.g. in file /etc/default/grub) | |
41 | # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." | |
42 | # | |
43 | ||
44 | import sys | |
45 | import time | |
46 | import os | |
47 | import string | |
48 | import re | |
49 | import array | |
50 | import platform | |
51 | import datetime | |
52 | import struct | |
53 | ||
54 | # -- classes -- | |
55 | ||
56 | class SystemValues: | |
57 | testdir = "." | |
58 | tpath = "/sys/kernel/debug/tracing/" | |
59 | mempath = "/dev/mem" | |
60 | powerfile = "/sys/power/state" | |
61 | suspendmode = "mem" | |
62 | prefix = "test" | |
63 | teststamp = "" | |
64 | dmesgfile = "" | |
65 | ftracefile = "" | |
66 | htmlfile = "" | |
67 | rtcwake = False | |
68 | def setOutputFile(self): | |
69 | if((self.htmlfile == "") and (self.dmesgfile != "")): | |
70 | m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile) | |
71 | if(m): | |
72 | self.htmlfile = m.group("name")+".html" | |
73 | if((self.htmlfile == "") and (self.ftracefile != "")): | |
74 | m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile) | |
75 | if(m): | |
76 | self.htmlfile = m.group("name")+".html" | |
77 | if(self.htmlfile == ""): | |
78 | self.htmlfile = "output.html" | |
79 | def initTestOutput(self): | |
80 | hostname = platform.node() | |
81 | if(hostname != ""): | |
82 | self.prefix = hostname | |
83 | v = os.popen("cat /proc/version").read().strip() | |
84 | kver = string.split(v)[2] | |
85 | self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip() | |
86 | self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver | |
87 | self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt" | |
88 | self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt" | |
89 | self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html" | |
90 | os.mkdir(self.testdir) | |
91 | ||
92 | class Data: | |
93 | altdevname = dict() | |
94 | usedmesg = False | |
95 | useftrace = False | |
96 | notestrun = False | |
97 | verbose = False | |
98 | phases = [] | |
99 | dmesg = {} # root data structure | |
100 | start = 0.0 | |
101 | end = 0.0 | |
102 | stamp = {'time': "", 'host': "", 'mode': ""} | |
103 | id = 0 | |
104 | tSuspended = 0.0 | |
105 | fwValid = False | |
106 | fwSuspend = 0 | |
107 | fwResume = 0 | |
108 | def initialize(self): | |
109 | self.dmesg = { # dmesg log data | |
110 | 'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
111 | 'row': 0, 'color': "#CCFFCC", 'order': 0}, | |
112 | 'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
113 | 'row': 0, 'color': "green", 'order': 1}, | |
114 | 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
115 | 'row': 0, 'color': "#00FFFF", 'order': 2}, | |
116 | 'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
117 | 'row': 0, 'color': "blue", 'order': 3}, | |
118 | 'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
119 | 'row': 0, 'color': "red", 'order': 4}, | |
120 | 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
121 | 'row': 0, 'color': "orange", 'order': 5}, | |
122 | 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
123 | 'row': 0, 'color': "yellow", 'order': 6}, | |
124 | 'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0, | |
125 | 'row': 0, 'color': "#FFFFCC", 'order': 7} | |
126 | } | |
127 | self.phases = self.sortedPhases() | |
128 | def normalizeTime(self): | |
129 | tSus = tRes = self.tSuspended | |
130 | if self.fwValid: | |
131 | tSus -= -self.fwSuspend / 1000000000.0 | |
132 | tRes -= self.fwResume / 1000000000.0 | |
133 | self.tSuspended = 0.0 | |
134 | self.start -= tSus | |
135 | self.end -= tRes | |
136 | for phase in self.phases: | |
137 | zero = tRes | |
138 | if "suspend" in phase: | |
139 | zero = tSus | |
140 | p = self.dmesg[phase] | |
141 | p['start'] -= zero | |
142 | p['end'] -= zero | |
143 | list = p['list'] | |
144 | for name in list: | |
145 | d = list[name] | |
146 | d['start'] -= zero | |
147 | d['end'] -= zero | |
148 | if('ftrace' in d): | |
149 | cg = d['ftrace'] | |
150 | cg.start -= zero | |
151 | cg.end -= zero | |
152 | for line in cg.list: | |
153 | line.time -= zero | |
154 | if self.fwValid: | |
155 | fws = -self.fwSuspend / 1000000000.0 | |
156 | fwr = self.fwResume / 1000000000.0 | |
157 | list = dict() | |
158 | self.id += 1 | |
159 | devid = "dc%d" % self.id | |
160 | list["firmware-suspend"] = \ | |
161 | {'start': fws, 'end': 0, 'pid': 0, 'par': "", | |
162 | 'length': -fws, 'row': 0, 'id': devid }; | |
163 | self.id += 1 | |
164 | devid = "dc%d" % self.id | |
165 | list["firmware-resume"] = \ | |
166 | {'start': 0, 'end': fwr, 'pid': 0, 'par': "", | |
167 | 'length': fwr, 'row': 0, 'id': devid }; | |
168 | self.dmesg['BIOS'] = \ | |
169 | {'list': list, 'start': fws, 'end': fwr, | |
170 | 'row': 0, 'color': "purple", 'order': 4} | |
171 | self.dmesg['resume_cpu']['order'] += 1 | |
172 | self.dmesg['resume_noirq']['order'] += 1 | |
173 | self.dmesg['resume_early']['order'] += 1 | |
174 | self.dmesg['resume_general']['order'] += 1 | |
175 | self.phases = self.sortedPhases() | |
176 | def vprint(self, msg): | |
177 | if(self.verbose): | |
178 | print(msg) | |
179 | def dmesgSortVal(self, phase): | |
180 | return self.dmesg[phase]['order'] | |
181 | def sortedPhases(self): | |
182 | return sorted(self.dmesg, key=self.dmesgSortVal) | |
183 | def sortedDevices(self, phase): | |
184 | list = self.dmesg[phase]['list'] | |
185 | slist = [] | |
186 | tmp = dict() | |
187 | for devname in list: | |
188 | dev = list[devname] | |
189 | tmp[dev['start']] = devname | |
190 | for t in sorted(tmp): | |
191 | slist.append(tmp[t]) | |
192 | return slist | |
193 | def fixupInitcalls(self, phase, end): | |
194 | # if any calls never returned, clip them at system resume end | |
195 | phaselist = self.dmesg[phase]['list'] | |
196 | for devname in phaselist: | |
197 | dev = phaselist[devname] | |
198 | if(dev['end'] < 0): | |
199 | dev['end'] = end | |
200 | self.vprint("%s (%s): callback didn't return" % (devname, phase)) | |
201 | def fixupInitcallsThatDidntReturn(self): | |
202 | # if any calls never returned, clip them at system resume end | |
203 | for phase in self.phases: | |
204 | self.fixupInitcalls(phase, self.dmesg['resume_general']['end']) | |
205 | if(phase == "resume_general"): | |
206 | break | |
207 | def newAction(self, phase, name, pid, parent, start, end): | |
208 | self.id += 1 | |
209 | devid = "dc%d" % self.id | |
210 | list = self.dmesg[phase]['list'] | |
211 | length = -1.0 | |
212 | if(start >= 0 and end >= 0): | |
213 | length = end - start | |
214 | list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, | |
215 | 'length': length, 'row': 0, 'id': devid } | |
216 | def deviceIDs(self, devlist, phase): | |
217 | idlist = [] | |
218 | for p in self.phases: | |
219 | if(p[0] != phase[0]): | |
220 | continue | |
221 | list = data.dmesg[p]['list'] | |
222 | for devname in list: | |
223 | if devname in devlist: | |
224 | idlist.append(list[devname]['id']) | |
225 | return idlist | |
226 | def deviceParentID(self, devname, phase): | |
227 | pdev = "" | |
228 | pdevid = "" | |
229 | for p in self.phases: | |
230 | if(p[0] != phase[0]): | |
231 | continue | |
232 | list = data.dmesg[p]['list'] | |
233 | if devname in list: | |
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 | |
242 | def deviceChildrenIDs(self, devname, phase): | |
243 | devlist = [] | |
244 | for p in self.phases: | |
245 | if(p[0] != phase[0]): | |
246 | continue | |
247 | list = data.dmesg[p]['list'] | |
248 | for child in list: | |
249 | if(list[child]['par'] == devname): | |
250 | devlist.append(child) | |
251 | return self.deviceIDs(devlist, phase) | |
252 | ||
253 | class FTraceLine: | |
254 | time = 0.0 | |
255 | length = 0.0 | |
256 | fcall = False | |
257 | freturn = False | |
258 | fevent = False | |
259 | depth = 0 | |
260 | name = "" | |
261 | def __init__(self, t, m, d): | |
262 | self.time = float(t) | |
263 | # check to see if this is a trace event | |
264 | em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m) | |
265 | if(em): | |
266 | self.name = em.group("msg") | |
267 | self.fevent = True | |
268 | return | |
269 | # convert the duration to seconds | |
270 | if(d): | |
271 | self.length = float(d)/1000000 | |
272 | # the indentation determines the depth | |
273 | match = re.match(r"^(?P<d> *)(?P<o>.*)$", m) | |
274 | if(not match): | |
275 | return | |
276 | self.depth = self.getDepth(match.group('d')) | |
277 | m = match.group('o') | |
278 | # function return | |
279 | if(m[0] == '}'): | |
280 | self.freturn = True | |
281 | if(len(m) > 1): | |
282 | # includes comment with function name | |
283 | match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m) | |
284 | if(match): | |
285 | self.name = match.group('n') | |
286 | # function call | |
287 | else: | |
288 | self.fcall = True | |
289 | # function call with children | |
290 | if(m[-1] == '{'): | |
291 | match = re.match(r"^(?P<n>.*) *\(.*", m) | |
292 | if(match): | |
293 | self.name = match.group('n') | |
294 | # function call with no children (leaf) | |
295 | elif(m[-1] == ';'): | |
296 | self.freturn = True | |
297 | match = re.match(r"^(?P<n>.*) *\(.*", m) | |
298 | if(match): | |
299 | self.name = match.group('n') | |
300 | # something else (possibly a trace marker) | |
301 | else: | |
302 | self.name = m | |
303 | def getDepth(self, str): | |
304 | return len(str)/2 | |
305 | ||
306 | class FTraceCallGraph: | |
307 | start = -1.0 | |
308 | end = -1.0 | |
309 | list = [] | |
310 | invalid = False | |
311 | depth = 0 | |
312 | def __init__(self): | |
313 | self.start = -1.0 | |
314 | self.end = -1.0 | |
315 | self.list = [] | |
316 | self.depth = 0 | |
317 | def setDepth(self, line): | |
318 | if(line.fcall and not line.freturn): | |
319 | line.depth = self.depth | |
320 | self.depth += 1 | |
321 | elif(line.freturn and not line.fcall): | |
322 | self.depth -= 1 | |
323 | line.depth = self.depth | |
324 | else: | |
325 | line.depth = self.depth | |
326 | def addLine(self, line, match): | |
327 | if(not self.invalid): | |
328 | self.setDepth(line) | |
329 | if(line.depth == 0 and line.freturn): | |
330 | self.end = line.time | |
331 | self.list.append(line) | |
332 | return True | |
333 | if(self.invalid): | |
334 | return False | |
335 | if(len(self.list) >= 1000000 or self.depth < 0): | |
336 | first = self.list[0] | |
337 | self.list = [] | |
338 | self.list.append(first) | |
339 | self.invalid = True | |
340 | id = "task %s cpu %s" % (match.group("pid"), match.group("cpu")) | |
341 | window = "(%f - %f)" % (self.start, line.time) | |
342 | data.vprint("Too much data for "+id+" "+window+", ignoring this callback") | |
343 | return False | |
344 | self.list.append(line) | |
345 | if(self.start < 0): | |
346 | self.start = line.time | |
347 | return False | |
348 | def sanityCheck(self): | |
349 | stack = dict() | |
350 | cnt = 0 | |
351 | for l in self.list: | |
352 | if(l.fcall and not l.freturn): | |
353 | stack[l.depth] = l | |
354 | cnt += 1 | |
355 | elif(l.freturn and not l.fcall): | |
356 | if(not stack[l.depth]): | |
357 | return False | |
358 | stack[l.depth].length = l.length | |
359 | stack[l.depth] = 0 | |
360 | l.length = 0 | |
361 | cnt -= 1 | |
362 | if(cnt == 0): | |
363 | return True | |
364 | return False | |
365 | def debugPrint(self, filename): | |
366 | if(filename == "stdout"): | |
367 | print("[%f - %f]") % (self.start, self.end) | |
368 | for l in self.list: | |
369 | if(l.freturn and l.fcall): | |
370 | print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) | |
371 | elif(l.freturn): | |
372 | print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) | |
373 | else: | |
374 | print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000)) | |
375 | print(" ") | |
376 | else: | |
377 | fp = open(filename, 'w') | |
378 | print(filename) | |
379 | for l in self.list: | |
380 | if(l.freturn and l.fcall): | |
381 | fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) | |
382 | elif(l.freturn): | |
383 | fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) | |
384 | else: | |
385 | fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000)) | |
386 | fp.close() | |
387 | ||
388 | class Timeline: | |
389 | html = {} | |
390 | scaleH = 0.0 # height of the timescale row as a percent of the timeline height | |
391 | rowH = 0.0 # height of each row in percent of the timeline height | |
392 | row_height_pixels = 30 | |
393 | maxrows = 0 | |
394 | height = 0 | |
395 | def __init__(self): | |
396 | self.html = { | |
397 | 'timeline': "", | |
398 | 'legend': "", | |
399 | 'scale': "" | |
400 | } | |
401 | def setRows(self, rows): | |
402 | self.maxrows = int(rows) | |
403 | self.scaleH = 100.0/float(self.maxrows) | |
404 | self.height = self.maxrows*self.row_height_pixels | |
405 | r = float(self.maxrows - 1) | |
406 | if(r < 1.0): | |
407 | r = 1.0 | |
408 | self.rowH = (100.0 - self.scaleH)/r | |
409 | ||
410 | # -- global objects -- | |
411 | ||
412 | sysvals = SystemValues() | |
413 | data = Data() | |
414 | ||
415 | # -- functions -- | |
416 | ||
417 | # Function: initFtrace | |
418 | # Description: | |
419 | # Configure ftrace to capture a function trace during suspend/resume | |
420 | def initFtrace(): | |
421 | global sysvals | |
422 | ||
423 | print("INITIALIZING FTRACE...") | |
424 | # turn trace off | |
425 | os.system("echo 0 > "+sysvals.tpath+"tracing_on") | |
426 | # set the trace clock to global | |
427 | os.system("echo global > "+sysvals.tpath+"trace_clock") | |
428 | # set trace buffer to a huge value | |
429 | os.system("echo nop > "+sysvals.tpath+"current_tracer") | |
430 | os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb") | |
431 | # clear the trace buffer | |
432 | os.system("echo \"\" > "+sysvals.tpath+"trace") | |
433 | # set trace type | |
434 | os.system("echo function_graph > "+sysvals.tpath+"current_tracer") | |
435 | os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter") | |
436 | # set trace format options | |
437 | os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options") | |
438 | os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options") | |
439 | # focus only on device suspend and resume | |
440 | os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function") | |
441 | ||
442 | # Function: verifyFtrace | |
443 | # Description: | |
444 | # Check that ftrace is working on the system | |
445 | def verifyFtrace(): | |
446 | global sysvals | |
447 | files = ["available_filter_functions", "buffer_size_kb", | |
448 | "current_tracer", "set_ftrace_filter", | |
449 | "trace", "trace_marker"] | |
450 | for f in files: | |
451 | if(os.path.exists(sysvals.tpath+f) == False): | |
452 | return False | |
453 | return True | |
454 | ||
455 | def parseStamp(line): | |
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: | |
473 | # Analyse an ftrace log output file generated from this app during | |
474 | # the execution phase. Create an "ftrace" structure in memory for | |
475 | # subsequent formatting in the html output file | |
476 | def analyzeTraceLog(): | |
477 | global sysvals, data | |
478 | ||
479 | # the ftrace data is tied to the dmesg data | |
480 | if(not data.usedmesg): | |
481 | return | |
482 | ||
483 | # read through the ftrace and parse the data | |
484 | data.vprint("Analyzing the ftrace data...") | |
485 | ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\ | |
486 | " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\ | |
487 | "[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)" | |
488 | ftemp = dict() | |
489 | inthepipe = False | |
490 | tf = open(sysvals.ftracefile, 'r') | |
491 | count = 0 | |
492 | for line in tf: | |
493 | count = count + 1 | |
494 | # grab the time stamp if it's valid | |
495 | if(count == 1): | |
496 | parseStamp(line) | |
497 | continue | |
498 | # parse only valid lines | |
499 | m = re.match(ftrace_line_fmt, line) | |
500 | if(not m): | |
501 | continue | |
502 | m_time = m.group("time") | |
503 | m_pid = m.group("pid") | |
504 | m_msg = m.group("msg") | |
505 | m_dur = m.group("dur") | |
506 | if(m_time and m_pid and m_msg): | |
507 | t = FTraceLine(m_time, m_msg, m_dur) | |
508 | pid = int(m_pid) | |
509 | else: | |
510 | continue | |
511 | # the line should be a call, return, or event | |
512 | if(not t.fcall and not t.freturn and not t.fevent): | |
513 | continue | |
514 | # only parse the ftrace data during suspend/resume | |
515 | if(not inthepipe): | |
516 | # look for the suspend start marker | |
517 | if(t.fevent): | |
518 | if(t.name == "SUSPEND START"): | |
519 | data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count)) | |
520 | inthepipe = True | |
521 | continue | |
522 | else: | |
523 | # look for the resume end marker | |
524 | if(t.fevent): | |
525 | if(t.name == "RESUME COMPLETE"): | |
526 | data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count)) | |
527 | inthepipe = False | |
528 | break | |
529 | continue | |
530 | # create a callgraph object for the data | |
531 | if(pid not in ftemp): | |
532 | ftemp[pid] = FTraceCallGraph() | |
533 | # when the call is finished, see which device matches it | |
534 | if(ftemp[pid].addLine(t, m)): | |
535 | if(not ftemp[pid].sanityCheck()): | |
536 | id = "task %s cpu %s" % (pid, m.group("cpu")) | |
537 | data.vprint("Sanity check failed for "+id+", ignoring this callback") | |
538 | continue | |
539 | callstart = ftemp[pid].start | |
540 | callend = ftemp[pid].end | |
541 | for p in data.phases: | |
542 | if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']): | |
543 | list = data.dmesg[p]['list'] | |
544 | for devname in list: | |
545 | dev = list[devname] | |
546 | if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']): | |
547 | data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid)) | |
548 | dev['ftrace'] = ftemp[pid] | |
549 | break | |
550 | ftemp[pid] = FTraceCallGraph() | |
551 | tf.close() | |
552 | ||
553 | # Function: sortKernelLog | |
554 | # Description: | |
555 | # The dmesg output log sometimes comes with with lines that have | |
556 | # timestamps out of order. This could cause issues since a call | |
557 | # could accidentally end up in the wrong phase | |
558 | def sortKernelLog(): | |
559 | global sysvals, data | |
560 | lf = open(sysvals.dmesgfile, 'r') | |
561 | dmesglist = [] | |
562 | count = 0 | |
563 | for line in lf: | |
564 | line = line.replace("\r\n", "") | |
565 | if(count == 0): | |
566 | parseStamp(line) | |
567 | elif(count == 1): | |
568 | m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line) | |
569 | if(m): | |
570 | data.fwSuspend = int(m.group("s")) | |
571 | data.fwResume = int(m.group("r")) | |
572 | if(data.fwSuspend > 0 or data.fwResume > 0): | |
573 | data.fwValid = True | |
574 | if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)): | |
575 | dmesglist.append(line) | |
576 | count += 1 | |
577 | lf.close() | |
578 | last = "" | |
579 | ||
580 | # fix lines with the same time stamp and function with the call and return swapped | |
581 | for line in dmesglist: | |
582 | mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling (?P<f>.*)\+ @ .*, parent: .*", line) | |
583 | mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last) | |
584 | if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))): | |
585 | i = dmesglist.index(last) | |
586 | j = dmesglist.index(line) | |
587 | dmesglist[i] = line | |
588 | dmesglist[j] = last | |
589 | last = line | |
590 | return dmesglist | |
591 | ||
592 | # Function: analyzeKernelLog | |
593 | # Description: | |
594 | # Analyse a dmesg log output file generated from this app during | |
595 | # the execution phase. Create a set of device structures in memory | |
596 | # for subsequent formatting in the html output file | |
597 | def analyzeKernelLog(): | |
598 | global sysvals, data | |
599 | ||
600 | print("PROCESSING DATA") | |
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 | ||
606 | lf = sortKernelLog() | |
607 | phase = "suspend_runtime" | |
608 | ||
609 | dm = { | |
610 | 'suspend_general': r"PM: Syncing filesystems.*", | |
611 | 'suspend_early': r"PM: suspend of devices complete after.*", | |
612 | 'suspend_noirq': r"PM: late suspend of devices complete after.*", | |
613 | 'suspend_cpu': r"PM: noirq suspend of devices complete after.*", | |
614 | 'resume_cpu': r"ACPI: Low-level resume complete.*", | |
615 | 'resume_noirq': r"ACPI: Waking up from system sleep state.*", | |
616 | 'resume_early': r"PM: noirq resume of devices complete after.*", | |
617 | 'resume_general': r"PM: early resume of devices complete after.*", | |
618 | 'resume_complete': r".*Restarting tasks \.\.\..*", | |
619 | } | |
620 | if(sysvals.suspendmode == "standby"): | |
621 | dm['resume_cpu'] = r"PM: Restoring platform NVS memory" | |
622 | elif(sysvals.suspendmode == "disk"): | |
623 | dm['suspend_early'] = r"PM: freeze of devices complete after.*" | |
624 | dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*" | |
625 | dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*" | |
626 | dm['resume_cpu'] = r"PM: Restoring platform NVS memory" | |
627 | dm['resume_early'] = r"PM: noirq restore of devices complete after.*" | |
628 | dm['resume_general'] = r"PM: early restore of devices complete after.*" | |
629 | ||
630 | action_start = 0.0 | |
631 | for line in lf: | |
632 | # -- preprocessing -- | |
633 | # parse each dmesg line into the time and message | |
634 | m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line) | |
635 | if(m): | |
636 | ktime = float(m.group("ktime")) | |
637 | msg = m.group("msg") | |
638 | else: | |
639 | print line | |
640 | continue | |
641 | ||
642 | # -- phase changes -- | |
643 | # suspend_general start | |
644 | if(re.match(dm['suspend_general'], msg)): | |
645 | phase = "suspend_general" | |
646 | data.dmesg[phase]['start'] = ktime | |
647 | data.start = ktime | |
648 | # action start: syncing filesystems | |
649 | action_start = ktime | |
650 | # suspend_early start | |
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 | |
655 | # suspend_noirq start | |
656 | elif(re.match(dm['suspend_noirq'], msg)): | |
657 | data.dmesg["suspend_early"]['end'] = ktime | |
658 | phase = "suspend_noirq" | |
659 | data.dmesg[phase]['start'] = ktime | |
660 | # suspend_cpu start | |
661 | elif(re.match(dm['suspend_cpu'], msg)): | |
662 | data.dmesg["suspend_noirq"]['end'] = ktime | |
663 | phase = "suspend_cpu" | |
664 | data.dmesg[phase]['start'] = ktime | |
665 | # resume_cpu start | |
666 | elif(re.match(dm['resume_cpu'], msg)): | |
667 | data.tSuspended = ktime | |
668 | data.dmesg["suspend_cpu"]['end'] = ktime | |
669 | phase = "resume_cpu" | |
670 | data.dmesg[phase]['start'] = ktime | |
671 | # resume_noirq start | |
672 | elif(re.match(dm['resume_noirq'], msg)): | |
673 | data.dmesg["resume_cpu"]['end'] = ktime | |
674 | phase = "resume_noirq" | |
675 | data.dmesg[phase]['start'] = ktime | |
676 | # action end: ACPI resume | |
677 | data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime) | |
678 | # resume_early start | |
679 | elif(re.match(dm['resume_early'], msg)): | |
680 | data.dmesg["resume_noirq"]['end'] = ktime | |
681 | phase = "resume_early" | |
682 | data.dmesg[phase]['start'] = ktime | |
683 | # resume_general start | |
684 | elif(re.match(dm['resume_general'], msg)): | |
685 | data.dmesg["resume_early"]['end'] = ktime | |
686 | phase = "resume_general" | |
687 | data.dmesg[phase]['start'] = ktime | |
688 | # resume complete start | |
689 | elif(re.match(dm['resume_complete'], msg)): | |
690 | data.dmesg["resume_general"]['end'] = ktime | |
691 | data.end = ktime | |
692 | phase = "resume_runtime" | |
693 | break | |
694 | ||
695 | # -- device callbacks -- | |
696 | if(phase in data.phases): | |
697 | # device init call | |
698 | if(re.match(r"calling (?P<f>.*)\+ @ .*, parent: .*", msg)): | |
699 | sm = re.match(r"calling (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg); | |
700 | f = sm.group("f") | |
701 | n = sm.group("n") | |
702 | p = sm.group("p") | |
703 | if(f and n and p): | |
704 | data.newAction(phase, f, int(n), p, ktime, -1) | |
705 | # device init return | |
706 | elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)): | |
707 | sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg); | |
708 | f = sm.group("f") | |
709 | t = sm.group("t") | |
710 | list = data.dmesg[phase]['list'] | |
711 | if(f in list): | |
712 | dev = list[f] | |
713 | dev['length'] = int(t) | |
714 | dev['end'] = ktime | |
715 | data.vprint("%15s [%f - %f] %s(%d) %s" % | |
716 | (phase, dev['start'], dev['end'], f, dev['pid'], dev['par'])) | |
717 | ||
718 | # -- phase specific actions -- | |
719 | if(phase == "suspend_general"): | |
720 | if(re.match(r"PM: Preparing system for mem sleep.*", msg)): | |
721 | data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime) | |
722 | elif(re.match(r"Freezing user space processes .*", msg)): | |
723 | action_start = ktime | |
724 | elif(re.match(r"Freezing remaining freezable tasks.*", msg)): | |
725 | data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime) | |
726 | action_start = ktime | |
727 | elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)): | |
728 | data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime) | |
729 | elif(phase == "suspend_cpu"): | |
730 | m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg) | |
731 | if(m): | |
732 | cpu = "CPU"+m.group("cpu") | |
733 | data.newAction(phase, cpu, -1, "", action_start, ktime) | |
734 | action_start = ktime | |
735 | elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)): | |
736 | action_start = ktime | |
737 | elif(re.match(r"Disabling non-boot CPUs .*", msg)): | |
738 | data.newAction(phase, "ACPI", -1, "", action_start, ktime) | |
739 | action_start = ktime | |
740 | elif(phase == "resume_cpu"): | |
741 | m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg) | |
742 | if(m): | |
743 | cpu = "CPU"+m.group("cpu") | |
744 | data.newAction(phase, cpu, -1, "", action_start, ktime) | |
745 | action_start = ktime | |
746 | elif(re.match(r"Enabling non-boot CPUs .*", msg)): | |
747 | action_start = ktime | |
748 | ||
749 | # fill in any missing phases | |
750 | lp = "suspend_general" | |
751 | for p in data.phases: | |
752 | if(p == "suspend_general"): | |
753 | continue | |
754 | if(data.dmesg[p]['start'] < 0): | |
755 | data.dmesg[p]['start'] = data.dmesg[lp]['end'] | |
756 | if(p == "resume_cpu"): | |
757 | data.tSuspended = data.dmesg[lp]['end'] | |
758 | if(data.dmesg[p]['end'] < 0): | |
759 | data.dmesg[p]['end'] = data.dmesg[p]['start'] | |
760 | lp = p | |
761 | ||
762 | data.fixupInitcallsThatDidntReturn() | |
763 | return True | |
764 | ||
765 | # Function: setTimelineRows | |
766 | # Description: | |
767 | # Organize the device or thread lists into the smallest | |
768 | # number of rows possible, with no entry overlapping | |
769 | # Arguments: | |
770 | # list: the list to sort (dmesg or ftrace) | |
771 | # sortedkeys: sorted key list to use | |
772 | def setTimelineRows(list, sortedkeys): | |
773 | global data | |
774 | ||
775 | # clear all rows and set them to undefined | |
776 | remaining = len(list) | |
777 | rowdata = dict() | |
778 | row = 0 | |
779 | for item in list: | |
780 | list[item]['row'] = -1 | |
781 | ||
782 | # try to pack each row with as many ranges as possible | |
783 | while(remaining > 0): | |
784 | if(row not in rowdata): | |
785 | rowdata[row] = [] | |
786 | for item in sortedkeys: | |
787 | if(list[item]['row'] < 0): | |
788 | s = list[item]['start'] | |
789 | e = list[item]['end'] | |
790 | valid = True | |
791 | for ritem in rowdata[row]: | |
792 | rs = ritem['start'] | |
793 | re = ritem['end'] | |
794 | if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))): | |
795 | valid = False | |
796 | break | |
797 | if(valid): | |
798 | rowdata[row].append(list[item]) | |
799 | list[item]['row'] = row | |
800 | remaining -= 1 | |
801 | row += 1 | |
802 | return row | |
803 | ||
804 | # Function: createTimeScale | |
805 | # Description: | |
806 | # Create timescale lines for the dmesg and ftrace timelines | |
807 | # Arguments: | |
808 | # t0: start time (suspend begin) | |
809 | # tMax: end time (resume end) | |
810 | # tSuspend: time when suspend occurs | |
811 | def createTimeScale(t0, tMax, tSuspended): | |
812 | global data | |
813 | timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n" | |
814 | output = '<div id="timescale">\n' | |
815 | ||
816 | # set scale for timeline | |
817 | tTotal = tMax - t0 | |
818 | tS = 0.1 | |
819 | if(tTotal <= 0): | |
820 | return output | |
821 | if(tTotal > 4): | |
822 | tS = 1 | |
823 | if(tSuspended < 0): | |
824 | for i in range(int(tTotal/tS)+1): | |
825 | pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal)) | |
826 | if(i > 0): | |
827 | val = "%0.f" % (float(i)*tS*1000) | |
828 | else: | |
829 | val = "" | |
830 | output += timescale.format(pos, val) | |
831 | else: | |
832 | tSuspend = tSuspended - t0 | |
833 | divTotal = int(tTotal/tS) + 1 | |
834 | divSuspend = int(tSuspend/tS) | |
835 | s0 = (tSuspend - tS*divSuspend)*100/tTotal | |
836 | for i in range(divTotal): | |
837 | pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0) | |
838 | if((i == 0) and (s0 < 3)): | |
839 | val = "" | |
840 | elif(i == divSuspend): | |
841 | val = "S/R" | |
842 | else: | |
843 | val = "%0.f" % (float(i-divSuspend)*tS*1000) | |
844 | output += timescale.format(pos, val) | |
845 | output += '</div>\n' | |
846 | return output | |
847 | ||
848 | # Function: createHTML | |
849 | # Description: | |
850 | # Create the output html file. | |
851 | def createHTML(): | |
852 | global sysvals, data | |
853 | ||
854 | data.normalizeTime() | |
855 | ||
856 | # html function templates | |
857 | 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' | |
859 | html_timeline = '<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' | |
861 | html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n' | |
862 | html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n' | |
863 | html_timetotal = '<table class="time1">\n<tr>'\ | |
864 | '<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\ | |
865 | '<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\ | |
866 | '</tr>\n</table>\n' | |
867 | html_timegroups = '<table class="time2">\n<tr>'\ | |
868 | '<td class="green">Kernel Suspend: {0} ms</td>'\ | |
869 | '<td class="purple">Firmware Suspend: {1} ms</td>'\ | |
870 | '<td class="purple">Firmware Resume: {2} ms</td>'\ | |
871 | '<td class="yellow">Kernel Resume: {3} ms</td>'\ | |
872 | '</tr>\n</table>\n' | |
873 | ||
874 | # device timeline (dmesg) | |
875 | if(data.usedmesg): | |
876 | data.vprint("Creating Device Timeline...") | |
877 | devtl = Timeline() | |
878 | ||
879 | # Generate the header for this timeline | |
880 | t0 = data.start | |
881 | tMax = data.end | |
882 | tTotal = tMax - t0 | |
883 | if(tTotal == 0): | |
884 | print("ERROR: No timeline data") | |
885 | sys.exit() | |
886 | suspend_time = "%.0f"%(-data.start*1000) | |
887 | resume_time = "%.0f"%(data.end*1000) | |
888 | if data.fwValid: | |
889 | devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total") | |
890 | sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000) | |
891 | sftime = "%.3f"%(data.fwSuspend / 1000000.0) | |
892 | rftime = "%.3f"%(data.fwResume / 1000000.0) | |
893 | rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000) | |
894 | devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime) | |
895 | else: | |
896 | devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel") | |
897 | ||
898 | # determine the maximum number of rows we need to draw | |
899 | timelinerows = 0 | |
900 | for phase in data.dmesg: | |
901 | list = data.dmesg[phase]['list'] | |
902 | rows = setTimelineRows(list, list) | |
903 | data.dmesg[phase]['row'] = rows | |
904 | if(rows > timelinerows): | |
905 | timelinerows = rows | |
906 | ||
907 | # calculate the timeline height and create its bounding box | |
908 | devtl.setRows(timelinerows + 1) | |
909 | devtl.html['timeline'] += html_zoombox; | |
910 | devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height); | |
911 | ||
912 | # draw the colored boxes for each of the phases | |
913 | for b in data.dmesg: | |
914 | phase = data.dmesg[b] | |
915 | left = "%.3f" % (((phase['start']-data.start)*100)/tTotal) | |
916 | width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal) | |
917 | devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "") | |
918 | ||
919 | # draw the time scale, try to make the number of labels readable | |
920 | devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended) | |
921 | devtl.html['timeline'] += devtl.html['scale'] | |
922 | for b in data.dmesg: | |
923 | phaselist = data.dmesg[b]['list'] | |
924 | for d in phaselist: | |
925 | name = d | |
926 | if(d in data.altdevname): | |
927 | name = data.altdevname[d] | |
928 | dev = phaselist[d] | |
929 | height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] | |
930 | top = "%.3f" % ((dev['row']*height) + devtl.scaleH) | |
931 | left = "%.3f" % (((dev['start']-data.start)*100)/tTotal) | |
932 | width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal) | |
933 | len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000) | |
934 | 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) | |
936 | ||
937 | # timeline is finished | |
938 | devtl.html['timeline'] += "</div>\n</div>\n" | |
939 | ||
940 | # draw a legend which describes the phases by color | |
941 | devtl.html['legend'] = "<div class=\"legend\">\n" | |
942 | pdelta = 100.0/data.phases.__len__() | |
943 | pmargin = pdelta / 4.0 | |
944 | for phase in data.phases: | |
945 | order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin) | |
946 | name = string.replace(phase, "_", " ") | |
947 | devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name) | |
948 | devtl.html['legend'] += "</div>\n" | |
949 | ||
950 | hf = open(sysvals.htmlfile, 'w') | |
951 | thread_height = 0 | |
952 | ||
953 | # write the html header first (html head, css code, everything up to the start of body) | |
954 | html_header = "<!DOCTYPE html>\n<html>\n<head>\n\ | |
955 | <meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\ | |
956 | <title>AnalyzeSuspend</title>\n\ | |
957 | <style type='text/css'>\n\ | |
958 | body {overflow-y: scroll;}\n\ | |
959 | .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\ | |
961 | .callgraph article * {padding-left: 28px;}\n\ | |
962 | h1 {color:black;font: bold 30px Times;}\n\ | |
963 | table {width:100%;}\n\ | |
964 | .gray {background-color:rgba(80,80,80,0.1);}\n\ | |
965 | .green {background-color:rgba(204,255,204,0.4);}\n\ | |
966 | .purple {background-color:rgba(128,0,128,0.2);}\n\ | |
967 | .yellow {background-color:rgba(255,255,204,0.4);}\n\ | |
968 | .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\ | |
970 | td {text-align: center;}\n\ | |
971 | .tdhl {color: red;}\n\ | |
972 | .hide {display: none;}\n\ | |
973 | .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\ | |
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\ | |
976 | .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\ | |
977 | .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\ | |
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\ | |
980 | .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\ | |
981 | .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\ | |
983 | .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\ | |
985 | button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ | |
986 | </style>\n</head>\n<body>\n" | |
987 | hf.write(html_header) | |
988 | ||
989 | # write the test title and general info header | |
990 | if(data.stamp['time'] != ""): | |
991 | hf.write(headline_stamp.format(data.stamp['host'], | |
992 | data.stamp['kernel'], data.stamp['mode'], data.stamp['time'])) | |
993 | ||
994 | # write the dmesg data (device timeline) | |
995 | if(data.usedmesg): | |
996 | hf.write(devtl.html['timeline']) | |
997 | hf.write(devtl.html['legend']) | |
998 | hf.write('<div id="devicedetail"></div>\n') | |
999 | hf.write('<div id="devicetree"></div>\n') | |
1000 | ||
1001 | # write the ftrace data (callgraph) | |
1002 | if(data.useftrace): | |
1003 | hf.write('<section id="callgraphs" class="callgraph">\n') | |
1004 | # 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' | |
1006 | html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n' | |
1007 | html_func_end = '</article>\n' | |
1008 | html_func_leaf = '<article>{0} {1}</article>\n' | |
1009 | num = 0 | |
1010 | for p in data.phases: | |
1011 | list = data.dmesg[p]['list'] | |
1012 | for devname in data.sortedDevices(p): | |
1013 | if('ftrace' not in list[devname]): | |
1014 | continue | |
1015 | name = devname | |
1016 | if(devname in data.altdevname): | |
1017 | name = data.altdevname[devname] | |
1018 | devid = list[devname]['id'] | |
1019 | cg = list[devname]['ftrace'] | |
1020 | flen = "(%.3f ms)" % ((cg.end - cg.start)*1000) | |
1021 | hf.write(html_func_top.format(devid, data.dmesg[p]['color'], num, name+" "+p, flen)) | |
1022 | num += 1 | |
1023 | for line in cg.list: | |
1024 | if(line.length < 0.000000001): | |
1025 | flen = "" | |
1026 | else: | |
1027 | flen = "(%.3f ms)" % (line.length*1000) | |
1028 | if(line.freturn and line.fcall): | |
1029 | hf.write(html_func_leaf.format(line.name, flen)) | |
1030 | elif(line.freturn): | |
1031 | hf.write(html_func_end) | |
1032 | else: | |
1033 | hf.write(html_func_start.format(num, line.name, flen)) | |
1034 | num += 1 | |
1035 | hf.write(html_func_end) | |
1036 | hf.write("\n\n </section>\n") | |
1037 | # write the footer and close | |
1038 | addScriptCode(hf) | |
1039 | hf.write("</body>\n</html>\n") | |
1040 | hf.close() | |
1041 | return True | |
1042 | ||
1043 | def addScriptCode(hf): | |
1044 | global data | |
1045 | ||
1046 | t0 = (data.start - data.tSuspended) * 1000 | |
1047 | tMax = (data.end - data.tSuspended) * 1000 | |
1048 | # create an array in javascript memory with the device details | |
1049 | detail = ' var bounds = [%f,%f];\n' % (t0, tMax) | |
1050 | detail += ' var d = [];\n' | |
1051 | dfmt = ' d["%s"] = { n:"%s", p:"%s", c:[%s] };\n'; | |
1052 | for p in data.dmesg: | |
1053 | list = data.dmesg[p]['list'] | |
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 | |
1066 | script_code = \ | |
1067 | '<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'\ | |
1127 | ' var timescale = document.getElementById("timescale");\n'\ | |
1128 | ' var dmesg = document.getElementById("dmesg");\n'\ | |
1129 | ' var zoombox = document.getElementById("dmesgzoombox");\n'\ | |
1130 | ' var val = parseFloat(dmesg.style.width);\n'\ | |
1131 | ' var newval = 100;\n'\ | |
1132 | ' var sh = window.outerWidth / 2;\n'\ | |
1133 | ' if(this.id == "zoomin") {\n'\ | |
1134 | ' newval = val * 1.2;\n'\ | |
1135 | ' if(newval > 40000) newval = 40000;\n'\ | |
1136 | ' dmesg.style.width = newval+"%";\n'\ | |
1137 | ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\ | |
1138 | ' } else if (this.id == "zoomout") {\n'\ | |
1139 | ' newval = val / 1.2;\n'\ | |
1140 | ' if(newval < 100) newval = 100;\n'\ | |
1141 | ' dmesg.style.width = newval+"%";\n'\ | |
1142 | ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\ | |
1143 | ' } else {\n'\ | |
1144 | ' zoombox.scrollLeft = 0;\n'\ | |
1145 | ' dmesg.style.width = "100%";\n'\ | |
1146 | ' }\n'\ | |
1147 | ' var html = "";\n'\ | |
1148 | ' var t0 = bounds[0];\n'\ | |
1149 | ' var tMax = bounds[1];\n'\ | |
1150 | ' var tTotal = tMax - t0;\n'\ | |
1151 | ' var wTotal = tTotal * 100.0 / newval;\n'\ | |
1152 | ' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\ | |
1153 | ' if(tS < 1) tS = 1;\n'\ | |
1154 | ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\ | |
1155 | ' var pos = (tMax - s) * 100.0 / tTotal;\n'\ | |
1156 | ' var name = (s == 0)?"S/R":(s+"ms");\n'\ | |
1157 | ' html += \"<div class=\\\"t\\\" style=\\\"right:\"+pos+\"%\\\">\"+name+\"</div>\";\n'\ | |
1158 | ' }\n'\ | |
1159 | ' timescale.innerHTML = html;\n'\ | |
1160 | ' }\n'\ | |
1161 | ' function deviceDetail() {\n'\ | |
1162 | ' var devtitle = document.getElementById("devicedetail");\n'\ | |
1163 | ' devtitle.innerHTML = "<h1>"+this.title+"</h1>";\n'\ | |
1164 | ' var devtree = document.getElementById("devicetree");\n'\ | |
1165 | ' devtree.innerHTML = deviceTree(this.id, (this.title.indexOf("resume") >= 0));\n'\ | |
1166 | ' var cglist = document.getElementById("callgraphs");\n'\ | |
1167 | ' if(!cglist) return;\n'\ | |
1168 | ' var cg = cglist.getElementsByClassName("atop");\n'\ | |
1169 | ' for (var i = 0; i < cg.length; i++) {\n'\ | |
1170 | ' if(filter.indexOf(cg[i].id) >= 0) {\n'\ | |
1171 | ' cg[i].style.display = "block";\n'\ | |
1172 | ' } else {\n'\ | |
1173 | ' cg[i].style.display = "none";\n'\ | |
1174 | ' }\n'\ | |
1175 | ' }\n'\ | |
1176 | ' }\n'\ | |
1177 | ' window.addEventListener("load", function () {\n'\ | |
1178 | ' var dmesg = document.getElementById("dmesg");\n'\ | |
1179 | ' dmesg.style.width = "100%"\n'\ | |
1180 | ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ | |
1181 | ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ | |
1182 | ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ | |
1183 | ' var dev = dmesg.getElementsByClassName("thread");\n'\ | |
1184 | ' for (var i = 0; i < dev.length; i++) {\n'\ | |
1185 | ' dev[i].onclick = deviceDetail;\n'\ | |
1186 | ' }\n'\ | |
1187 | ' zoomTimeline();\n'\ | |
1188 | ' });\n'\ | |
1189 | '</script>\n' | |
1190 | hf.write(script_code); | |
1191 | ||
1192 | # Function: executeSuspend | |
1193 | # Description: | |
1194 | # Execute system suspend through the sysfs interface | |
1195 | def executeSuspend(): | |
1196 | global sysvals, data | |
1197 | ||
1198 | detectUSB() | |
1199 | pf = open(sysvals.powerfile, 'w') | |
1200 | # clear the kernel ring buffer just as we start | |
1201 | os.system("dmesg -C") | |
1202 | # start ftrace | |
1203 | if(data.useftrace): | |
1204 | print("START TRACING") | |
1205 | os.system("echo 1 > "+sysvals.tpath+"tracing_on") | |
1206 | os.system("echo SUSPEND START > "+sysvals.tpath+"trace_marker") | |
1207 | # initiate suspend | |
1208 | if(sysvals.rtcwake): | |
1209 | print("SUSPEND START") | |
1210 | os.system("rtcwake -s 10 -m "+sysvals.suspendmode) | |
1211 | else: | |
1212 | print("SUSPEND START (press a key to resume)") | |
1213 | pf.write(sysvals.suspendmode) | |
1214 | # execution will pause here | |
1215 | pf.close() | |
1216 | # return from suspend | |
1217 | print("RESUME COMPLETE") | |
1218 | # stop ftrace | |
1219 | if(data.useftrace): | |
1220 | os.system("echo RESUME COMPLETE > "+sysvals.tpath+"trace_marker") | |
1221 | os.system("echo 0 > "+sysvals.tpath+"tracing_on") | |
1222 | print("CAPTURING FTRACE") | |
1223 | os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.ftracefile) | |
1224 | os.system("cat "+sysvals.tpath+"trace >> "+sysvals.ftracefile) | |
1225 | # grab a copy of the dmesg output | |
1226 | print("CAPTURING DMESG") | |
1227 | os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.dmesgfile) | |
1228 | os.system("dmesg -c >> "+sysvals.dmesgfile) | |
1229 | ||
1230 | # Function: detectUSB | |
1231 | # Description: | |
1232 | # Detect all the USB hosts and devices currently connected | |
1233 | def detectUSB(): | |
1234 | global sysvals, data | |
1235 | ||
1236 | for dirname, dirnames, filenames in os.walk("/sys/devices"): | |
1237 | if(re.match(r".*/usb[0-9]*.*", dirname) and | |
1238 | "idVendor" in filenames and "idProduct" in filenames): | |
1239 | vid = os.popen("cat %s/idVendor 2>/dev/null" % dirname).read().replace('\n', '') | |
1240 | pid = os.popen("cat %s/idProduct 2>/dev/null" % dirname).read().replace('\n', '') | |
1241 | product = os.popen("cat %s/product 2>/dev/null" % dirname).read().replace('\n', '') | |
1242 | name = dirname.split('/')[-1] | |
1243 | if(len(product) > 0): | |
1244 | data.altdevname[name] = "%s [%s]" % (product, name) | |
1245 | else: | |
1246 | data.altdevname[name] = "%s:%s [%s]" % (vid, pid, name) | |
1247 | ||
1248 | def getModes(): | |
1249 | global sysvals | |
1250 | modes = "" | |
1251 | if(os.path.exists(sysvals.powerfile)): | |
1252 | fp = open(sysvals.powerfile, 'r') | |
1253 | modes = string.split(fp.read()) | |
1254 | fp.close() | |
1255 | return modes | |
1256 | ||
1257 | # Function: statusCheck | |
1258 | # Description: | |
1259 | # Verify that the requested command and options will work | |
1260 | def statusCheck(dryrun): | |
1261 | global sysvals, data | |
1262 | res = dict() | |
1263 | ||
1264 | if(data.notestrun): | |
1265 | print("SUCCESS: The command should run!") | |
1266 | return | |
1267 | ||
1268 | # check we have root access | |
1269 | check = "YES" | |
1270 | if(os.environ['USER'] != "root"): | |
1271 | if(not dryrun): | |
1272 | doError("root access is required", False) | |
1273 | check = "NO" | |
1274 | res[" have root access: "] = check | |
1275 | ||
1276 | # check sysfs is mounted | |
1277 | check = "YES" | |
1278 | if(not os.path.exists(sysvals.powerfile)): | |
1279 | if(not dryrun): | |
1280 | doError("sysfs must be mounted", False) | |
1281 | check = "NO" | |
1282 | res[" is sysfs mounted: "] = check | |
1283 | ||
1284 | # check target mode is a valid mode | |
1285 | check = "YES" | |
1286 | modes = getModes() | |
1287 | if(sysvals.suspendmode not in modes): | |
1288 | if(not dryrun): | |
1289 | doError("%s is not a value power mode" % sysvals.suspendmode, False) | |
1290 | check = "NO" | |
1291 | res[" is "+sysvals.suspendmode+" a power mode: "] = check | |
1292 | ||
1293 | # check if ftrace is available | |
1294 | if(data.useftrace): | |
1295 | check = "YES" | |
1296 | if(not verifyFtrace()): | |
1297 | if(not dryrun): | |
1298 | doError("ftrace is not configured", False) | |
1299 | check = "NO" | |
1300 | res[" is ftrace usable: "] = check | |
1301 | ||
1302 | # check if rtcwake | |
1303 | if(sysvals.rtcwake): | |
1304 | check = "YES" | |
1305 | version = os.popen("rtcwake -V 2>/dev/null").read() | |
1306 | if(not version.startswith("rtcwake")): | |
1307 | if(not dryrun): | |
1308 | doError("rtcwake is not installed", False) | |
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 | ||
1324 | def printHelp(): | |
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 | ||
1356 | def doError(msg, help): | |
1357 | print("ERROR: %s") % msg | |
1358 | if(help == True): | |
1359 | printHelp() | |
1360 | sys.exit() | |
1361 | ||
1362 | # -- script main -- | |
1363 | # loop through the command line arguments | |
1364 | cmd = "" | |
1365 | args = iter(sys.argv[1:]) | |
1366 | for arg in args: | |
1367 | if(arg == "-m"): | |
1368 | try: | |
1369 | val = args.next() | |
1370 | except: | |
1371 | doError("No mode supplied", True) | |
1372 | sysvals.suspendmode = val | |
1373 | elif(arg == "-f"): | |
1374 | data.useftrace = True | |
1375 | elif(arg == "-modes"): | |
1376 | cmd = "modes" | |
1377 | elif(arg == "-status"): | |
1378 | cmd = "status" | |
1379 | elif(arg == "-verbose"): | |
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 | ||
1414 | data.initialize() | |
1415 | ||
1416 | # if instructed, re-analyze existing data files | |
1417 | if(data.notestrun): | |
1418 | sysvals.setOutputFile() | |
1419 | data.vprint("Output file: %s" % sysvals.htmlfile) | |
1420 | if(sysvals.dmesgfile != ""): | |
1421 | analyzeKernelLog() | |
1422 | if(sysvals.ftracefile != ""): | |
1423 | analyzeTraceLog() | |
1424 | createHTML() | |
1425 | sys.exit() | |
1426 | ||
1427 | # verify that we can run a test | |
1428 | data.usedmesg = True | |
1429 | statusCheck(False) | |
1430 | ||
1431 | # prepare for the test | |
1432 | if(data.useftrace): | |
1433 | initFtrace() | |
1434 | sysvals.initTestOutput() | |
1435 | ||
1436 | data.vprint("Output files:\n %s" % sysvals.dmesgfile) | |
1437 | if(data.useftrace): | |
1438 | data.vprint(" %s" % sysvals.ftracefile) | |
1439 | data.vprint(" %s" % sysvals.htmlfile) | |
1440 | ||
1441 | # execute the test | |
1442 | executeSuspend() | |
1443 | analyzeKernelLog() | |
1444 | if(data.useftrace): | |
1445 | analyzeTraceLog() | |
1446 | createHTML() |