summaryrefslogtreecommitdiffstats
path: root/scripts
diff options
context:
space:
mode:
authorLinus Torvalds <torvalds@linux-foundation.org>2014-01-24 18:51:02 -0500
committerLinus Torvalds <torvalds@linux-foundation.org>2014-01-24 18:51:02 -0500
commit09da8dfa98682d871987145ed11e3232accac860 (patch)
tree152a9bb1e52f70db6efb66fffbdc4871f749d7df /scripts
parent3aacd625f20129f5a41ea3ff3b5353b0e4dabd01 (diff)
parent7744064731a9543105e207504e0262f883bc14c0 (diff)
Merge tag 'pm+acpi-3.14-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
Pull ACPI and power management updates from Rafael Wysocki: "As far as the number of commits goes, the top spot belongs to ACPI this time with cpufreq in the second position and a handful of PM core, PNP and cpuidle updates. They are fixes and cleanups mostly, as usual, with a couple of new features in the mix. The most visible change is probably that we will create struct acpi_device objects (visible in sysfs) for all devices represented in the ACPI tables regardless of their status and there will be a new sysfs attribute under those objects allowing user space to check that status via _STA. Consequently, ACPI device eject or generally hot-removal will not delete those objects, unless the table containing the corresponding namespace nodes is unloaded, which is extremely rare. Also ACPI container hotplug will be handled quite a bit differently and cpufreq will support CPU boost ("turbo") generically and not only in the acpi-cpufreq driver. Specifics: - ACPI core changes to make it create a struct acpi_device object for every device represented in the ACPI tables during all namespace scans regardless of the current status of that device. In accordance with this, ACPI hotplug operations will not delete those objects, unless the underlying ACPI tables go away. - On top of the above, new sysfs attribute for ACPI device objects allowing user space to check device status by triggering the execution of _STA for its ACPI object. From Srinivas Pandruvada. - ACPI core hotplug changes reducing code duplication, integrating the PCI root hotplug with the core and reworking container hotplug. - ACPI core simplifications making it use ACPI_COMPANION() in the code "glueing" ACPI device objects to "physical" devices. - ACPICA update to upstream version 20131218. This adds support for the DBG2 and PCCT tables to ACPICA, fixes some bugs and improves debug facilities. From Bob Moore, Lv Zheng and Betty Dall. - Init code change to carry out the early ACPI initialization earlier. That should allow us to use ACPI during the timekeeping initialization and possibly to simplify the EFI initialization too. From Chun-Yi Lee. - Clenups of the inclusions of ACPI headers in many places all over from Lv Zheng and Rashika Kheria (work in progress). - New helper for ACPI _DSM execution and rework of the code in drivers that uses _DSM to execute it via the new helper. From Jiang Liu. - New Win8 OSI blacklist entries from Takashi Iwai. - Assorted ACPI fixes and cleanups from Al Stone, Emil Goode, Hanjun Guo, Lan Tianyu, Masanari Iida, Oliver Neukum, Prarit Bhargava, Rashika Kheria, Tang Chen, Zhang Rui. - intel_pstate driver updates, including proper Baytrail support, from Dirk Brandewie and intel_pstate documentation from Ramkumar Ramachandra. - Generic CPU boost ("turbo") support for cpufreq from Lukasz Majewski. - powernow-k6 cpufreq driver fixes from Mikulas Patocka. - cpufreq core fixes and cleanups from Viresh Kumar, Jane Li, Mark Brown. - Assorted cpufreq drivers fixes and cleanups from Anson Huang, John Tobias, Paul Bolle, Paul Walmsley, Sachin Kamat, Shawn Guo, Viresh Kumar. - cpuidle cleanups from Bartlomiej Zolnierkiewicz. - Support for hibernation APM events from Bin Shi. - Hibernation fix to avoid bringing up nonboot CPUs with ACPI EC disabled during thaw transitions from Bjørn Mork. - PM core fixes and cleanups from Ben Dooks, Leonardo Potenza, Ulf Hansson. - PNP subsystem fixes and cleanups from Dmitry Torokhov, Levente Kurusa, Rashika Kheria. - New tool for profiling system suspend from Todd E Brandt and a cpupower tool cleanup from One Thousand Gnomes" * tag 'pm+acpi-3.14-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm: (153 commits) thermal: exynos: boost: Automatic enable/disable of BOOST feature (at Exynos4412) cpufreq: exynos4x12: Change L0 driver data to CPUFREQ_BOOST_FREQ Documentation: cpufreq / boost: Update BOOST documentation cpufreq: exynos: Extend Exynos cpufreq driver to support boost cpufreq / boost: Kconfig: Support for software-managed BOOST acpi-cpufreq: Adjust the code to use the common boost attribute cpufreq: Add boost frequency support in core intel_pstate: Add trace point to report internal state. cpufreq: introduce cpufreq_generic_get() routine ARM: SA1100: Create dummy clk_get_rate() to avoid build failures cpufreq: stats: create sysfs entries when cpufreq_stats is a module cpufreq: stats: free table and remove sysfs entry in a single routine cpufreq: stats: remove hotplug notifiers cpufreq: stats: handle cpufreq_unregister_driver() and suspend/resume properly cpufreq: speedstep: remove unused speedstep_get_state platform: introduce OF style 'modalias' support for platform bus PM / tools: new tool for suspend/resume performance optimization ACPI: fix module autoloading for ACPI enumerated devices ACPI: add module autoloading support for ACPI enumerated devices ACPI: fix create_modalias() return value handling ...
Diffstat (limited to 'scripts')
-rwxr-xr-xscripts/analyze_suspend.py1446
1 files changed, 1446 insertions, 0 deletions
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
new file mode 100755
index 000000000000..4f2cc12dc7c7
--- /dev/null
+++ b/scripts/analyze_suspend.py
@@ -0,0 +1,1446 @@
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
44import sys
45import time
46import os
47import string
48import re
49import array
50import platform
51import datetime
52import struct
53
54# -- classes --
55
56class 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
92class 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
253class 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
306class 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
388class 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
412sysvals = SystemValues()
413data = Data()
414
415# -- functions --
416
417# Function: initFtrace
418# Description:
419# Configure ftrace to capture a function trace during suspend/resume
420def 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
445def 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
455def 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
476def 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
558def 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
597def 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
772def 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
811def 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.
851def 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
1043def 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
1195def 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
1233def 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
1248def 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
1260def 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
1324def 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
1356def 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
1364cmd = ""
1365args = iter(sys.argv[1:])
1366for 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
1406if(cmd != ""):
1407 if(cmd == "status"):
1408 statusCheck(True)
1409 elif(cmd == "modes"):
1410 modes = getModes()
1411 print modes
1412 sys.exit()
1413
1414data.initialize()
1415
1416# if instructed, re-analyze existing data files
1417if(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
1428data.usedmesg = True
1429statusCheck(False)
1430
1431# prepare for the test
1432if(data.useftrace):
1433 initFtrace()
1434sysvals.initTestOutput()
1435
1436data.vprint("Output files:\n %s" % sysvals.dmesgfile)
1437if(data.useftrace):
1438 data.vprint(" %s" % sysvals.ftracefile)
1439data.vprint(" %s" % sysvals.htmlfile)
1440
1441# execute the test
1442executeSuspend()
1443analyzeKernelLog()
1444if(data.useftrace):
1445 analyzeTraceLog()
1446createHTML()
generated by cgit v1.2.2 (git 2.25.0) at 2025-02-15 02:36:41 -0500