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