| @@ -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() |