?  search:
summary | log | graphiclog1 | graphiclog2 | commit | commitdiff | tree | refs | edit | fork
blame | history | raw | HEAD
serial: 8250, disable "too much work" messages
[linux/fpc-iii.git] / scripts / analyze_suspend.py
blob4f2cc12dc7c78bcbb5a6c8560a2c037db58c6b5e
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}">&nbsp;{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, "_", " &nbsp;")
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+" &rarr;</td>";\n'\
1118 ' else\n'\
1119 ' html += "<td"+args+">&larr; "+cell.name+"</td>";\n'\
1120 ' }\n'\
1121 ' html += "</tr>";\n'\
1122 ' }\n'\
1123 ' html += "</table>";\n'\
1124 ' return html;\n'\
1125 ' }\n'\
1126 ' function zoomTimeline() {\n'\
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()
Linux with added FPC-III support