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# For kernel versions older than 3.15: 40# The following additional kernel parameters are required: 41# (e.g. in file /etc/default/grub) 42# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." 43# 44 45# ----------------- LIBRARIES -------------------- 46 47import sys 48import time 49import os 50import string 51import re 52import platform 53from datetime import datetime 54import struct 55 56# ----------------- CLASSES -------------------- 57 58# Class: SystemValues 59# Description: 60# A global, single-instance container used to 61# store system values and test parameters 62class SystemValues: 63 version = 3.0 64 verbose = False 65 testdir = '.' 66 tpath = '/sys/kernel/debug/tracing/' 67 fpdtpath = '/sys/firmware/acpi/tables/FPDT' 68 epath = '/sys/kernel/debug/tracing/events/power/' 69 traceevents = [ 70 'suspend_resume', 71 'device_pm_callback_end', 72 'device_pm_callback_start' 73 ] 74 modename = { 75 'freeze': 'Suspend-To-Idle (S0)', 76 'standby': 'Power-On Suspend (S1)', 77 'mem': 'Suspend-to-RAM (S3)', 78 'disk': 'Suspend-to-disk (S4)' 79 } 80 mempath = '/dev/mem' 81 powerfile = '/sys/power/state' 82 suspendmode = 'mem' 83 hostname = 'localhost' 84 prefix = 'test' 85 teststamp = '' 86 dmesgfile = '' 87 ftracefile = '' 88 htmlfile = '' 89 rtcwake = False 90 rtcwaketime = 10 91 rtcpath = '' 92 android = False 93 adb = 'adb' 94 devicefilter = [] 95 stamp = 0 96 execcount = 1 97 x2delay = 0 98 usecallgraph = False 99 usetraceevents = False 100 usetraceeventsonly = False 101 notestrun = False 102 altdevname = dict() 103 postresumetime = 0 104 tracertypefmt = '# tracer: (?P<t>.*)' 105 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' 106 postresumefmt = '# post resume time (?P<t>[0-9]*)$' 107 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ 108 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ 109 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' 110 def __init__(self): 111 self.hostname = platform.node() 112 if(self.hostname == ''): 113 self.hostname = 'localhost' 114 rtc = "rtc0" 115 if os.path.exists('/dev/rtc'): 116 rtc = os.readlink('/dev/rtc') 117 rtc = '/sys/class/rtc/'+rtc 118 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \ 119 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'): 120 self.rtcpath = rtc 121 def setOutputFile(self): 122 if((self.htmlfile == '') and (self.dmesgfile != '')): 123 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) 124 if(m): 125 self.htmlfile = m.group('name')+'.html' 126 if((self.htmlfile == '') and (self.ftracefile != '')): 127 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile) 128 if(m): 129 self.htmlfile = m.group('name')+'.html' 130 if(self.htmlfile == ''): 131 self.htmlfile = 'output.html' 132 def initTestOutput(self, subdir): 133 if(not self.android): 134 self.prefix = self.hostname 135 v = open('/proc/version', 'r').read().strip() 136 kver = string.split(v)[2] 137 else: 138 self.prefix = 'android' 139 v = os.popen(self.adb+' shell cat /proc/version').read().strip() 140 kver = string.split(v)[2] 141 testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S') 142 if(subdir != "."): 143 self.testdir = subdir+"/"+testtime 144 else: 145 self.testdir = testtime 146 self.teststamp = \ 147 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver 148 self.dmesgfile = \ 149 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' 150 self.ftracefile = \ 151 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' 152 self.htmlfile = \ 153 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' 154 os.mkdir(self.testdir) 155 def setDeviceFilter(self, devnames): 156 self.devicefilter = string.split(devnames) 157 def rtcWakeAlarm(self): 158 os.system('echo 0 > '+self.rtcpath+'/wakealarm') 159 outD = open(self.rtcpath+'/date', 'r').read().strip() 160 outT = open(self.rtcpath+'/time', 'r').read().strip() 161 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD) 162 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT) 163 if(mD and mT): 164 # get the current time from hardware 165 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds()) 166 dt = datetime(\ 167 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')), 168 int(mT.group('h')), int(mT.group('m')), int(mT.group('s'))) 169 nowtime = int(dt.strftime('%s')) + utcoffset 170 else: 171 # if hardware time fails, use the software time 172 nowtime = int(datetime.now().strftime('%s')) 173 alarm = nowtime + self.rtcwaketime 174 os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath)) 175 176sysvals = SystemValues() 177 178# Class: DeviceNode 179# Description: 180# A container used to create a device hierachy, with a single root node 181# and a tree of child nodes. Used by Data.deviceTopology() 182class DeviceNode: 183 name = '' 184 children = 0 185 depth = 0 186 def __init__(self, nodename, nodedepth): 187 self.name = nodename 188 self.children = [] 189 self.depth = nodedepth 190 191# Class: Data 192# Description: 193# The primary container for suspend/resume test data. There is one for 194# each test run. The data is organized into a cronological hierarchy: 195# Data.dmesg { 196# root structure, started as dmesg & ftrace, but now only ftrace 197# contents: times for suspend start/end, resume start/end, fwdata 198# phases { 199# 10 sequential, non-overlapping phases of S/R 200# contents: times for phase start/end, order/color data for html 201# devlist { 202# device callback or action list for this phase 203# device { 204# a single device callback or generic action 205# contents: start/stop times, pid/cpu/driver info 206# parents/children, html id for timeline/callgraph 207# optionally includes an ftrace callgraph 208# optionally includes intradev trace events 209# } 210# } 211# } 212# } 213# 214class Data: 215 dmesg = {} # root data structure 216 phases = [] # ordered list of phases 217 start = 0.0 # test start 218 end = 0.0 # test end 219 tSuspended = 0.0 # low-level suspend start 220 tResumed = 0.0 # low-level resume start 221 tLow = 0.0 # time spent in low-level suspend (standby/freeze) 222 fwValid = False # is firmware data available 223 fwSuspend = 0 # time spent in firmware suspend 224 fwResume = 0 # time spent in firmware resume 225 dmesgtext = [] # dmesg text file in memory 226 testnumber = 0 227 idstr = '' 228 html_device_id = 0 229 stamp = 0 230 outfile = '' 231 def __init__(self, num): 232 idchar = 'abcdefghijklmnopqrstuvwxyz' 233 self.testnumber = num 234 self.idstr = idchar[num] 235 self.dmesgtext = [] 236 self.phases = [] 237 self.dmesg = { # fixed list of 10 phases 238 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, 239 'row': 0, 'color': '#CCFFCC', 'order': 0}, 240 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, 241 'row': 0, 'color': '#88FF88', 'order': 1}, 242 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, 243 'row': 0, 'color': '#00AA00', 'order': 2}, 244 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 245 'row': 0, 'color': '#008888', 'order': 3}, 246 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 247 'row': 0, 'color': '#0000FF', 'order': 4}, 248 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 249 'row': 0, 'color': '#FF0000', 'order': 5}, 250 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 251 'row': 0, 'color': '#FF9900', 'order': 6}, 252 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0, 253 'row': 0, 'color': '#FFCC00', 'order': 7}, 254 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0, 255 'row': 0, 'color': '#FFFF88', 'order': 8}, 256 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0, 257 'row': 0, 'color': '#FFFFCC', 'order': 9} 258 } 259 self.phases = self.sortedPhases() 260 def getStart(self): 261 return self.dmesg[self.phases[0]]['start'] 262 def setStart(self, time): 263 self.start = time 264 self.dmesg[self.phases[0]]['start'] = time 265 def getEnd(self): 266 return self.dmesg[self.phases[-1]]['end'] 267 def setEnd(self, time): 268 self.end = time 269 self.dmesg[self.phases[-1]]['end'] = time 270 def isTraceEventOutsideDeviceCalls(self, pid, time): 271 for phase in self.phases: 272 list = self.dmesg[phase]['list'] 273 for dev in list: 274 d = list[dev] 275 if(d['pid'] == pid and time >= d['start'] and 276 time <= d['end']): 277 return False 278 return True 279 def addIntraDevTraceEvent(self, action, name, pid, time): 280 if(action == 'mutex_lock_try'): 281 color = 'red' 282 elif(action == 'mutex_lock_pass'): 283 color = 'green' 284 elif(action == 'mutex_unlock'): 285 color = 'blue' 286 else: 287 # create separate colors based on the name 288 v1 = len(name)*10 % 256 289 v2 = string.count(name, 'e')*100 % 256 290 v3 = ord(name[0])*20 % 256 291 color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3) 292 for phase in self.phases: 293 list = self.dmesg[phase]['list'] 294 for dev in list: 295 d = list[dev] 296 if(d['pid'] == pid and time >= d['start'] and 297 time <= d['end']): 298 e = TraceEvent(action, name, color, time) 299 if('traceevents' not in d): 300 d['traceevents'] = [] 301 d['traceevents'].append(e) 302 return d 303 break 304 return 0 305 def capIntraDevTraceEvent(self, action, name, pid, time): 306 for phase in self.phases: 307 list = self.dmesg[phase]['list'] 308 for dev in list: 309 d = list[dev] 310 if(d['pid'] == pid and time >= d['start'] and 311 time <= d['end']): 312 if('traceevents' not in d): 313 return 314 for e in d['traceevents']: 315 if(e.action == action and 316 e.name == name and not e.ready): 317 e.length = time - e.time 318 e.ready = True 319 break 320 return 321 def trimTimeVal(self, t, t0, dT, left): 322 if left: 323 if(t > t0): 324 if(t - dT < t0): 325 return t0 326 return t - dT 327 else: 328 return t 329 else: 330 if(t < t0 + dT): 331 if(t > t0): 332 return t0 + dT 333 return t + dT 334 else: 335 return t 336 def trimTime(self, t0, dT, left): 337 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left) 338 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left) 339 self.start = self.trimTimeVal(self.start, t0, dT, left) 340 self.end = self.trimTimeVal(self.end, t0, dT, left) 341 for phase in self.phases: 342 p = self.dmesg[phase] 343 p['start'] = self.trimTimeVal(p['start'], t0, dT, left) 344 p['end'] = self.trimTimeVal(p['end'], t0, dT, left) 345 list = p['list'] 346 for name in list: 347 d = list[name] 348 d['start'] = self.trimTimeVal(d['start'], t0, dT, left) 349 d['end'] = self.trimTimeVal(d['end'], t0, dT, left) 350 if('ftrace' in d): 351 cg = d['ftrace'] 352 cg.start = self.trimTimeVal(cg.start, t0, dT, left) 353 cg.end = self.trimTimeVal(cg.end, t0, dT, left) 354 for line in cg.list: 355 line.time = self.trimTimeVal(line.time, t0, dT, left) 356 if('traceevents' in d): 357 for e in d['traceevents']: 358 e.time = self.trimTimeVal(e.time, t0, dT, left) 359 def normalizeTime(self, tZero): 360 # first trim out any standby or freeze clock time 361 if(self.tSuspended != self.tResumed): 362 if(self.tResumed > tZero): 363 self.trimTime(self.tSuspended, \ 364 self.tResumed-self.tSuspended, True) 365 else: 366 self.trimTime(self.tSuspended, \ 367 self.tResumed-self.tSuspended, False) 368 # shift the timeline so that tZero is the new 0 369 self.tSuspended -= tZero 370 self.tResumed -= tZero 371 self.start -= tZero 372 self.end -= tZero 373 for phase in self.phases: 374 p = self.dmesg[phase] 375 p['start'] -= tZero 376 p['end'] -= tZero 377 list = p['list'] 378 for name in list: 379 d = list[name] 380 d['start'] -= tZero 381 d['end'] -= tZero 382 if('ftrace' in d): 383 cg = d['ftrace'] 384 cg.start -= tZero 385 cg.end -= tZero 386 for line in cg.list: 387 line.time -= tZero 388 if('traceevents' in d): 389 for e in d['traceevents']: 390 e.time -= tZero 391 def newPhaseWithSingleAction(self, phasename, devname, start, end, color): 392 for phase in self.phases: 393 self.dmesg[phase]['order'] += 1 394 self.html_device_id += 1 395 devid = '%s%d' % (self.idstr, self.html_device_id) 396 list = dict() 397 list[devname] = \ 398 {'start': start, 'end': end, 'pid': 0, 'par': '', 399 'length': (end-start), 'row': 0, 'id': devid, 'drv': '' }; 400 self.dmesg[phasename] = \ 401 {'list': list, 'start': start, 'end': end, 402 'row': 0, 'color': color, 'order': 0} 403 self.phases = self.sortedPhases() 404 def newPhase(self, phasename, start, end, color, order): 405 if(order < 0): 406 order = len(self.phases) 407 for phase in self.phases[order:]: 408 self.dmesg[phase]['order'] += 1 409 if(order > 0): 410 p = self.phases[order-1] 411 self.dmesg[p]['end'] = start 412 if(order < len(self.phases)): 413 p = self.phases[order] 414 self.dmesg[p]['start'] = end 415 list = dict() 416 self.dmesg[phasename] = \ 417 {'list': list, 'start': start, 'end': end, 418 'row': 0, 'color': color, 'order': order} 419 self.phases = self.sortedPhases() 420 def setPhase(self, phase, ktime, isbegin): 421 if(isbegin): 422 self.dmesg[phase]['start'] = ktime 423 else: 424 self.dmesg[phase]['end'] = ktime 425 def dmesgSortVal(self, phase): 426 return self.dmesg[phase]['order'] 427 def sortedPhases(self): 428 return sorted(self.dmesg, key=self.dmesgSortVal) 429 def sortedDevices(self, phase): 430 list = self.dmesg[phase]['list'] 431 slist = [] 432 tmp = dict() 433 for devname in list: 434 dev = list[devname] 435 tmp[dev['start']] = devname 436 for t in sorted(tmp): 437 slist.append(tmp[t]) 438 return slist 439 def fixupInitcalls(self, phase, end): 440 # if any calls never returned, clip them at system resume end 441 phaselist = self.dmesg[phase]['list'] 442 for devname in phaselist: 443 dev = phaselist[devname] 444 if(dev['end'] < 0): 445 dev['end'] = end 446 vprint('%s (%s): callback didnt return' % (devname, phase)) 447 def deviceFilter(self, devicefilter): 448 # remove all by the relatives of the filter devnames 449 filter = [] 450 for phase in self.phases: 451 list = self.dmesg[phase]['list'] 452 for name in devicefilter: 453 dev = name 454 while(dev in list): 455 if(dev not in filter): 456 filter.append(dev) 457 dev = list[dev]['par'] 458 children = self.deviceDescendants(name, phase) 459 for dev in children: 460 if(dev not in filter): 461 filter.append(dev) 462 for phase in self.phases: 463 list = self.dmesg[phase]['list'] 464 rmlist = [] 465 for name in list: 466 pid = list[name]['pid'] 467 if(name not in filter and pid >= 0): 468 rmlist.append(name) 469 for name in rmlist: 470 del list[name] 471 def fixupInitcallsThatDidntReturn(self): 472 # if any calls never returned, clip them at system resume end 473 for phase in self.phases: 474 self.fixupInitcalls(phase, self.getEnd()) 475 def newActionGlobal(self, name, start, end): 476 # which phase is this device callback or action "in" 477 targetphase = "none" 478 overlap = 0.0 479 for phase in self.phases: 480 pstart = self.dmesg[phase]['start'] 481 pend = self.dmesg[phase]['end'] 482 o = max(0, min(end, pend) - max(start, pstart)) 483 if(o > overlap): 484 targetphase = phase 485 overlap = o 486 if targetphase in self.phases: 487 self.newAction(targetphase, name, -1, '', start, end, '') 488 return True 489 return False 490 def newAction(self, phase, name, pid, parent, start, end, drv): 491 # new device callback for a specific phase 492 self.html_device_id += 1 493 devid = '%s%d' % (self.idstr, self.html_device_id) 494 list = self.dmesg[phase]['list'] 495 length = -1.0 496 if(start >= 0 and end >= 0): 497 length = end - start 498 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, 499 'length': length, 'row': 0, 'id': devid, 'drv': drv } 500 def deviceIDs(self, devlist, phase): 501 idlist = [] 502 list = self.dmesg[phase]['list'] 503 for devname in list: 504 if devname in devlist: 505 idlist.append(list[devname]['id']) 506 return idlist 507 def deviceParentID(self, devname, phase): 508 pdev = '' 509 pdevid = '' 510 list = self.dmesg[phase]['list'] 511 if devname in list: 512 pdev = list[devname]['par'] 513 if pdev in list: 514 return list[pdev]['id'] 515 return pdev 516 def deviceChildren(self, devname, phase): 517 devlist = [] 518 list = self.dmesg[phase]['list'] 519 for child in list: 520 if(list[child]['par'] == devname): 521 devlist.append(child) 522 return devlist 523 def deviceDescendants(self, devname, phase): 524 children = self.deviceChildren(devname, phase) 525 family = children 526 for child in children: 527 family += self.deviceDescendants(child, phase) 528 return family 529 def deviceChildrenIDs(self, devname, phase): 530 devlist = self.deviceChildren(devname, phase) 531 return self.deviceIDs(devlist, phase) 532 def printDetails(self): 533 vprint(' test start: %f' % self.start) 534 for phase in self.phases: 535 dc = len(self.dmesg[phase]['list']) 536 vprint(' %16s: %f - %f (%d devices)' % (phase, \ 537 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) 538 vprint(' test end: %f' % self.end) 539 def masterTopology(self, name, list, depth): 540 node = DeviceNode(name, depth) 541 for cname in list: 542 clist = self.deviceChildren(cname, 'resume') 543 cnode = self.masterTopology(cname, clist, depth+1) 544 node.children.append(cnode) 545 return node 546 def printTopology(self, node): 547 html = '' 548 if node.name: 549 info = '' 550 drv = '' 551 for phase in self.phases: 552 list = self.dmesg[phase]['list'] 553 if node.name in list: 554 s = list[node.name]['start'] 555 e = list[node.name]['end'] 556 if list[node.name]['drv']: 557 drv = ' {'+list[node.name]['drv']+'}' 558 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000)) 559 html += '<li><b>'+node.name+drv+'</b>' 560 if info: 561 html += '<ul>'+info+'</ul>' 562 html += '</li>' 563 if len(node.children) > 0: 564 html += '<ul>' 565 for cnode in node.children: 566 html += self.printTopology(cnode) 567 html += '</ul>' 568 return html 569 def rootDeviceList(self): 570 # list of devices graphed 571 real = [] 572 for phase in self.dmesg: 573 list = self.dmesg[phase]['list'] 574 for dev in list: 575 if list[dev]['pid'] >= 0 and dev not in real: 576 real.append(dev) 577 # list of top-most root devices 578 rootlist = [] 579 for phase in self.dmesg: 580 list = self.dmesg[phase]['list'] 581 for dev in list: 582 pdev = list[dev]['par'] 583 if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): 584 continue 585 if pdev and pdev not in real and pdev not in rootlist: 586 rootlist.append(pdev) 587 return rootlist 588 def deviceTopology(self): 589 rootlist = self.rootDeviceList() 590 master = self.masterTopology('', rootlist, 0) 591 return self.printTopology(master) 592 593# Class: TraceEvent 594# Description: 595# A container for trace event data found in the ftrace file 596class TraceEvent: 597 ready = False 598 name = '' 599 time = 0.0 600 color = '#FFFFFF' 601 length = 0.0 602 action = '' 603 def __init__(self, a, n, c, t): 604 self.action = a 605 self.name = n 606 self.color = c 607 self.time = t 608 609# Class: FTraceLine 610# Description: 611# A container for a single line of ftrace data. There are six basic types: 612# callgraph line: 613# call: " dpm_run_callback() {" 614# return: " }" 615# leaf: " dpm_run_callback();" 616# trace event: 617# tracing_mark_write: SUSPEND START or RESUME COMPLETE 618# suspend_resume: phase or custom exec block data 619# device_pm_callback: device callback info 620class FTraceLine: 621 time = 0.0 622 length = 0.0 623 fcall = False 624 freturn = False 625 fevent = False 626 depth = 0 627 name = '' 628 type = '' 629 def __init__(self, t, m, d): 630 self.time = float(t) 631 # is this a trace event 632 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)): 633 if(d == 'traceevent'): 634 # nop format trace event 635 msg = m 636 else: 637 # function_graph format trace event 638 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m) 639 msg = em.group('msg') 640 641 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg) 642 if(emm): 643 self.name = emm.group('msg') 644 self.type = emm.group('call') 645 else: 646 self.name = msg 647 self.fevent = True 648 return 649 # convert the duration to seconds 650 if(d): 651 self.length = float(d)/1000000 652 # the indentation determines the depth 653 match = re.match('^(?P<d> *)(?P<o>.*)$', m) 654 if(not match): 655 return 656 self.depth = self.getDepth(match.group('d')) 657 m = match.group('o') 658 # function return 659 if(m[0] == '}'): 660 self.freturn = True 661 if(len(m) > 1): 662 # includes comment with function name 663 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m) 664 if(match): 665 self.name = match.group('n') 666 # function call 667 else: 668 self.fcall = True 669 # function call with children 670 if(m[-1] == '{'): 671 match = re.match('^(?P<n>.*) *\(.*', m) 672 if(match): 673 self.name = match.group('n') 674 # function call with no children (leaf) 675 elif(m[-1] == ';'): 676 self.freturn = True 677 match = re.match('^(?P<n>.*) *\(.*', m) 678 if(match): 679 self.name = match.group('n') 680 # something else (possibly a trace marker) 681 else: 682 self.name = m 683 def getDepth(self, str): 684 return len(str)/2 685 def debugPrint(self, dev): 686 if(self.freturn and self.fcall): 687 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ 688 self.depth, self.name, self.length*1000000)) 689 elif(self.freturn): 690 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ 691 self.depth, self.name, self.length*1000000)) 692 else: 693 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ 694 self.depth, self.name, self.length*1000000)) 695 696# Class: FTraceCallGraph 697# Description: 698# A container for the ftrace callgraph of a single recursive function. 699# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph 700# Each instance is tied to a single device in a single phase, and is 701# comprised of an ordered list of FTraceLine objects 702class FTraceCallGraph: 703 start = -1.0 704 end = -1.0 705 list = [] 706 invalid = False 707 depth = 0 708 def __init__(self): 709 self.start = -1.0 710 self.end = -1.0 711 self.list = [] 712 self.depth = 0 713 def setDepth(self, line): 714 if(line.fcall and not line.freturn): 715 line.depth = self.depth 716 self.depth += 1 717 elif(line.freturn and not line.fcall): 718 self.depth -= 1 719 line.depth = self.depth 720 else: 721 line.depth = self.depth 722 def addLine(self, line, match): 723 if(not self.invalid): 724 self.setDepth(line) 725 if(line.depth == 0 and line.freturn): 726 if(self.start < 0): 727 self.start = line.time 728 self.end = line.time 729 self.list.append(line) 730 return True 731 if(self.invalid): 732 return False 733 if(len(self.list) >= 1000000 or self.depth < 0): 734 if(len(self.list) > 0): 735 first = self.list[0] 736 self.list = [] 737 self.list.append(first) 738 self.invalid = True 739 if(not match): 740 return False 741 id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu')) 742 window = '(%f - %f)' % (self.start, line.time) 743 if(self.depth < 0): 744 print('Too much data for '+id+\ 745 ' (buffer overflow), ignoring this callback') 746 else: 747 print('Too much data for '+id+\ 748 ' '+window+', ignoring this callback') 749 return False 750 self.list.append(line) 751 if(self.start < 0): 752 self.start = line.time 753 return False 754 def slice(self, t0, tN): 755 minicg = FTraceCallGraph() 756 count = -1 757 firstdepth = 0 758 for l in self.list: 759 if(l.time < t0 or l.time > tN): 760 continue 761 if(count < 0): 762 if(not l.fcall or l.name == 'dev_driver_string'): 763 continue 764 firstdepth = l.depth 765 count = 0 766 l.depth -= firstdepth 767 minicg.addLine(l, 0) 768 if((count == 0 and l.freturn and l.fcall) or 769 (count > 0 and l.depth <= 0)): 770 break 771 count += 1 772 return minicg 773 def sanityCheck(self): 774 stack = dict() 775 cnt = 0 776 for l in self.list: 777 if(l.fcall and not l.freturn): 778 stack[l.depth] = l 779 cnt += 1 780 elif(l.freturn and not l.fcall): 781 if(l.depth not in stack): 782 return False 783 stack[l.depth].length = l.length 784 stack[l.depth] = 0 785 l.length = 0 786 cnt -= 1 787 if(cnt == 0): 788 return True 789 return False 790 def debugPrint(self, filename): 791 if(filename == 'stdout'): 792 print('[%f - %f]') % (self.start, self.end) 793 for l in self.list: 794 if(l.freturn and l.fcall): 795 print('%f (%02d): %s(); (%.3f us)' % (l.time, \ 796 l.depth, l.name, l.length*1000000)) 797 elif(l.freturn): 798 print('%f (%02d): %s} (%.3f us)' % (l.time, \ 799 l.depth, l.name, l.length*1000000)) 800 else: 801 print('%f (%02d): %s() { (%.3f us)' % (l.time, \ 802 l.depth, l.name, l.length*1000000)) 803 print(' ') 804 else: 805 fp = open(filename, 'w') 806 print(filename) 807 for l in self.list: 808 if(l.freturn and l.fcall): 809 fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \ 810 l.depth, l.name, l.length*1000000)) 811 elif(l.freturn): 812 fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \ 813 l.depth, l.name, l.length*1000000)) 814 else: 815 fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \ 816 l.depth, l.name, l.length*1000000)) 817 fp.close() 818 819# Class: Timeline 820# Description: 821# A container for a suspend/resume html timeline. In older versions 822# of the script there were multiple timelines, but in the latest 823# there is only one. 824class Timeline: 825 html = {} 826 scaleH = 0.0 # height of the row as a percent of the timeline height 827 rowH = 0.0 # height of each row in percent of the timeline height 828 row_height_pixels = 30 829 maxrows = 0 830 height = 0 831 def __init__(self): 832 self.html = { 833 'timeline': '', 834 'legend': '', 835 'scale': '' 836 } 837 def setRows(self, rows): 838 self.maxrows = int(rows) 839 self.scaleH = 100.0/float(self.maxrows) 840 self.height = self.maxrows*self.row_height_pixels 841 r = float(self.maxrows - 1) 842 if(r < 1.0): 843 r = 1.0 844 self.rowH = (100.0 - self.scaleH)/r 845 846# Class: TestRun 847# Description: 848# A container for a suspend/resume test run. This is necessary as 849# there could be more than one, and they need to be separate. 850class TestRun: 851 ftrace_line_fmt_fg = \ 852 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ 853 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ 854 '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' 855 ftrace_line_fmt_nop = \ 856 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ 857 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ 858 '(?P<msg>.*)' 859 ftrace_line_fmt = ftrace_line_fmt_nop 860 cgformat = False 861 ftemp = dict() 862 ttemp = dict() 863 inthepipe = False 864 tracertype = '' 865 data = 0 866 def __init__(self, dataobj): 867 self.data = dataobj 868 self.ftemp = dict() 869 self.ttemp = dict() 870 def isReady(self): 871 if(tracertype == '' or not data): 872 return False 873 return True 874 def setTracerType(self, tracer): 875 self.tracertype = tracer 876 if(tracer == 'function_graph'): 877 self.cgformat = True 878 self.ftrace_line_fmt = self.ftrace_line_fmt_fg 879 elif(tracer == 'nop'): 880 self.ftrace_line_fmt = self.ftrace_line_fmt_nop 881 else: 882 doError('Invalid tracer format: [%s]' % tracer, False) 883 884# ----------------- FUNCTIONS -------------------- 885 886# Function: vprint 887# Description: 888# verbose print (prints only with -verbose option) 889# Arguments: 890# msg: the debug/log message to print 891def vprint(msg): 892 global sysvals 893 if(sysvals.verbose): 894 print(msg) 895 896# Function: initFtrace 897# Description: 898# Configure ftrace to use trace events and/or a callgraph 899def initFtrace(): 900 global sysvals 901 902 tp = sysvals.tpath 903 cf = 'dpm_run_callback' 904 if(sysvals.usetraceeventsonly): 905 cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback' 906 if(sysvals.usecallgraph or sysvals.usetraceevents): 907 print('INITIALIZING FTRACE...') 908 # turn trace off 909 os.system('echo 0 > '+tp+'tracing_on') 910 # set the trace clock to global 911 os.system('echo global > '+tp+'trace_clock') 912 # set trace buffer to a huge value 913 os.system('echo nop > '+tp+'current_tracer') 914 os.system('echo 100000 > '+tp+'buffer_size_kb') 915 # initialize the callgraph trace, unless this is an x2 run 916 if(sysvals.usecallgraph and sysvals.execcount == 1): 917 # set trace type 918 os.system('echo function_graph > '+tp+'current_tracer') 919 os.system('echo "" > '+tp+'set_ftrace_filter') 920 # set trace format options 921 os.system('echo funcgraph-abstime > '+tp+'trace_options') 922 os.system('echo funcgraph-proc > '+tp+'trace_options') 923 # focus only on device suspend and resume 924 os.system('cat '+tp+'available_filter_functions | grep '+\ 925 cf+' > '+tp+'set_graph_function') 926 if(sysvals.usetraceevents): 927 # turn trace events on 928 events = iter(sysvals.traceevents) 929 for e in events: 930 os.system('echo 1 > '+sysvals.epath+e+'/enable') 931 # clear the trace buffer 932 os.system('echo "" > '+tp+'trace') 933 934# Function: initFtraceAndroid 935# Description: 936# Configure ftrace to capture trace events 937def initFtraceAndroid(): 938 global sysvals 939 940 tp = sysvals.tpath 941 if(sysvals.usetraceevents): 942 print('INITIALIZING FTRACE...') 943 # turn trace off 944 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'") 945 # set the trace clock to global 946 os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'") 947 # set trace buffer to a huge value 948 os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'") 949 os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'") 950 # turn trace events on 951 events = iter(sysvals.traceevents) 952 for e in events: 953 os.system(sysvals.adb+" shell 'echo 1 > "+\ 954 sysvals.epath+e+"/enable'") 955 # clear the trace buffer 956 os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'") 957 958# Function: verifyFtrace 959# Description: 960# Check that ftrace is working on the system 961# Output: 962# True or False 963def verifyFtrace(): 964 global sysvals 965 # files needed for any trace data 966 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock', 967 'trace_marker', 'trace_options', 'tracing_on'] 968 # files needed for callgraph trace data 969 tp = sysvals.tpath 970 if(sysvals.usecallgraph): 971 files += [ 972 'available_filter_functions', 973 'set_ftrace_filter', 974 'set_graph_function' 975 ] 976 for f in files: 977 if(sysvals.android): 978 out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip() 979 if(out != tp+f): 980 return False 981 else: 982 if(os.path.exists(tp+f) == False): 983 return False 984 return True 985 986# Function: parseStamp 987# Description: 988# Pull in the stamp comment line from the data file(s), 989# create the stamp, and add it to the global sysvals object 990# Arguments: 991# m: the valid re.match output for the stamp line 992def parseStamp(m, data): 993 global sysvals 994 data.stamp = {'time': '', 'host': '', 'mode': ''} 995 dt = datetime(int(m.group('y'))+2000, int(m.group('m')), 996 int(m.group('d')), int(m.group('H')), int(m.group('M')), 997 int(m.group('S'))) 998 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p') 999 data.stamp['host'] = m.group('host') 1000 data.stamp['mode'] = m.group('mode') 1001 data.stamp['kernel'] = m.group('kernel') 1002 sysvals.suspendmode = data.stamp['mode'] 1003 if not sysvals.stamp: 1004 sysvals.stamp = data.stamp 1005 1006# Function: diffStamp 1007# Description: 1008# compare the host, kernel, and mode fields in 3 stamps 1009# Arguments: 1010# stamp1: string array with mode, kernel, and host 1011# stamp2: string array with mode, kernel, and host 1012# Return: 1013# True if stamps differ, False if they're the same 1014def diffStamp(stamp1, stamp2): 1015 if 'host' in stamp1 and 'host' in stamp2: 1016 if stamp1['host'] != stamp2['host']: 1017 return True 1018 if 'kernel' in stamp1 and 'kernel' in stamp2: 1019 if stamp1['kernel'] != stamp2['kernel']: 1020 return True 1021 if 'mode' in stamp1 and 'mode' in stamp2: 1022 if stamp1['mode'] != stamp2['mode']: 1023 return True 1024 return False 1025 1026# Function: doesTraceLogHaveTraceEvents 1027# Description: 1028# Quickly determine if the ftrace log has some or all of the trace events 1029# required for primary parsing. Set the usetraceevents and/or 1030# usetraceeventsonly flags in the global sysvals object 1031def doesTraceLogHaveTraceEvents(): 1032 global sysvals 1033 1034 sysvals.usetraceeventsonly = True 1035 sysvals.usetraceevents = False 1036 for e in sysvals.traceevents: 1037 out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read() 1038 if(not out): 1039 sysvals.usetraceeventsonly = False 1040 if(e == 'suspend_resume' and out): 1041 sysvals.usetraceevents = True 1042 1043# Function: appendIncompleteTraceLog 1044# Description: 1045# [deprecated for kernel 3.15 or newer] 1046# Legacy support of ftrace outputs that lack the device_pm_callback 1047# and/or suspend_resume trace events. The primary data should be 1048# taken from dmesg, and this ftrace is used only for callgraph data 1049# or custom actions in the timeline. The data is appended to the Data 1050# objects provided. 1051# Arguments: 1052# testruns: the array of Data objects obtained from parseKernelLog 1053def appendIncompleteTraceLog(testruns): 1054 global sysvals 1055 1056 # create TestRun vessels for ftrace parsing 1057 testcnt = len(testruns) 1058 testidx = -1 1059 testrun = [] 1060 for data in testruns: 1061 testrun.append(TestRun(data)) 1062 1063 # extract the callgraph and traceevent data 1064 vprint('Analyzing the ftrace data...') 1065 tf = open(sysvals.ftracefile, 'r') 1066 for line in tf: 1067 # remove any latent carriage returns 1068 line = line.replace('\r\n', '') 1069 # grab the time stamp first (signifies the start of the test run) 1070 m = re.match(sysvals.stampfmt, line) 1071 if(m): 1072 testidx += 1 1073 parseStamp(m, testrun[testidx].data) 1074 continue 1075 # pull out any firmware data 1076 if(re.match(sysvals.firmwarefmt, line)): 1077 continue 1078 # if we havent found a test time stamp yet keep spinning til we do 1079 if(testidx < 0): 1080 continue 1081 # determine the trace data type (required for further parsing) 1082 m = re.match(sysvals.tracertypefmt, line) 1083 if(m): 1084 tracer = m.group('t') 1085 testrun[testidx].setTracerType(tracer) 1086 continue 1087 # parse only valid lines, if this isnt one move on 1088 m = re.match(testrun[testidx].ftrace_line_fmt, line) 1089 if(not m): 1090 continue 1091 # gather the basic message data from the line 1092 m_time = m.group('time') 1093 m_pid = m.group('pid') 1094 m_msg = m.group('msg') 1095 if(testrun[testidx].cgformat): 1096 m_param3 = m.group('dur') 1097 else: 1098 m_param3 = 'traceevent' 1099 if(m_time and m_pid and m_msg): 1100 t = FTraceLine(m_time, m_msg, m_param3) 1101 pid = int(m_pid) 1102 else: 1103 continue 1104 # the line should be a call, return, or event 1105 if(not t.fcall and not t.freturn and not t.fevent): 1106 continue 1107 # only parse the ftrace data during suspend/resume 1108 data = testrun[testidx].data 1109 if(not testrun[testidx].inthepipe): 1110 # look for the suspend start marker 1111 if(t.fevent): 1112 if(t.name == 'SUSPEND START'): 1113 testrun[testidx].inthepipe = True 1114 data.setStart(t.time) 1115 continue 1116 else: 1117 # trace event processing 1118 if(t.fevent): 1119 if(t.name == 'RESUME COMPLETE'): 1120 testrun[testidx].inthepipe = False 1121 data.setEnd(t.time) 1122 if(testidx == testcnt - 1): 1123 break 1124 continue 1125 # general trace events have two types, begin and end 1126 if(re.match('(?P<name>.*) begin$', t.name)): 1127 isbegin = True 1128 elif(re.match('(?P<name>.*) end$', t.name)): 1129 isbegin = False 1130 else: 1131 continue 1132 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 1133 if(m): 1134 val = m.group('val') 1135 if val == '0': 1136 name = m.group('name') 1137 else: 1138 name = m.group('name')+'['+val+']' 1139 else: 1140 m = re.match('(?P<name>.*) .*', t.name) 1141 name = m.group('name') 1142 # special processing for trace events 1143 if re.match('dpm_prepare\[.*', name): 1144 continue 1145 elif re.match('machine_suspend.*', name): 1146 continue 1147 elif re.match('suspend_enter\[.*', name): 1148 if(not isbegin): 1149 data.dmesg['suspend_prepare']['end'] = t.time 1150 continue 1151 elif re.match('dpm_suspend\[.*', name): 1152 if(not isbegin): 1153 data.dmesg['suspend']['end'] = t.time 1154 continue 1155 elif re.match('dpm_suspend_late\[.*', name): 1156 if(isbegin): 1157 data.dmesg['suspend_late']['start'] = t.time 1158 else: 1159 data.dmesg['suspend_late']['end'] = t.time 1160 continue 1161 elif re.match('dpm_suspend_noirq\[.*', name): 1162 if(isbegin): 1163 data.dmesg['suspend_noirq']['start'] = t.time 1164 else: 1165 data.dmesg['suspend_noirq']['end'] = t.time 1166 continue 1167 elif re.match('dpm_resume_noirq\[.*', name): 1168 if(isbegin): 1169 data.dmesg['resume_machine']['end'] = t.time 1170 data.dmesg['resume_noirq']['start'] = t.time 1171 else: 1172 data.dmesg['resume_noirq']['end'] = t.time 1173 continue 1174 elif re.match('dpm_resume_early\[.*', name): 1175 if(isbegin): 1176 data.dmesg['resume_early']['start'] = t.time 1177 else: 1178 data.dmesg['resume_early']['end'] = t.time 1179 continue 1180 elif re.match('dpm_resume\[.*', name): 1181 if(isbegin): 1182 data.dmesg['resume']['start'] = t.time 1183 else: 1184 data.dmesg['resume']['end'] = t.time 1185 continue 1186 elif re.match('dpm_complete\[.*', name): 1187 if(isbegin): 1188 data.dmesg['resume_complete']['start'] = t.time 1189 else: 1190 data.dmesg['resume_complete']['end'] = t.time 1191 continue 1192 # is this trace event outside of the devices calls 1193 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): 1194 # global events (outside device calls) are simply graphed 1195 if(isbegin): 1196 # store each trace event in ttemp 1197 if(name not in testrun[testidx].ttemp): 1198 testrun[testidx].ttemp[name] = [] 1199 testrun[testidx].ttemp[name].append(\ 1200 {'begin': t.time, 'end': t.time}) 1201 else: 1202 # finish off matching trace event in ttemp 1203 if(name in testrun[testidx].ttemp): 1204 testrun[testidx].ttemp[name][-1]['end'] = t.time 1205 else: 1206 if(isbegin): 1207 data.addIntraDevTraceEvent('', name, pid, t.time) 1208 else: 1209 data.capIntraDevTraceEvent('', name, pid, t.time) 1210 # call/return processing 1211 elif sysvals.usecallgraph: 1212 # create a callgraph object for the data 1213 if(pid not in testrun[testidx].ftemp): 1214 testrun[testidx].ftemp[pid] = [] 1215 testrun[testidx].ftemp[pid].append(FTraceCallGraph()) 1216 # when the call is finished, see which device matches it 1217 cg = testrun[testidx].ftemp[pid][-1] 1218 if(cg.addLine(t, m)): 1219 testrun[testidx].ftemp[pid].append(FTraceCallGraph()) 1220 tf.close() 1221 1222 for test in testrun: 1223 # add the traceevent data to the device hierarchy 1224 if(sysvals.usetraceevents): 1225 for name in test.ttemp: 1226 for event in test.ttemp[name]: 1227 begin = event['begin'] 1228 end = event['end'] 1229 # if event starts before timeline start, expand timeline 1230 if(begin < test.data.start): 1231 test.data.setStart(begin) 1232 # if event ends after timeline end, expand the timeline 1233 if(end > test.data.end): 1234 test.data.setEnd(end) 1235 test.data.newActionGlobal(name, begin, end) 1236 1237 # add the callgraph data to the device hierarchy 1238 for pid in test.ftemp: 1239 for cg in test.ftemp[pid]: 1240 if(not cg.sanityCheck()): 1241 id = 'task %s cpu %s' % (pid, m.group('cpu')) 1242 vprint('Sanity check failed for '+\ 1243 id+', ignoring this callback') 1244 continue 1245 callstart = cg.start 1246 callend = cg.end 1247 for p in test.data.phases: 1248 if(test.data.dmesg[p]['start'] <= callstart and 1249 callstart <= test.data.dmesg[p]['end']): 1250 list = test.data.dmesg[p]['list'] 1251 for devname in list: 1252 dev = list[devname] 1253 if(pid == dev['pid'] and 1254 callstart <= dev['start'] and 1255 callend >= dev['end']): 1256 dev['ftrace'] = cg 1257 break 1258 1259 if(sysvals.verbose): 1260 test.data.printDetails() 1261 1262 1263 # add the time in between the tests as a new phase so we can see it 1264 if(len(testruns) > 1): 1265 t1e = testruns[0].getEnd() 1266 t2s = testruns[-1].getStart() 1267 testruns[-1].newPhaseWithSingleAction('user mode', \ 1268 'user mode', t1e, t2s, '#FF9966') 1269 1270# Function: parseTraceLog 1271# Description: 1272# Analyze an ftrace log output file generated from this app during 1273# the execution phase. Used when the ftrace log is the primary data source 1274# and includes the suspend_resume and device_pm_callback trace events 1275# The ftrace filename is taken from sysvals 1276# Output: 1277# An array of Data objects 1278def parseTraceLog(): 1279 global sysvals 1280 1281 vprint('Analyzing the ftrace data...') 1282 if(os.path.exists(sysvals.ftracefile) == False): 1283 doError('%s doesnt exist' % sysvals.ftracefile, False) 1284 1285 # extract the callgraph and traceevent data 1286 testruns = [] 1287 testdata = [] 1288 testrun = 0 1289 data = 0 1290 tf = open(sysvals.ftracefile, 'r') 1291 phase = 'suspend_prepare' 1292 for line in tf: 1293 # remove any latent carriage returns 1294 line = line.replace('\r\n', '') 1295 # stamp line: each stamp means a new test run 1296 m = re.match(sysvals.stampfmt, line) 1297 if(m): 1298 data = Data(len(testdata)) 1299 testdata.append(data) 1300 testrun = TestRun(data) 1301 testruns.append(testrun) 1302 parseStamp(m, data) 1303 continue 1304 if(not data): 1305 continue 1306 # firmware line: pull out any firmware data 1307 m = re.match(sysvals.firmwarefmt, line) 1308 if(m): 1309 data.fwSuspend = int(m.group('s')) 1310 data.fwResume = int(m.group('r')) 1311 if(data.fwSuspend > 0 or data.fwResume > 0): 1312 data.fwValid = True 1313 continue 1314 # tracer type line: determine the trace data type 1315 m = re.match(sysvals.tracertypefmt, line) 1316 if(m): 1317 tracer = m.group('t') 1318 testrun.setTracerType(tracer) 1319 continue 1320 # post resume time line: did this test run include post-resume data 1321 m = re.match(sysvals.postresumefmt, line) 1322 if(m): 1323 t = int(m.group('t')) 1324 if(t > 0): 1325 sysvals.postresumetime = t 1326 continue 1327 # ftrace line: parse only valid lines 1328 m = re.match(testrun.ftrace_line_fmt, line) 1329 if(not m): 1330 continue 1331 # gather the basic message data from the line 1332 m_time = m.group('time') 1333 m_pid = m.group('pid') 1334 m_msg = m.group('msg') 1335 if(testrun.cgformat): 1336 m_param3 = m.group('dur') 1337 else: 1338 m_param3 = 'traceevent' 1339 if(m_time and m_pid and m_msg): 1340 t = FTraceLine(m_time, m_msg, m_param3) 1341 pid = int(m_pid) 1342 else: 1343 continue 1344 # the line should be a call, return, or event 1345 if(not t.fcall and not t.freturn and not t.fevent): 1346 continue 1347 # only parse the ftrace data during suspend/resume 1348 if(not testrun.inthepipe): 1349 # look for the suspend start marker 1350 if(t.fevent): 1351 if(t.name == 'SUSPEND START'): 1352 testrun.inthepipe = True 1353 data.setStart(t.time) 1354 continue 1355 # trace event processing 1356 if(t.fevent): 1357 if(t.name == 'RESUME COMPLETE'): 1358 if(sysvals.postresumetime > 0): 1359 phase = 'post_resume' 1360 data.newPhase(phase, t.time, t.time, '#FF9966', -1) 1361 else: 1362 testrun.inthepipe = False 1363 data.setEnd(t.time) 1364 continue 1365 if(phase == 'post_resume'): 1366 data.setEnd(t.time) 1367 if(t.type == 'suspend_resume'): 1368 # suspend_resume trace events have two types, begin and end 1369 if(re.match('(?P<name>.*) begin$', t.name)): 1370 isbegin = True 1371 elif(re.match('(?P<name>.*) end$', t.name)): 1372 isbegin = False 1373 else: 1374 continue 1375 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 1376 if(m): 1377 val = m.group('val') 1378 if val == '0': 1379 name = m.group('name') 1380 else: 1381 name = m.group('name')+'['+val+']' 1382 else: 1383 m = re.match('(?P<name>.*) .*', t.name) 1384 name = m.group('name') 1385 # ignore these events 1386 if(re.match('acpi_suspend\[.*', t.name) or 1387 re.match('suspend_enter\[.*', name)): 1388 continue 1389 # -- phase changes -- 1390 # suspend_prepare start 1391 if(re.match('dpm_prepare\[.*', t.name)): 1392 phase = 'suspend_prepare' 1393 if(not isbegin): 1394 data.dmesg[phase]['end'] = t.time 1395 continue 1396 # suspend start 1397 elif(re.match('dpm_suspend\[.*', t.name)): 1398 phase = 'suspend' 1399 data.setPhase(phase, t.time, isbegin) 1400 continue 1401 # suspend_late start 1402 elif(re.match('dpm_suspend_late\[.*', t.name)): 1403 phase = 'suspend_late' 1404 data.setPhase(phase, t.time, isbegin) 1405 continue 1406 # suspend_noirq start 1407 elif(re.match('dpm_suspend_noirq\[.*', t.name)): 1408 phase = 'suspend_noirq' 1409 data.setPhase(phase, t.time, isbegin) 1410 if(not isbegin): 1411 phase = 'suspend_machine' 1412 data.dmesg[phase]['start'] = t.time 1413 continue 1414 # suspend_machine/resume_machine 1415 elif(re.match('machine_suspend\[.*', t.name)): 1416 if(isbegin): 1417 phase = 'suspend_machine' 1418 data.dmesg[phase]['end'] = t.time 1419 data.tSuspended = t.time 1420 else: 1421 if(sysvals.suspendmode in ['mem', 'disk']): 1422 data.dmesg['suspend_machine']['end'] = t.time 1423 data.tSuspended = t.time 1424 phase = 'resume_machine' 1425 data.dmesg[phase]['start'] = t.time 1426 data.tResumed = t.time 1427 data.tLow = data.tResumed - data.tSuspended 1428 continue 1429 # resume_noirq start 1430 elif(re.match('dpm_resume_noirq\[.*', t.name)): 1431 phase = 'resume_noirq' 1432 data.setPhase(phase, t.time, isbegin) 1433 if(isbegin): 1434 data.dmesg['resume_machine']['end'] = t.time 1435 continue 1436 # resume_early start 1437 elif(re.match('dpm_resume_early\[.*', t.name)): 1438 phase = 'resume_early' 1439 data.setPhase(phase, t.time, isbegin) 1440 continue 1441 # resume start 1442 elif(re.match('dpm_resume\[.*', t.name)): 1443 phase = 'resume' 1444 data.setPhase(phase, t.time, isbegin) 1445 continue 1446 # resume complete start 1447 elif(re.match('dpm_complete\[.*', t.name)): 1448 phase = 'resume_complete' 1449 if(isbegin): 1450 data.dmesg[phase]['start'] = t.time 1451 continue 1452 1453 # is this trace event outside of the devices calls 1454 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)): 1455 # global events (outside device calls) are simply graphed 1456 if(name not in testrun.ttemp): 1457 testrun.ttemp[name] = [] 1458 if(isbegin): 1459 # create a new list entry 1460 testrun.ttemp[name].append(\ 1461 {'begin': t.time, 'end': t.time}) 1462 else: 1463 if(len(testrun.ttemp[name]) > 0): 1464 # if an antry exists, assume this is its end 1465 testrun.ttemp[name][-1]['end'] = t.time 1466 elif(phase == 'post_resume'): 1467 # post resume events can just have ends 1468 testrun.ttemp[name].append({ 1469 'begin': data.dmesg[phase]['start'], 1470 'end': t.time}) 1471 else: 1472 if(isbegin): 1473 data.addIntraDevTraceEvent('', name, pid, t.time) 1474 else: 1475 data.capIntraDevTraceEvent('', name, pid, t.time) 1476 # device callback start 1477 elif(t.type == 'device_pm_callback_start'): 1478 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ 1479 t.name); 1480 if(not m): 1481 continue 1482 drv = m.group('drv') 1483 n = m.group('d') 1484 p = m.group('p') 1485 if(n and p): 1486 data.newAction(phase, n, pid, p, t.time, -1, drv) 1487 # device callback finish 1488 elif(t.type == 'device_pm_callback_end'): 1489 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name); 1490 if(not m): 1491 continue 1492 n = m.group('d') 1493 list = data.dmesg[phase]['list'] 1494 if(n in list): 1495 dev = list[n] 1496 dev['length'] = t.time - dev['start'] 1497 dev['end'] = t.time 1498 # callgraph processing 1499 elif sysvals.usecallgraph: 1500 # this shouldn't happen, but JIC, ignore callgraph data post-res 1501 if(phase == 'post_resume'): 1502 continue 1503 # create a callgraph object for the data 1504 if(pid not in testrun.ftemp): 1505 testrun.ftemp[pid] = [] 1506 testrun.ftemp[pid].append(FTraceCallGraph()) 1507 # when the call is finished, see which device matches it 1508 cg = testrun.ftemp[pid][-1] 1509 if(cg.addLine(t, m)): 1510 testrun.ftemp[pid].append(FTraceCallGraph()) 1511 tf.close() 1512 1513 for test in testruns: 1514 # add the traceevent data to the device hierarchy 1515 if(sysvals.usetraceevents): 1516 for name in test.ttemp: 1517 for event in test.ttemp[name]: 1518 begin = event['begin'] 1519 end = event['end'] 1520 # if event starts before timeline start, expand timeline 1521 if(begin < test.data.start): 1522 test.data.setStart(begin) 1523 # if event ends after timeline end, expand the timeline 1524 if(end > test.data.end): 1525 test.data.setEnd(end) 1526 test.data.newActionGlobal(name, begin, end) 1527 1528 # add the callgraph data to the device hierarchy 1529 borderphase = { 1530 'dpm_prepare': 'suspend_prepare', 1531 'dpm_complete': 'resume_complete' 1532 } 1533 for pid in test.ftemp: 1534 for cg in test.ftemp[pid]: 1535 if len(cg.list) < 2: 1536 continue 1537 if(not cg.sanityCheck()): 1538 id = 'task %s cpu %s' % (pid, m.group('cpu')) 1539 vprint('Sanity check failed for '+\ 1540 id+', ignoring this callback') 1541 continue 1542 callstart = cg.start 1543 callend = cg.end 1544 if(cg.list[0].name in borderphase): 1545 p = borderphase[cg.list[0].name] 1546 list = test.data.dmesg[p]['list'] 1547 for devname in list: 1548 dev = list[devname] 1549 if(pid == dev['pid'] and 1550 callstart <= dev['start'] and 1551 callend >= dev['end']): 1552 dev['ftrace'] = cg.slice(dev['start'], dev['end']) 1553 continue 1554 if(cg.list[0].name != 'dpm_run_callback'): 1555 continue 1556 for p in test.data.phases: 1557 if(test.data.dmesg[p]['start'] <= callstart and 1558 callstart <= test.data.dmesg[p]['end']): 1559 list = test.data.dmesg[p]['list'] 1560 for devname in list: 1561 dev = list[devname] 1562 if(pid == dev['pid'] and 1563 callstart <= dev['start'] and 1564 callend >= dev['end']): 1565 dev['ftrace'] = cg 1566 break 1567 1568 # fill in any missing phases 1569 for data in testdata: 1570 lp = data.phases[0] 1571 for p in data.phases: 1572 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 1573 print('WARNING: phase "%s" is missing!' % p) 1574 if(data.dmesg[p]['start'] < 0): 1575 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 1576 if(p == 'resume_machine'): 1577 data.tSuspended = data.dmesg[lp]['end'] 1578 data.tResumed = data.dmesg[lp]['end'] 1579 data.tLow = 0 1580 if(data.dmesg[p]['end'] < 0): 1581 data.dmesg[p]['end'] = data.dmesg[p]['start'] 1582 lp = p 1583 1584 if(len(sysvals.devicefilter) > 0): 1585 data.deviceFilter(sysvals.devicefilter) 1586 data.fixupInitcallsThatDidntReturn() 1587 if(sysvals.verbose): 1588 data.printDetails() 1589 1590 # add the time in between the tests as a new phase so we can see it 1591 if(len(testdata) > 1): 1592 t1e = testdata[0].getEnd() 1593 t2s = testdata[-1].getStart() 1594 testdata[-1].newPhaseWithSingleAction('user mode', \ 1595 'user mode', t1e, t2s, '#FF9966') 1596 return testdata 1597 1598# Function: loadKernelLog 1599# Description: 1600# [deprecated for kernel 3.15.0 or newer] 1601# load the dmesg file into memory and fix up any ordering issues 1602# The dmesg filename is taken from sysvals 1603# Output: 1604# An array of empty Data objects with only their dmesgtext attributes set 1605def loadKernelLog(): 1606 global sysvals 1607 1608 vprint('Analyzing the dmesg data...') 1609 if(os.path.exists(sysvals.dmesgfile) == False): 1610 doError('%s doesnt exist' % sysvals.dmesgfile, False) 1611 1612 # there can be multiple test runs in a single file delineated by stamps 1613 testruns = [] 1614 data = 0 1615 lf = open(sysvals.dmesgfile, 'r') 1616 for line in lf: 1617 line = line.replace('\r\n', '') 1618 idx = line.find('[') 1619 if idx > 1: 1620 line = line[idx:] 1621 m = re.match(sysvals.stampfmt, line) 1622 if(m): 1623 if(data): 1624 testruns.append(data) 1625 data = Data(len(testruns)) 1626 parseStamp(m, data) 1627 continue 1628 if(not data): 1629 continue 1630 m = re.match(sysvals.firmwarefmt, line) 1631 if(m): 1632 data.fwSuspend = int(m.group('s')) 1633 data.fwResume = int(m.group('r')) 1634 if(data.fwSuspend > 0 or data.fwResume > 0): 1635 data.fwValid = True 1636 continue 1637 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 1638 if(m): 1639 data.dmesgtext.append(line) 1640 if(re.match('ACPI: resume from mwait', m.group('msg'))): 1641 print('NOTE: This suspend appears to be freeze rather than'+\ 1642 ' %s, it will be treated as such' % sysvals.suspendmode) 1643 sysvals.suspendmode = 'freeze' 1644 else: 1645 vprint('ignoring dmesg line: %s' % line.replace('\n', '')) 1646 testruns.append(data) 1647 lf.close() 1648 1649 if(not data): 1650 print('ERROR: analyze_suspend header missing from dmesg log') 1651 sys.exit() 1652 1653 # fix lines with same timestamp/function with the call and return swapped 1654 for data in testruns: 1655 last = '' 1656 for line in data.dmesgtext: 1657 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ 1658 '(?P<f>.*)\+ @ .*, parent: .*', line) 1659 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ 1660 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last) 1661 if(mc and mr and (mc.group('t') == mr.group('t')) and 1662 (mc.group('f') == mr.group('f'))): 1663 i = data.dmesgtext.index(last) 1664 j = data.dmesgtext.index(line) 1665 data.dmesgtext[i] = line 1666 data.dmesgtext[j] = last 1667 last = line 1668 return testruns 1669 1670# Function: parseKernelLog 1671# Description: 1672# [deprecated for kernel 3.15.0 or newer] 1673# Analyse a dmesg log output file generated from this app during 1674# the execution phase. Create a set of device structures in memory 1675# for subsequent formatting in the html output file 1676# This call is only for legacy support on kernels where the ftrace 1677# data lacks the suspend_resume or device_pm_callbacks trace events. 1678# Arguments: 1679# data: an empty Data object (with dmesgtext) obtained from loadKernelLog 1680# Output: 1681# The filled Data object 1682def parseKernelLog(data): 1683 global sysvals 1684 1685 phase = 'suspend_runtime' 1686 1687 if(data.fwValid): 1688 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \ 1689 (data.fwSuspend, data.fwResume)) 1690 1691 # dmesg phase match table 1692 dm = { 1693 'suspend_prepare': 'PM: Syncing filesystems.*', 1694 'suspend': 'PM: Entering [a-z]* sleep.*', 1695 'suspend_late': 'PM: suspend of devices complete after.*', 1696 'suspend_noirq': 'PM: late suspend of devices complete after.*', 1697 'suspend_machine': 'PM: noirq suspend of devices complete after.*', 1698 'resume_machine': 'ACPI: Low-level resume complete.*', 1699 'resume_noirq': 'ACPI: Waking up from system sleep state.*', 1700 'resume_early': 'PM: noirq resume of devices complete after.*', 1701 'resume': 'PM: early resume of devices complete after.*', 1702 'resume_complete': 'PM: resume of devices complete after.*', 1703 'post_resume': '.*Restarting tasks \.\.\..*', 1704 } 1705 if(sysvals.suspendmode == 'standby'): 1706 dm['resume_machine'] = 'PM: Restoring platform NVS memory' 1707 elif(sysvals.suspendmode == 'disk'): 1708 dm['suspend_late'] = 'PM: freeze of devices complete after.*' 1709 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*' 1710 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*' 1711 dm['resume_machine'] = 'PM: Restoring platform NVS memory' 1712 dm['resume_early'] = 'PM: noirq restore of devices complete after.*' 1713 dm['resume'] = 'PM: early restore of devices complete after.*' 1714 dm['resume_complete'] = 'PM: restore of devices complete after.*' 1715 elif(sysvals.suspendmode == 'freeze'): 1716 dm['resume_machine'] = 'ACPI: resume from mwait' 1717 1718 # action table (expected events that occur and show up in dmesg) 1719 at = { 1720 'sync_filesystems': { 1721 'smsg': 'PM: Syncing filesystems.*', 1722 'emsg': 'PM: Preparing system for mem sleep.*' }, 1723 'freeze_user_processes': { 1724 'smsg': 'Freezing user space processes .*', 1725 'emsg': 'Freezing remaining freezable tasks.*' }, 1726 'freeze_tasks': { 1727 'smsg': 'Freezing remaining freezable tasks.*', 1728 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' }, 1729 'ACPI prepare': { 1730 'smsg': 'ACPI: Preparing to enter system sleep state.*', 1731 'emsg': 'PM: Saving platform NVS memory.*' }, 1732 'PM vns': { 1733 'smsg': 'PM: Saving platform NVS memory.*', 1734 'emsg': 'Disabling non-boot CPUs .*' }, 1735 } 1736 1737 t0 = -1.0 1738 cpu_start = -1.0 1739 prevktime = -1.0 1740 actions = dict() 1741 for line in data.dmesgtext: 1742 # -- preprocessing -- 1743 # parse each dmesg line into the time and message 1744 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 1745 if(m): 1746 val = m.group('ktime') 1747 try: 1748 ktime = float(val) 1749 except: 1750 doWarning('INVALID DMESG LINE: '+\ 1751 line.replace('\n', ''), 'dmesg') 1752 continue 1753 msg = m.group('msg') 1754 # initialize data start to first line time 1755 if t0 < 0: 1756 data.setStart(ktime) 1757 t0 = ktime 1758 else: 1759 continue 1760 1761 # hack for determining resume_machine end for freeze 1762 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ 1763 and phase == 'resume_machine' and \ 1764 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 1765 data.dmesg['resume_machine']['end'] = ktime 1766 phase = 'resume_noirq' 1767 data.dmesg[phase]['start'] = ktime 1768 1769 # -- phase changes -- 1770 # suspend start 1771 if(re.match(dm['suspend_prepare'], msg)): 1772 phase = 'suspend_prepare' 1773 data.dmesg[phase]['start'] = ktime 1774 data.setStart(ktime) 1775 # suspend start 1776 elif(re.match(dm['suspend'], msg)): 1777 data.dmesg['suspend_prepare']['end'] = ktime 1778 phase = 'suspend' 1779 data.dmesg[phase]['start'] = ktime 1780 # suspend_late start 1781 elif(re.match(dm['suspend_late'], msg)): 1782 data.dmesg['suspend']['end'] = ktime 1783 phase = 'suspend_late' 1784 data.dmesg[phase]['start'] = ktime 1785 # suspend_noirq start 1786 elif(re.match(dm['suspend_noirq'], msg)): 1787 data.dmesg['suspend_late']['end'] = ktime 1788 phase = 'suspend_noirq' 1789 data.dmesg[phase]['start'] = ktime 1790 # suspend_machine start 1791 elif(re.match(dm['suspend_machine'], msg)): 1792 data.dmesg['suspend_noirq']['end'] = ktime 1793 phase = 'suspend_machine' 1794 data.dmesg[phase]['start'] = ktime 1795 # resume_machine start 1796 elif(re.match(dm['resume_machine'], msg)): 1797 if(sysvals.suspendmode in ['freeze', 'standby']): 1798 data.tSuspended = prevktime 1799 data.dmesg['suspend_machine']['end'] = prevktime 1800 else: 1801 data.tSuspended = ktime 1802 data.dmesg['suspend_machine']['end'] = ktime 1803 phase = 'resume_machine' 1804 data.tResumed = ktime 1805 data.tLow = data.tResumed - data.tSuspended 1806 data.dmesg[phase]['start'] = ktime 1807 # resume_noirq start 1808 elif(re.match(dm['resume_noirq'], msg)): 1809 data.dmesg['resume_machine']['end'] = ktime 1810 phase = 'resume_noirq' 1811 data.dmesg[phase]['start'] = ktime 1812 # resume_early start 1813 elif(re.match(dm['resume_early'], msg)): 1814 data.dmesg['resume_noirq']['end'] = ktime 1815 phase = 'resume_early' 1816 data.dmesg[phase]['start'] = ktime 1817 # resume start 1818 elif(re.match(dm['resume'], msg)): 1819 data.dmesg['resume_early']['end'] = ktime 1820 phase = 'resume' 1821 data.dmesg[phase]['start'] = ktime 1822 # resume complete start 1823 elif(re.match(dm['resume_complete'], msg)): 1824 data.dmesg['resume']['end'] = ktime 1825 phase = 'resume_complete' 1826 data.dmesg[phase]['start'] = ktime 1827 # post resume start 1828 elif(re.match(dm['post_resume'], msg)): 1829 data.dmesg['resume_complete']['end'] = ktime 1830 data.setEnd(ktime) 1831 phase = 'post_resume' 1832 break 1833 1834 # -- device callbacks -- 1835 if(phase in data.phases): 1836 # device init call 1837 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 1838 sm = re.match('calling (?P<f>.*)\+ @ '+\ 1839 '(?P<n>.*), parent: (?P<p>.*)', msg); 1840 f = sm.group('f') 1841 n = sm.group('n') 1842 p = sm.group('p') 1843 if(f and n and p): 1844 data.newAction(phase, f, int(n), p, ktime, -1, '') 1845 # device init return 1846 elif(re.match('call (?P<f>.*)\+ returned .* after '+\ 1847 '(?P<t>.*) usecs', msg)): 1848 sm = re.match('call (?P<f>.*)\+ returned .* after '+\ 1849 '(?P<t>.*) usecs(?P<a>.*)', msg); 1850 f = sm.group('f') 1851 t = sm.group('t') 1852 list = data.dmesg[phase]['list'] 1853 if(f in list): 1854 dev = list[f] 1855 dev['length'] = int(t) 1856 dev['end'] = ktime 1857 1858 # -- non-devicecallback actions -- 1859 # if trace events are not available, these are better than nothing 1860 if(not sysvals.usetraceevents): 1861 # look for known actions 1862 for a in at: 1863 if(re.match(at[a]['smsg'], msg)): 1864 if(a not in actions): 1865 actions[a] = [] 1866 actions[a].append({'begin': ktime, 'end': ktime}) 1867 if(re.match(at[a]['emsg'], msg)): 1868 actions[a][-1]['end'] = ktime 1869 # now look for CPU on/off events 1870 if(re.match('Disabling non-boot CPUs .*', msg)): 1871 # start of first cpu suspend 1872 cpu_start = ktime 1873 elif(re.match('Enabling non-boot CPUs .*', msg)): 1874 # start of first cpu resume 1875 cpu_start = ktime 1876 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)): 1877 # end of a cpu suspend, start of the next 1878 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) 1879 cpu = 'CPU'+m.group('cpu') 1880 if(cpu not in actions): 1881 actions[cpu] = [] 1882 actions[cpu].append({'begin': cpu_start, 'end': ktime}) 1883 cpu_start = ktime 1884 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)): 1885 # end of a cpu resume, start of the next 1886 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg) 1887 cpu = 'CPU'+m.group('cpu') 1888 if(cpu not in actions): 1889 actions[cpu] = [] 1890 actions[cpu].append({'begin': cpu_start, 'end': ktime}) 1891 cpu_start = ktime 1892 prevktime = ktime 1893 1894 # fill in any missing phases 1895 lp = data.phases[0] 1896 for p in data.phases: 1897 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 1898 print('WARNING: phase "%s" is missing, something went wrong!' % p) 1899 print(' In %s, this dmesg line denotes the start of %s:' % \ 1900 (sysvals.suspendmode, p)) 1901 print(' "%s"' % dm[p]) 1902 if(data.dmesg[p]['start'] < 0): 1903 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 1904 if(p == 'resume_machine'): 1905 data.tSuspended = data.dmesg[lp]['end'] 1906 data.tResumed = data.dmesg[lp]['end'] 1907 data.tLow = 0 1908 if(data.dmesg[p]['end'] < 0): 1909 data.dmesg[p]['end'] = data.dmesg[p]['start'] 1910 lp = p 1911 1912 # fill in any actions we've found 1913 for name in actions: 1914 for event in actions[name]: 1915 begin = event['begin'] 1916 end = event['end'] 1917 # if event starts before timeline start, expand timeline 1918 if(begin < data.start): 1919 data.setStart(begin) 1920 # if event ends after timeline end, expand the timeline 1921 if(end > data.end): 1922 data.setEnd(end) 1923 data.newActionGlobal(name, begin, end) 1924 1925 if(sysvals.verbose): 1926 data.printDetails() 1927 if(len(sysvals.devicefilter) > 0): 1928 data.deviceFilter(sysvals.devicefilter) 1929 data.fixupInitcallsThatDidntReturn() 1930 return True 1931 1932# Function: setTimelineRows 1933# Description: 1934# Organize the timeline entries into the smallest 1935# number of rows possible, with no entry overlapping 1936# Arguments: 1937# list: the list of devices/actions for a single phase 1938# sortedkeys: cronologically sorted key list to use 1939# Output: 1940# The total number of rows needed to display this phase of the timeline 1941def setTimelineRows(list, sortedkeys): 1942 1943 # clear all rows and set them to undefined 1944 remaining = len(list) 1945 rowdata = dict() 1946 row = 0 1947 for item in list: 1948 list[item]['row'] = -1 1949 1950 # try to pack each row with as many ranges as possible 1951 while(remaining > 0): 1952 if(row not in rowdata): 1953 rowdata[row] = [] 1954 for item in sortedkeys: 1955 if(list[item]['row'] < 0): 1956 s = list[item]['start'] 1957 e = list[item]['end'] 1958 valid = True 1959 for ritem in rowdata[row]: 1960 rs = ritem['start'] 1961 re = ritem['end'] 1962 if(not (((s <= rs) and (e <= rs)) or 1963 ((s >= re) and (e >= re)))): 1964 valid = False 1965 break 1966 if(valid): 1967 rowdata[row].append(list[item]) 1968 list[item]['row'] = row 1969 remaining -= 1 1970 row += 1 1971 return row 1972 1973# Function: createTimeScale 1974# Description: 1975# Create the timescale header for the html timeline 1976# Arguments: 1977# t0: start time (suspend begin) 1978# tMax: end time (resume end) 1979# tSuspend: time when suspend occurs, i.e. the zero time 1980# Output: 1981# The html code needed to display the time scale 1982def createTimeScale(t0, tMax, tSuspended): 1983 timescale = '<div class="t" style="right:{0}%">{1}</div>\n' 1984 output = '<div id="timescale">\n' 1985 1986 # set scale for timeline 1987 tTotal = tMax - t0 1988 tS = 0.1 1989 if(tTotal <= 0): 1990 return output 1991 if(tTotal > 4): 1992 tS = 1 1993 if(tSuspended < 0): 1994 for i in range(int(tTotal/tS)+1): 1995 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal)) 1996 if(i > 0): 1997 val = '%0.fms' % (float(i)*tS*1000) 1998 else: 1999 val = '' 2000 output += timescale.format(pos, val) 2001 else: 2002 tSuspend = tSuspended - t0 2003 divTotal = int(tTotal/tS) + 1 2004 divSuspend = int(tSuspend/tS) 2005 s0 = (tSuspend - tS*divSuspend)*100/tTotal 2006 for i in range(divTotal): 2007 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0) 2008 if((i == 0) and (s0 < 3)): 2009 val = '' 2010 elif(i == divSuspend): 2011 val = 'S/R' 2012 else: 2013 val = '%0.fms' % (float(i-divSuspend)*tS*1000) 2014 output += timescale.format(pos, val) 2015 output += '</div>\n' 2016 return output 2017 2018# Function: createHTMLSummarySimple 2019# Description: 2020# Create summary html file for a series of tests 2021# Arguments: 2022# testruns: array of Data objects from parseTraceLog 2023def createHTMLSummarySimple(testruns, htmlfile): 2024 global sysvals 2025 2026 # print out the basic summary of all the tests 2027 hf = open(htmlfile, 'w') 2028 2029 # write the html header first (html head, css code, up to body start) 2030 html = '<!DOCTYPE html>\n<html>\n<head>\n\ 2031 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 2032 <title>AnalyzeSuspend Summary</title>\n\ 2033 <style type=\'text/css\'>\n\ 2034 body {overflow-y: scroll;}\n\ 2035 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\ 2036 table {width:100%;border-collapse: collapse;}\n\ 2037 .summary {font: 22px Arial;border:1px solid;}\n\ 2038 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\ 2039 td {text-align: center;}\n\ 2040 tr.alt td {background-color:#EAF2D3;}\n\ 2041 tr.avg td {background-color:#BDE34C;}\n\ 2042 a:link {color: #90B521;}\n\ 2043 a:visited {color: #495E09;}\n\ 2044 a:hover {color: #B1DF28;}\n\ 2045 a:active {color: #FFFFFF;}\n\ 2046 </style>\n</head>\n<body>\n' 2047 2048 # group test header 2049 count = len(testruns) 2050 headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n' 2051 html += headline_stamp.format(sysvals.stamp['host'], 2052 sysvals.stamp['kernel'], sysvals.stamp['mode'], 2053 sysvals.stamp['time'], count) 2054 2055 # check to see if all the tests have the same value 2056 stampcolumns = False 2057 for data in testruns: 2058 if diffStamp(sysvals.stamp, data.stamp): 2059 stampcolumns = True 2060 break 2061 2062 th = '\t<th>{0}</th>\n' 2063 td = '\t<td>{0}</td>\n' 2064 tdlink = '\t<td><a href="{0}">Click Here</a></td>\n' 2065 2066 # table header 2067 html += '<table class="summary">\n<tr>\n' 2068 html += th.format("Test #") 2069 if stampcolumns: 2070 html += th.format("Hostname") 2071 html += th.format("Kernel Version") 2072 html += th.format("Suspend Mode") 2073 html += th.format("Test Time") 2074 html += th.format("Suspend Time") 2075 html += th.format("Resume Time") 2076 html += th.format("Detail") 2077 html += '</tr>\n' 2078 2079 # test data, 1 row per test 2080 sTimeAvg = 0.0 2081 rTimeAvg = 0.0 2082 num = 1 2083 for data in testruns: 2084 # data.end is the end of post_resume 2085 resumeEnd = data.dmesg['resume_complete']['end'] 2086 if num % 2 == 1: 2087 html += '<tr class="alt">\n' 2088 else: 2089 html += '<tr>\n' 2090 2091 # test num 2092 html += td.format("test %d" % num) 2093 num += 1 2094 if stampcolumns: 2095 # host name 2096 val = "unknown" 2097 if('host' in data.stamp): 2098 val = data.stamp['host'] 2099 html += td.format(val) 2100 # host kernel 2101 val = "unknown" 2102 if('kernel' in data.stamp): 2103 val = data.stamp['kernel'] 2104 html += td.format(val) 2105 # suspend mode 2106 val = "unknown" 2107 if('mode' in data.stamp): 2108 val = data.stamp['mode'] 2109 html += td.format(val) 2110 # test time 2111 val = "unknown" 2112 if('time' in data.stamp): 2113 val = data.stamp['time'] 2114 html += td.format(val) 2115 # suspend time 2116 sTime = (data.tSuspended - data.start)*1000 2117 sTimeAvg += sTime 2118 html += td.format("%3.3f ms" % sTime) 2119 # resume time 2120 rTime = (resumeEnd - data.tResumed)*1000 2121 rTimeAvg += rTime 2122 html += td.format("%3.3f ms" % rTime) 2123 # link to the output html 2124 html += tdlink.format(data.outfile) 2125 2126 html += '</tr>\n' 2127 2128 # last line: test average 2129 if(count > 0): 2130 sTimeAvg /= count 2131 rTimeAvg /= count 2132 html += '<tr class="avg">\n' 2133 html += td.format('Average') # name 2134 if stampcolumns: 2135 html += td.format('') # host 2136 html += td.format('') # kernel 2137 html += td.format('') # mode 2138 html += td.format('') # time 2139 html += td.format("%3.3f ms" % sTimeAvg) # suspend time 2140 html += td.format("%3.3f ms" % rTimeAvg) # resume time 2141 html += td.format('') # output link 2142 html += '</tr>\n' 2143 2144 # flush the data to file 2145 hf.write(html+'</table>\n') 2146 hf.write('</body>\n</html>\n') 2147 hf.close() 2148 2149# Function: createHTML 2150# Description: 2151# Create the output html file from the resident test data 2152# Arguments: 2153# testruns: array of Data objects from parseKernelLog or parseTraceLog 2154# Output: 2155# True if the html file was created, false if it failed 2156def createHTML(testruns): 2157 global sysvals 2158 2159 for data in testruns: 2160 data.normalizeTime(testruns[-1].tSuspended) 2161 2162 x2changes = ['', 'absolute'] 2163 if len(testruns) > 1: 2164 x2changes = ['1', 'relative'] 2165 # html function templates 2166 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' 2167 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0] 2168 html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n' 2169 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n' 2170 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n' 2171 html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n' 2172 html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n' 2173 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n' 2174 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n' 2175 html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n' 2176 html_timetotal = '<table class="time1">\n<tr>'\ 2177 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\ 2178 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\ 2179 '</tr>\n</table>\n' 2180 html_timetotal2 = '<table class="time1">\n<tr>'\ 2181 '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\ 2182 '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\ 2183 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\ 2184 '</tr>\n</table>\n' 2185 html_timegroups = '<table class="time2">\n<tr>'\ 2186 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\ 2187 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\ 2188 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\ 2189 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\ 2190 '</tr>\n</table>\n' 2191 2192 # device timeline 2193 vprint('Creating Device Timeline...') 2194 devtl = Timeline() 2195 2196 # Generate the header for this timeline 2197 textnum = ['First', 'Second'] 2198 for data in testruns: 2199 tTotal = data.end - data.start 2200 tEnd = data.dmesg['resume_complete']['end'] 2201 if(tTotal == 0): 2202 print('ERROR: No timeline data') 2203 sys.exit() 2204 if(data.tLow > 0): 2205 low_time = '%.0f'%(data.tLow*1000) 2206 if data.fwValid: 2207 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \ 2208 (data.fwSuspend/1000000.0)) 2209 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \ 2210 (data.fwResume/1000000.0)) 2211 testdesc1 = 'Total' 2212 testdesc2 = '' 2213 if(len(testruns) > 1): 2214 testdesc1 = testdesc2 = textnum[data.testnumber] 2215 testdesc2 += ' ' 2216 if(data.tLow == 0): 2217 thtml = html_timetotal.format(suspend_time, \ 2218 resume_time, testdesc1) 2219 else: 2220 thtml = html_timetotal2.format(suspend_time, low_time, \ 2221 resume_time, testdesc1) 2222 devtl.html['timeline'] += thtml 2223 sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \ 2224 data.getStart())*1000) 2225 sftime = '%.3f'%(data.fwSuspend / 1000000.0) 2226 rftime = '%.3f'%(data.fwResume / 1000000.0) 2227 rktime = '%.3f'%((data.getEnd() - \ 2228 data.dmesg['resume_machine']['start'])*1000) 2229 devtl.html['timeline'] += html_timegroups.format(sktime, \ 2230 sftime, rftime, rktime, testdesc2) 2231 else: 2232 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000) 2233 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000) 2234 testdesc = 'Kernel' 2235 if(len(testruns) > 1): 2236 testdesc = textnum[data.testnumber]+' '+testdesc 2237 if(data.tLow == 0): 2238 thtml = html_timetotal.format(suspend_time, \ 2239 resume_time, testdesc) 2240 else: 2241 thtml = html_timetotal2.format(suspend_time, low_time, \ 2242 resume_time, testdesc) 2243 devtl.html['timeline'] += thtml 2244 2245 # time scale for potentially multiple datasets 2246 t0 = testruns[0].start 2247 tMax = testruns[-1].end 2248 tSuspended = testruns[-1].tSuspended 2249 tTotal = tMax - t0 2250 2251 # determine the maximum number of rows we need to draw 2252 timelinerows = 0 2253 for data in testruns: 2254 for phase in data.dmesg: 2255 list = data.dmesg[phase]['list'] 2256 rows = setTimelineRows(list, list) 2257 data.dmesg[phase]['row'] = rows 2258 if(rows > timelinerows): 2259 timelinerows = rows 2260 2261 # calculate the timeline height and create bounding box, add buttons 2262 devtl.setRows(timelinerows + 1) 2263 devtl.html['timeline'] += html_devlist1 2264 if len(testruns) > 1: 2265 devtl.html['timeline'] += html_devlist2 2266 devtl.html['timeline'] += html_zoombox 2267 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) 2268 2269 # draw the colored boxes for each of the phases 2270 for data in testruns: 2271 for b in data.dmesg: 2272 phase = data.dmesg[b] 2273 length = phase['end']-phase['start'] 2274 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 2275 width = '%.3f' % ((length*100.0)/tTotal) 2276 devtl.html['timeline'] += html_phase.format(left, width, \ 2277 '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \ 2278 data.dmesg[b]['color'], '') 2279 2280 # draw the time scale, try to make the number of labels readable 2281 devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended) 2282 devtl.html['timeline'] += devtl.html['scale'] 2283 for data in testruns: 2284 for b in data.dmesg: 2285 phaselist = data.dmesg[b]['list'] 2286 for d in phaselist: 2287 name = d 2288 drv = '' 2289 dev = phaselist[d] 2290 if(d in sysvals.altdevname): 2291 name = sysvals.altdevname[d] 2292 if('drv' in dev and dev['drv']): 2293 drv = ' {%s}' % dev['drv'] 2294 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 2295 top = '%.3f' % ((dev['row']*height) + devtl.scaleH) 2296 left = '%.3f' % (((dev['start']-t0)*100)/tTotal) 2297 width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal) 2298 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) 2299 color = 'rgba(204,204,204,0.5)' 2300 devtl.html['timeline'] += html_device.format(dev['id'], \ 2301 d+drv+length+b, left, top, '%.3f'%height, width, name+drv) 2302 2303 # draw any trace events found 2304 for data in testruns: 2305 for b in data.dmesg: 2306 phaselist = data.dmesg[b]['list'] 2307 for name in phaselist: 2308 dev = phaselist[name] 2309 if('traceevents' in dev): 2310 vprint('Debug trace events found for device %s' % name) 2311 vprint('%20s %20s %10s %8s' % ('action', \ 2312 'name', 'time(ms)', 'length(ms)')) 2313 for e in dev['traceevents']: 2314 vprint('%20s %20s %10.3f %8.3f' % (e.action, \ 2315 e.name, e.time*1000, e.length*1000)) 2316 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row'] 2317 top = '%.3f' % ((dev['row']*height) + devtl.scaleH) 2318 left = '%.3f' % (((e.time-t0)*100)/tTotal) 2319 width = '%.3f' % (e.length*100/tTotal) 2320 color = 'rgba(204,204,204,0.5)' 2321 devtl.html['timeline'] += \ 2322 html_traceevent.format(e.action+' '+e.name, \ 2323 left, top, '%.3f'%height, \ 2324 width, e.color, '') 2325 2326 # timeline is finished 2327 devtl.html['timeline'] += '</div>\n</div>\n' 2328 2329 # draw a legend which describes the phases by color 2330 data = testruns[-1] 2331 devtl.html['legend'] = '<div class="legend">\n' 2332 pdelta = 100.0/len(data.phases) 2333 pmargin = pdelta / 4.0 2334 for phase in data.phases: 2335 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) 2336 name = string.replace(phase, '_', ' ') 2337 devtl.html['legend'] += html_legend.format(order, \ 2338 data.dmesg[phase]['color'], name) 2339 devtl.html['legend'] += '</div>\n' 2340 2341 hf = open(sysvals.htmlfile, 'w') 2342 thread_height = 0 2343 2344 # write the html header first (html head, css code, up to body start) 2345 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\ 2346 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 2347 <title>AnalyzeSuspend</title>\n\ 2348 <style type=\'text/css\'>\n\ 2349 body {overflow-y: scroll;}\n\ 2350 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\ 2351 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\ 2352 .callgraph article * {padding-left: 28px;}\n\ 2353 h1 {color:black;font: bold 30px Times;}\n\ 2354 t0 {color:black;font: bold 30px Times;}\n\ 2355 t1 {color:black;font: 30px Times;}\n\ 2356 t2 {color:black;font: 25px Times;}\n\ 2357 t3 {color:black;font: 20px Times;white-space:nowrap;}\n\ 2358 t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\ 2359 table {width:100%;}\n\ 2360 .gray {background-color:rgba(80,80,80,0.1);}\n\ 2361 .green {background-color:rgba(204,255,204,0.4);}\n\ 2362 .purple {background-color:rgba(128,0,128,0.2);}\n\ 2363 .yellow {background-color:rgba(255,255,204,0.4);}\n\ 2364 .time1 {font: 22px Arial;border:1px solid;}\n\ 2365 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ 2366 td {text-align: center;}\n\ 2367 r {color:#500000;font:15px Tahoma;}\n\ 2368 n {color:#505050;font:15px Tahoma;}\n\ 2369 .tdhl {color: red;}\n\ 2370 .hide {display: none;}\n\ 2371 .pf {display: none;}\n\ 2372 .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\ 2373 .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\ 2374 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\ 2375 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\ 2376 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\ 2377 .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\ 2378 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\ 2379 .hover {background-color:white;border:1px solid red;z-index:10;}\n\ 2380 .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\ 2381 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\ 2382 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\ 2383 .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\ 2384 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\ 2385 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\ 2386 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ 2387 .devlist {position:'+x2changes[1]+';width:190px;}\n\ 2388 #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\ 2389 </style>\n</head>\n<body>\n' 2390 hf.write(html_header) 2391 2392 # write the test title and general info header 2393 if(sysvals.stamp['time'] != ""): 2394 hf.write(headline_stamp.format(sysvals.stamp['host'], 2395 sysvals.stamp['kernel'], sysvals.stamp['mode'], \ 2396 sysvals.stamp['time'])) 2397 2398 # write the device timeline 2399 hf.write(devtl.html['timeline']) 2400 hf.write(devtl.html['legend']) 2401 hf.write('<div id="devicedetailtitle"></div>\n') 2402 hf.write('<div id="devicedetail" style="display:none;">\n') 2403 # draw the colored boxes for the device detail section 2404 for data in testruns: 2405 hf.write('<div id="devicedetail%d">\n' % data.testnumber) 2406 for b in data.phases: 2407 phase = data.dmesg[b] 2408 length = phase['end']-phase['start'] 2409 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 2410 width = '%.3f' % ((length*100.0)/tTotal) 2411 hf.write(html_phaselet.format(b, left, width, \ 2412 data.dmesg[b]['color'])) 2413 hf.write('</div>\n') 2414 hf.write('</div>\n') 2415 2416 # write the ftrace data (callgraph) 2417 data = testruns[-1] 2418 if(sysvals.usecallgraph): 2419 hf.write('<section id="callgraphs" class="callgraph">\n') 2420 # write out the ftrace data converted to html 2421 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' 2422 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n' 2423 html_func_end = '</article>\n' 2424 html_func_leaf = '<article>{0} {1}</article>\n' 2425 num = 0 2426 for p in data.phases: 2427 list = data.dmesg[p]['list'] 2428 for devname in data.sortedDevices(p): 2429 if('ftrace' not in list[devname]): 2430 continue 2431 name = devname 2432 if(devname in sysvals.altdevname): 2433 name = sysvals.altdevname[devname] 2434 devid = list[devname]['id'] 2435 cg = list[devname]['ftrace'] 2436 flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \ 2437 ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000) 2438 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \ 2439 num, name+' '+p, flen)) 2440 num += 1 2441 for line in cg.list: 2442 if(line.length < 0.000000001): 2443 flen = '' 2444 else: 2445 flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \ 2446 line.time*1000) 2447 if(line.freturn and line.fcall): 2448 hf.write(html_func_leaf.format(line.name, flen)) 2449 elif(line.freturn): 2450 hf.write(html_func_end) 2451 else: 2452 hf.write(html_func_start.format(num, line.name, flen)) 2453 num += 1 2454 hf.write(html_func_end) 2455 hf.write('\n\n </section>\n') 2456 # write the footer and close 2457 addScriptCode(hf, testruns) 2458 hf.write('</body>\n</html>\n') 2459 hf.close() 2460 return True 2461 2462# Function: addScriptCode 2463# Description: 2464# Adds the javascript code to the output html 2465# Arguments: 2466# hf: the open html file pointer 2467# testruns: array of Data objects from parseKernelLog or parseTraceLog 2468def addScriptCode(hf, testruns): 2469 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000 2470 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000 2471 # create an array in javascript memory with the device details 2472 detail = ' var devtable = [];\n' 2473 for data in testruns: 2474 topo = data.deviceTopology() 2475 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo) 2476 detail += ' var bounds = [%f,%f];\n' % (t0, tMax) 2477 # add the code which will manipulate the data in the browser 2478 script_code = \ 2479 '<script type="text/javascript">\n'+detail+\ 2480 ' function zoomTimeline() {\n'\ 2481 ' var timescale = document.getElementById("timescale");\n'\ 2482 ' var dmesg = document.getElementById("dmesg");\n'\ 2483 ' var zoombox = document.getElementById("dmesgzoombox");\n'\ 2484 ' var val = parseFloat(dmesg.style.width);\n'\ 2485 ' var newval = 100;\n'\ 2486 ' var sh = window.outerWidth / 2;\n'\ 2487 ' if(this.id == "zoomin") {\n'\ 2488 ' newval = val * 1.2;\n'\ 2489 ' if(newval > 40000) newval = 40000;\n'\ 2490 ' dmesg.style.width = newval+"%";\n'\ 2491 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\ 2492 ' } else if (this.id == "zoomout") {\n'\ 2493 ' newval = val / 1.2;\n'\ 2494 ' if(newval < 100) newval = 100;\n'\ 2495 ' dmesg.style.width = newval+"%";\n'\ 2496 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\ 2497 ' } else {\n'\ 2498 ' zoombox.scrollLeft = 0;\n'\ 2499 ' dmesg.style.width = "100%";\n'\ 2500 ' }\n'\ 2501 ' var html = "";\n'\ 2502 ' var t0 = bounds[0];\n'\ 2503 ' var tMax = bounds[1];\n'\ 2504 ' var tTotal = tMax - t0;\n'\ 2505 ' var wTotal = tTotal * 100.0 / newval;\n'\ 2506 ' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\ 2507 ' if(tS < 1) tS = 1;\n'\ 2508 ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\ 2509 ' var pos = (tMax - s) * 100.0 / tTotal;\n'\ 2510 ' var name = (s == 0)?"S/R":(s+"ms");\n'\ 2511 ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\ 2512 ' }\n'\ 2513 ' timescale.innerHTML = html;\n'\ 2514 ' }\n'\ 2515 ' function deviceHover() {\n'\ 2516 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\ 2517 ' var dmesg = document.getElementById("dmesg");\n'\ 2518 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 2519 ' var cpu = -1;\n'\ 2520 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ 2521 ' cpu = parseInt(name.slice(7));\n'\ 2522 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ 2523 ' cpu = parseInt(name.slice(8));\n'\ 2524 ' for (var i = 0; i < dev.length; i++) {\n'\ 2525 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\ 2526 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 2527 ' (name == dname))\n'\ 2528 ' {\n'\ 2529 ' dev[i].className = "thread hover";\n'\ 2530 ' } else {\n'\ 2531 ' dev[i].className = "thread";\n'\ 2532 ' }\n'\ 2533 ' }\n'\ 2534 ' }\n'\ 2535 ' function deviceUnhover() {\n'\ 2536 ' var dmesg = document.getElementById("dmesg");\n'\ 2537 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 2538 ' for (var i = 0; i < dev.length; i++) {\n'\ 2539 ' dev[i].className = "thread";\n'\ 2540 ' }\n'\ 2541 ' }\n'\ 2542 ' function deviceTitle(title, total, cpu) {\n'\ 2543 ' var prefix = "Total";\n'\ 2544 ' if(total.length > 3) {\n'\ 2545 ' prefix = "Average";\n'\ 2546 ' total[1] = (total[1]+total[3])/2;\n'\ 2547 ' total[2] = (total[2]+total[4])/2;\n'\ 2548 ' }\n'\ 2549 ' var devtitle = document.getElementById("devicedetailtitle");\n'\ 2550 ' var name = title.slice(0, title.indexOf(" "));\n'\ 2551 ' if(cpu >= 0) name = "CPU"+cpu;\n'\ 2552 ' var driver = "";\n'\ 2553 ' var tS = "<t2>(</t2>";\n'\ 2554 ' var tR = "<t2>)</t2>";\n'\ 2555 ' if(total[1] > 0)\n'\ 2556 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\ 2557 ' if(total[2] > 0)\n'\ 2558 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\ 2559 ' var s = title.indexOf("{");\n'\ 2560 ' var e = title.indexOf("}");\n'\ 2561 ' if((s >= 0) && (e >= 0))\n'\ 2562 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\ 2563 ' if(total[1] > 0 && total[2] > 0)\n'\ 2564 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\ 2565 ' else\n'\ 2566 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\ 2567 ' return name;\n'\ 2568 ' }\n'\ 2569 ' function deviceDetail() {\n'\ 2570 ' var devinfo = document.getElementById("devicedetail");\n'\ 2571 ' devinfo.style.display = "block";\n'\ 2572 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\ 2573 ' var cpu = -1;\n'\ 2574 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ 2575 ' cpu = parseInt(name.slice(7));\n'\ 2576 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ 2577 ' cpu = parseInt(name.slice(8));\n'\ 2578 ' var dmesg = document.getElementById("dmesg");\n'\ 2579 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 2580 ' var idlist = [];\n'\ 2581 ' var pdata = [[]];\n'\ 2582 ' var pd = pdata[0];\n'\ 2583 ' var total = [0.0, 0.0, 0.0];\n'\ 2584 ' for (var i = 0; i < dev.length; i++) {\n'\ 2585 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\ 2586 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 2587 ' (name == dname))\n'\ 2588 ' {\n'\ 2589 ' idlist[idlist.length] = dev[i].id;\n'\ 2590 ' var tidx = 1;\n'\ 2591 ' if(dev[i].id[0] == "a") {\n'\ 2592 ' pd = pdata[0];\n'\ 2593 ' } else {\n'\ 2594 ' if(pdata.length == 1) pdata[1] = [];\n'\ 2595 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\ 2596 ' pd = pdata[1];\n'\ 2597 ' tidx = 3;\n'\ 2598 ' }\n'\ 2599 ' var info = dev[i].title.split(" ");\n'\ 2600 ' var pname = info[info.length-1];\n'\ 2601 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\ 2602 ' total[0] += pd[pname];\n'\ 2603 ' if(pname.indexOf("suspend") >= 0)\n'\ 2604 ' total[tidx] += pd[pname];\n'\ 2605 ' else\n'\ 2606 ' total[tidx+1] += pd[pname];\n'\ 2607 ' }\n'\ 2608 ' }\n'\ 2609 ' var devname = deviceTitle(this.title, total, cpu);\n'\ 2610 ' var left = 0.0;\n'\ 2611 ' for (var t = 0; t < pdata.length; t++) {\n'\ 2612 ' pd = pdata[t];\n'\ 2613 ' devinfo = document.getElementById("devicedetail"+t);\n'\ 2614 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\ 2615 ' for (var i = 0; i < phases.length; i++) {\n'\ 2616 ' if(phases[i].id in pd) {\n'\ 2617 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\ 2618 ' var fs = 32;\n'\ 2619 ' if(w < 8) fs = 4*w | 0;\n'\ 2620 ' var fs2 = fs*3/4;\n'\ 2621 ' phases[i].style.width = w+"%";\n'\ 2622 ' phases[i].style.left = left+"%";\n'\ 2623 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\ 2624 ' left += w;\n'\ 2625 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\ 2626 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\ 2627 ' phases[i].innerHTML = time+pname;\n'\ 2628 ' } else {\n'\ 2629 ' phases[i].style.width = "0%";\n'\ 2630 ' phases[i].style.left = left+"%";\n'\ 2631 ' }\n'\ 2632 ' }\n'\ 2633 ' }\n'\ 2634 ' var cglist = document.getElementById("callgraphs");\n'\ 2635 ' if(!cglist) return;\n'\ 2636 ' var cg = cglist.getElementsByClassName("atop");\n'\ 2637 ' for (var i = 0; i < cg.length; i++) {\n'\ 2638 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\ 2639 ' cg[i].style.display = "block";\n'\ 2640 ' } else {\n'\ 2641 ' cg[i].style.display = "none";\n'\ 2642 ' }\n'\ 2643 ' }\n'\ 2644 ' }\n'\ 2645 ' function devListWindow(e) {\n'\ 2646 ' var sx = e.clientX;\n'\ 2647 ' if(sx > window.innerWidth - 440)\n'\ 2648 ' sx = window.innerWidth - 440;\n'\ 2649 ' var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\ 2650 ' var win = window.open("", "_blank", cfg);\n'\ 2651 ' if(window.chrome) win.moveBy(sx, 0);\n'\ 2652 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\ 2653 ' "<style type=\\"text/css\\">"+\n'\ 2654 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\ 2655 ' "</style>"\n'\ 2656 ' var dt = devtable[0];\n'\ 2657 ' if(e.target.id != "devlist1")\n'\ 2658 ' dt = devtable[1];\n'\ 2659 ' win.document.write(html+dt);\n'\ 2660 ' }\n'\ 2661 ' window.addEventListener("load", function () {\n'\ 2662 ' var dmesg = document.getElementById("dmesg");\n'\ 2663 ' dmesg.style.width = "100%"\n'\ 2664 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ 2665 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ 2666 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ 2667 ' var devlist = document.getElementsByClassName("devlist");\n'\ 2668 ' for (var i = 0; i < devlist.length; i++)\n'\ 2669 ' devlist[i].onclick = devListWindow;\n'\ 2670 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 2671 ' for (var i = 0; i < dev.length; i++) {\n'\ 2672 ' dev[i].onclick = deviceDetail;\n'\ 2673 ' dev[i].onmouseover = deviceHover;\n'\ 2674 ' dev[i].onmouseout = deviceUnhover;\n'\ 2675 ' }\n'\ 2676 ' zoomTimeline();\n'\ 2677 ' });\n'\ 2678 '</script>\n' 2679 hf.write(script_code); 2680 2681# Function: executeSuspend 2682# Description: 2683# Execute system suspend through the sysfs interface, then copy the output 2684# dmesg and ftrace files to the test output directory. 2685def executeSuspend(): 2686 global sysvals 2687 2688 detectUSB(False) 2689 t0 = time.time()*1000 2690 tp = sysvals.tpath 2691 # execute however many s/r runs requested 2692 for count in range(1,sysvals.execcount+1): 2693 # clear the kernel ring buffer just as we start 2694 os.system('dmesg -C') 2695 # enable callgraph ftrace only for the second run 2696 if(sysvals.usecallgraph and count == 2): 2697 # set trace type 2698 os.system('echo function_graph > '+tp+'current_tracer') 2699 os.system('echo "" > '+tp+'set_ftrace_filter') 2700 # set trace format options 2701 os.system('echo funcgraph-abstime > '+tp+'trace_options') 2702 os.system('echo funcgraph-proc > '+tp+'trace_options') 2703 # focus only on device suspend and resume 2704 os.system('cat '+tp+'available_filter_functions | '+\ 2705 'grep dpm_run_callback > '+tp+'set_graph_function') 2706 # if this is test2 and there's a delay, start here 2707 if(count > 1 and sysvals.x2delay > 0): 2708 tN = time.time()*1000 2709 while (tN - t0) < sysvals.x2delay: 2710 tN = time.time()*1000 2711 time.sleep(0.001) 2712 # start ftrace 2713 if(sysvals.usecallgraph or sysvals.usetraceevents): 2714 print('START TRACING') 2715 os.system('echo 1 > '+tp+'tracing_on') 2716 # initiate suspend 2717 if(sysvals.usecallgraph or sysvals.usetraceevents): 2718 os.system('echo SUSPEND START > '+tp+'trace_marker') 2719 if(sysvals.rtcwake): 2720 print('SUSPEND START') 2721 print('will autoresume in %d seconds' % sysvals.rtcwaketime) 2722 sysvals.rtcWakeAlarm() 2723 else: 2724 print('SUSPEND START (press a key to resume)') 2725 pf = open(sysvals.powerfile, 'w') 2726 pf.write(sysvals.suspendmode) 2727 # execution will pause here 2728 pf.close() 2729 t0 = time.time()*1000 2730 # return from suspend 2731 print('RESUME COMPLETE') 2732 if(sysvals.usecallgraph or sysvals.usetraceevents): 2733 os.system('echo RESUME COMPLETE > '+tp+'trace_marker') 2734 # see if there's firmware timing data to be had 2735 t = sysvals.postresumetime 2736 if(t > 0): 2737 print('Waiting %d seconds for POST-RESUME trace events...' % t) 2738 time.sleep(t) 2739 # stop ftrace 2740 if(sysvals.usecallgraph or sysvals.usetraceevents): 2741 os.system('echo 0 > '+tp+'tracing_on') 2742 print('CAPTURING TRACE') 2743 writeDatafileHeader(sysvals.ftracefile) 2744 os.system('cat '+tp+'trace >> '+sysvals.ftracefile) 2745 os.system('echo "" > '+tp+'trace') 2746 # grab a copy of the dmesg output 2747 print('CAPTURING DMESG') 2748 writeDatafileHeader(sysvals.dmesgfile) 2749 os.system('dmesg -c >> '+sysvals.dmesgfile) 2750 2751def writeDatafileHeader(filename): 2752 global sysvals 2753 2754 fw = getFPDT(False) 2755 prt = sysvals.postresumetime 2756 fp = open(filename, 'a') 2757 fp.write(sysvals.teststamp+'\n') 2758 if(fw): 2759 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) 2760 if(prt > 0): 2761 fp.write('# post resume time %u\n' % prt) 2762 fp.close() 2763 2764# Function: executeAndroidSuspend 2765# Description: 2766# Execute system suspend through the sysfs interface 2767# on a remote android device, then transfer the output 2768# dmesg and ftrace files to the local output directory. 2769def executeAndroidSuspend(): 2770 global sysvals 2771 2772 # check to see if the display is currently off 2773 tp = sysvals.tpath 2774 out = os.popen(sysvals.adb+\ 2775 ' shell dumpsys power | grep mScreenOn').read().strip() 2776 # if so we need to turn it on so we can issue a new suspend 2777 if(out.endswith('false')): 2778 print('Waking the device up for the test...') 2779 # send the KEYPAD_POWER keyevent to wake it up 2780 os.system(sysvals.adb+' shell input keyevent 26') 2781 # wait a few seconds so the user can see the device wake up 2782 time.sleep(3) 2783 # execute however many s/r runs requested 2784 for count in range(1,sysvals.execcount+1): 2785 # clear the kernel ring buffer just as we start 2786 os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1') 2787 # start ftrace 2788 if(sysvals.usetraceevents): 2789 print('START TRACING') 2790 os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'") 2791 # initiate suspend 2792 for count in range(1,sysvals.execcount+1): 2793 if(sysvals.usetraceevents): 2794 os.system(sysvals.adb+\ 2795 " shell 'echo SUSPEND START > "+tp+"trace_marker'") 2796 print('SUSPEND START (press a key on the device to resume)') 2797 os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\ 2798 " > "+sysvals.powerfile+"'") 2799 # execution will pause here, then adb will exit 2800 while(True): 2801 check = os.popen(sysvals.adb+\ 2802 ' shell pwd 2>/dev/null').read().strip() 2803 if(len(check) > 0): 2804 break 2805 time.sleep(1) 2806 if(sysvals.usetraceevents): 2807 os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\ 2808 "trace_marker'") 2809 # return from suspend 2810 print('RESUME COMPLETE') 2811 # stop ftrace 2812 if(sysvals.usetraceevents): 2813 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'") 2814 print('CAPTURING TRACE') 2815 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile) 2816 os.system(sysvals.adb+' shell cat '+tp+\ 2817 'trace >> '+sysvals.ftracefile) 2818 # grab a copy of the dmesg output 2819 print('CAPTURING DMESG') 2820 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile) 2821 os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile) 2822 2823# Function: setUSBDevicesAuto 2824# Description: 2825# Set the autosuspend control parameter of all USB devices to auto 2826# This can be dangerous, so use at your own risk, most devices are set 2827# to always-on since the kernel cant determine if the device can 2828# properly autosuspend 2829def setUSBDevicesAuto(): 2830 global sysvals 2831 2832 rootCheck() 2833 for dirname, dirnames, filenames in os.walk('/sys/devices'): 2834 if(re.match('.*/usb[0-9]*.*', dirname) and 2835 'idVendor' in filenames and 'idProduct' in filenames): 2836 os.system('echo auto > %s/power/control' % dirname) 2837 name = dirname.split('/')[-1] 2838 desc = os.popen('cat %s/product 2>/dev/null' % \ 2839 dirname).read().replace('\n', '') 2840 ctrl = os.popen('cat %s/power/control 2>/dev/null' % \ 2841 dirname).read().replace('\n', '') 2842 print('control is %s for %6s: %s' % (ctrl, name, desc)) 2843 2844# Function: yesno 2845# Description: 2846# Print out an equivalent Y or N for a set of known parameter values 2847# Output: 2848# 'Y', 'N', or ' ' if the value is unknown 2849def yesno(val): 2850 yesvals = ['auto', 'enabled', 'active', '1'] 2851 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported'] 2852 if val in yesvals: 2853 return 'Y' 2854 elif val in novals: 2855 return 'N' 2856 return ' ' 2857 2858# Function: ms2nice 2859# Description: 2860# Print out a very concise time string in minutes and seconds 2861# Output: 2862# The time string, e.g. "1901m16s" 2863def ms2nice(val): 2864 ms = 0 2865 try: 2866 ms = int(val) 2867 except: 2868 return 0.0 2869 m = ms / 60000 2870 s = (ms / 1000) - (m * 60) 2871 return '%3dm%2ds' % (m, s) 2872 2873# Function: detectUSB 2874# Description: 2875# Detect all the USB hosts and devices currently connected and add 2876# a list of USB device names to sysvals for better timeline readability 2877# Arguments: 2878# output: True to output the info to stdout, False otherwise 2879def detectUSB(output): 2880 global sysvals 2881 2882 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} 2883 power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'', 2884 'control':'', 'persist':'', 'runtime_enabled':'', 2885 'runtime_status':'', 'runtime_usage':'', 2886 'runtime_active_time':'', 2887 'runtime_suspended_time':'', 2888 'active_duration':'', 2889 'connected_duration':''} 2890 if(output): 2891 print('LEGEND') 2892 print('---------------------------------------------------------------------------------------------') 2893 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)') 2894 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)') 2895 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)') 2896 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)') 2897 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)') 2898 print(' U = runtime usage count') 2899 print('---------------------------------------------------------------------------------------------') 2900 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT') 2901 print('---------------------------------------------------------------------------------------------') 2902 2903 for dirname, dirnames, filenames in os.walk('/sys/devices'): 2904 if(re.match('.*/usb[0-9]*.*', dirname) and 2905 'idVendor' in filenames and 'idProduct' in filenames): 2906 for i in field: 2907 field[i] = os.popen('cat %s/%s 2>/dev/null' % \ 2908 (dirname, i)).read().replace('\n', '') 2909 name = dirname.split('/')[-1] 2910 if(len(field['product']) > 0): 2911 sysvals.altdevname[name] = \ 2912 '%s [%s]' % (field['product'], name) 2913 else: 2914 sysvals.altdevname[name] = \ 2915 '%s:%s [%s]' % (field['idVendor'], \ 2916 field['idProduct'], name) 2917 if(output): 2918 for i in power: 2919 power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \ 2920 (dirname, i)).read().replace('\n', '') 2921 if(re.match('usb[0-9]*', name)): 2922 first = '%-8s' % name 2923 else: 2924 first = '%8s' % name 2925 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \ 2926 (first, field['idVendor'], field['idProduct'], \ 2927 field['product'][0:20], field['speed'], \ 2928 yesno(power['async']), \ 2929 yesno(power['control']), \ 2930 yesno(power['persist']), \ 2931 yesno(power['runtime_enabled']), \ 2932 yesno(power['runtime_status']), \ 2933 power['runtime_usage'], \ 2934 power['autosuspend'], \ 2935 ms2nice(power['runtime_active_time']), \ 2936 ms2nice(power['runtime_suspended_time']), \ 2937 ms2nice(power['active_duration']), \ 2938 ms2nice(power['connected_duration']))) 2939 2940# Function: getModes 2941# Description: 2942# Determine the supported power modes on this system 2943# Output: 2944# A string list of the available modes 2945def getModes(): 2946 global sysvals 2947 modes = '' 2948 if(not sysvals.android): 2949 if(os.path.exists(sysvals.powerfile)): 2950 fp = open(sysvals.powerfile, 'r') 2951 modes = string.split(fp.read()) 2952 fp.close() 2953 else: 2954 line = os.popen(sysvals.adb+' shell cat '+\ 2955 sysvals.powerfile).read().strip() 2956 modes = string.split(line) 2957 return modes 2958 2959# Function: getFPDT 2960# Description: 2961# Read the acpi bios tables and pull out FPDT, the firmware data 2962# Arguments: 2963# output: True to output the info to stdout, False otherwise 2964def getFPDT(output): 2965 global sysvals 2966 2967 rectype = {} 2968 rectype[0] = 'Firmware Basic Boot Performance Record' 2969 rectype[1] = 'S3 Performance Table Record' 2970 prectype = {} 2971 prectype[0] = 'Basic S3 Resume Performance Record' 2972 prectype[1] = 'Basic S3 Suspend Performance Record' 2973 2974 rootCheck() 2975 if(not os.path.exists(sysvals.fpdtpath)): 2976 if(output): 2977 doError('file doesnt exist: %s' % sysvals.fpdtpath, False) 2978 return False 2979 if(not os.access(sysvals.fpdtpath, os.R_OK)): 2980 if(output): 2981 doError('file isnt readable: %s' % sysvals.fpdtpath, False) 2982 return False 2983 if(not os.path.exists(sysvals.mempath)): 2984 if(output): 2985 doError('file doesnt exist: %s' % sysvals.mempath, False) 2986 return False 2987 if(not os.access(sysvals.mempath, os.R_OK)): 2988 if(output): 2989 doError('file isnt readable: %s' % sysvals.mempath, False) 2990 return False 2991 2992 fp = open(sysvals.fpdtpath, 'rb') 2993 buf = fp.read() 2994 fp.close() 2995 2996 if(len(buf) < 36): 2997 if(output): 2998 doError('Invalid FPDT table data, should '+\ 2999 'be at least 36 bytes', False) 3000 return False 3001 3002 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36]) 3003 if(output): 3004 print('') 3005 print('Firmware Performance Data Table (%s)' % table[0]) 3006 print(' Signature : %s' % table[0]) 3007 print(' Table Length : %u' % table[1]) 3008 print(' Revision : %u' % table[2]) 3009 print(' Checksum : 0x%x' % table[3]) 3010 print(' OEM ID : %s' % table[4]) 3011 print(' OEM Table ID : %s' % table[5]) 3012 print(' OEM Revision : %u' % table[6]) 3013 print(' Creator ID : %s' % table[7]) 3014 print(' Creator Revision : 0x%x' % table[8]) 3015 print('') 3016 3017 if(table[0] != 'FPDT'): 3018 if(output): 3019 doError('Invalid FPDT table') 3020 return False 3021 if(len(buf) <= 36): 3022 return False 3023 i = 0 3024 fwData = [0, 0] 3025 records = buf[36:] 3026 fp = open(sysvals.mempath, 'rb') 3027 while(i < len(records)): 3028 header = struct.unpack('HBB', records[i:i+4]) 3029 if(header[0] not in rectype): 3030 continue 3031 if(header[1] != 16): 3032 continue 3033 addr = struct.unpack('Q', records[i+8:i+16])[0] 3034 try: 3035 fp.seek(addr) 3036 first = fp.read(8) 3037 except: 3038 doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False) 3039 rechead = struct.unpack('4sI', first) 3040 recdata = fp.read(rechead[1]-8) 3041 if(rechead[0] == 'FBPT'): 3042 record = struct.unpack('HBBIQQQQQ', recdata) 3043 if(output): 3044 print('%s (%s)' % (rectype[header[0]], rechead[0])) 3045 print(' Reset END : %u ns' % record[4]) 3046 print(' OS Loader LoadImage Start : %u ns' % record[5]) 3047 print(' OS Loader StartImage Start : %u ns' % record[6]) 3048 print(' ExitBootServices Entry : %u ns' % record[7]) 3049 print(' ExitBootServices Exit : %u ns' % record[8]) 3050 elif(rechead[0] == 'S3PT'): 3051 if(output): 3052 print('%s (%s)' % (rectype[header[0]], rechead[0])) 3053 j = 0 3054 while(j < len(recdata)): 3055 prechead = struct.unpack('HBB', recdata[j:j+4]) 3056 if(prechead[0] not in prectype): 3057 continue 3058 if(prechead[0] == 0): 3059 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]]) 3060 fwData[1] = record[2] 3061 if(output): 3062 print(' %s' % prectype[prechead[0]]) 3063 print(' Resume Count : %u' % \ 3064 record[1]) 3065 print(' FullResume : %u ns' % \ 3066 record[2]) 3067 print(' AverageResume : %u ns' % \ 3068 record[3]) 3069 elif(prechead[0] == 1): 3070 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]]) 3071 fwData[0] = record[1] - record[0] 3072 if(output): 3073 print(' %s' % prectype[prechead[0]]) 3074 print(' SuspendStart : %u ns' % \ 3075 record[0]) 3076 print(' SuspendEnd : %u ns' % \ 3077 record[1]) 3078 print(' SuspendTime : %u ns' % \ 3079 fwData[0]) 3080 j += prechead[1] 3081 if(output): 3082 print('') 3083 i += header[1] 3084 fp.close() 3085 return fwData 3086 3087# Function: statusCheck 3088# Description: 3089# Verify that the requested command and options will work, and 3090# print the results to the terminal 3091# Output: 3092# True if the test will work, False if not 3093def statusCheck(): 3094 global sysvals 3095 status = True 3096 3097 if(sysvals.android): 3098 print('Checking the android system ...') 3099 else: 3100 print('Checking this system (%s)...' % platform.node()) 3101 3102 # check if adb is connected to a device 3103 if(sysvals.android): 3104 res = 'NO' 3105 out = os.popen(sysvals.adb+' get-state').read().strip() 3106 if(out == 'device'): 3107 res = 'YES' 3108 print(' is android device connected: %s' % res) 3109 if(res != 'YES'): 3110 print(' Please connect the device before using this tool') 3111 return False 3112 3113 # check we have root access 3114 res = 'NO (No features of this tool will work!)' 3115 if(sysvals.android): 3116 out = os.popen(sysvals.adb+' shell id').read().strip() 3117 if('root' in out): 3118 res = 'YES' 3119 else: 3120 if(os.environ['USER'] == 'root'): 3121 res = 'YES' 3122 print(' have root access: %s' % res) 3123 if(res != 'YES'): 3124 if(sysvals.android): 3125 print(' Try running "adb root" to restart the daemon as root') 3126 else: 3127 print(' Try running this script with sudo') 3128 return False 3129 3130 # check sysfs is mounted 3131 res = 'NO (No features of this tool will work!)' 3132 if(sysvals.android): 3133 out = os.popen(sysvals.adb+' shell ls '+\ 3134 sysvals.powerfile).read().strip() 3135 if(out == sysvals.powerfile): 3136 res = 'YES' 3137 else: 3138 if(os.path.exists(sysvals.powerfile)): 3139 res = 'YES' 3140 print(' is sysfs mounted: %s' % res) 3141 if(res != 'YES'): 3142 return False 3143 3144 # check target mode is a valid mode 3145 res = 'NO' 3146 modes = getModes() 3147 if(sysvals.suspendmode in modes): 3148 res = 'YES' 3149 else: 3150 status = False 3151 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 3152 if(res == 'NO'): 3153 print(' valid power modes are: %s' % modes) 3154 print(' please choose one with -m') 3155 3156 # check if the tool can unlock the device 3157 if(sysvals.android): 3158 res = 'YES' 3159 out1 = os.popen(sysvals.adb+\ 3160 ' shell dumpsys power | grep mScreenOn').read().strip() 3161 out2 = os.popen(sysvals.adb+\ 3162 ' shell input').read().strip() 3163 if(not out1.startswith('mScreenOn') or not out2.startswith('usage')): 3164 res = 'NO (wake the android device up before running the test)' 3165 print(' can I unlock the screen: %s' % res) 3166 3167 # check if ftrace is available 3168 res = 'NO' 3169 ftgood = verifyFtrace() 3170 if(ftgood): 3171 res = 'YES' 3172 elif(sysvals.usecallgraph): 3173 status = False 3174 print(' is ftrace supported: %s' % res) 3175 3176 # what data source are we using 3177 res = 'DMESG' 3178 if(ftgood): 3179 sysvals.usetraceeventsonly = True 3180 sysvals.usetraceevents = False 3181 for e in sysvals.traceevents: 3182 check = False 3183 if(sysvals.android): 3184 out = os.popen(sysvals.adb+' shell ls -d '+\ 3185 sysvals.epath+e).read().strip() 3186 if(out == sysvals.epath+e): 3187 check = True 3188 else: 3189 if(os.path.exists(sysvals.epath+e)): 3190 check = True 3191 if(not check): 3192 sysvals.usetraceeventsonly = False 3193 if(e == 'suspend_resume' and check): 3194 sysvals.usetraceevents = True 3195 if(sysvals.usetraceevents and sysvals.usetraceeventsonly): 3196 res = 'FTRACE (all trace events found)' 3197 elif(sysvals.usetraceevents): 3198 res = 'DMESG and FTRACE (suspend_resume trace event found)' 3199 print(' timeline data source: %s' % res) 3200 3201 # check if rtcwake 3202 res = 'NO' 3203 if(sysvals.rtcpath != ''): 3204 res = 'YES' 3205 elif(sysvals.rtcwake): 3206 status = False 3207 print(' is rtcwake supported: %s' % res) 3208 3209 return status 3210 3211# Function: doError 3212# Description: 3213# generic error function for catastrphic failures 3214# Arguments: 3215# msg: the error message to print 3216# help: True if printHelp should be called after, False otherwise 3217def doError(msg, help): 3218 if(help == True): 3219 printHelp() 3220 print('ERROR: %s\n') % msg 3221 sys.exit() 3222 3223# Function: doWarning 3224# Description: 3225# generic warning function for non-catastrophic anomalies 3226# Arguments: 3227# msg: the warning message to print 3228# file: If not empty, a filename to request be sent to the owner for debug 3229def doWarning(msg, file): 3230 print('/* %s */') % msg 3231 if(file): 3232 print('/* For a fix, please send this'+\ 3233 ' %s file to <todd.e.brandt@intel.com> */' % file) 3234 3235# Function: rootCheck 3236# Description: 3237# quick check to see if we have root access 3238def rootCheck(): 3239 if(os.environ['USER'] != 'root'): 3240 doError('This script must be run as root', False) 3241 3242# Function: getArgInt 3243# Description: 3244# pull out an integer argument from the command line with checks 3245def getArgInt(name, args, min, max): 3246 try: 3247 arg = args.next() 3248 except: 3249 doError(name+': no argument supplied', True) 3250 try: 3251 val = int(arg) 3252 except: 3253 doError(name+': non-integer value given', True) 3254 if(val < min or val > max): 3255 doError(name+': value should be between %d and %d' % (min, max), True) 3256 return val 3257 3258# Function: rerunTest 3259# Description: 3260# generate an output from an existing set of ftrace/dmesg logs 3261def rerunTest(): 3262 global sysvals 3263 3264 if(sysvals.ftracefile != ''): 3265 doesTraceLogHaveTraceEvents() 3266 if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly): 3267 doError('recreating this html output '+\ 3268 'requires a dmesg file', False) 3269 sysvals.setOutputFile() 3270 vprint('Output file: %s' % sysvals.htmlfile) 3271 print('PROCESSING DATA') 3272 if(sysvals.usetraceeventsonly): 3273 testruns = parseTraceLog() 3274 else: 3275 testruns = loadKernelLog() 3276 for data in testruns: 3277 parseKernelLog(data) 3278 if(sysvals.ftracefile != ''): 3279 appendIncompleteTraceLog(testruns) 3280 createHTML(testruns) 3281 3282# Function: runTest 3283# Description: 3284# execute a suspend/resume, gather the logs, and generate the output 3285def runTest(subdir): 3286 global sysvals 3287 3288 # prepare for the test 3289 if(not sysvals.android): 3290 initFtrace() 3291 else: 3292 initFtraceAndroid() 3293 sysvals.initTestOutput(subdir) 3294 3295 vprint('Output files:\n %s' % sysvals.dmesgfile) 3296 if(sysvals.usecallgraph or 3297 sysvals.usetraceevents or 3298 sysvals.usetraceeventsonly): 3299 vprint(' %s' % sysvals.ftracefile) 3300 vprint(' %s' % sysvals.htmlfile) 3301 3302 # execute the test 3303 if(not sysvals.android): 3304 executeSuspend() 3305 else: 3306 executeAndroidSuspend() 3307 3308 # analyze the data and create the html output 3309 print('PROCESSING DATA') 3310 if(sysvals.usetraceeventsonly): 3311 # data for kernels 3.15 or newer is entirely in ftrace 3312 testruns = parseTraceLog() 3313 else: 3314 # data for kernels older than 3.15 is primarily in dmesg 3315 testruns = loadKernelLog() 3316 for data in testruns: 3317 parseKernelLog(data) 3318 if(sysvals.usecallgraph or sysvals.usetraceevents): 3319 appendIncompleteTraceLog(testruns) 3320 createHTML(testruns) 3321 3322# Function: runSummary 3323# Description: 3324# create a summary of tests in a sub-directory 3325def runSummary(subdir, output): 3326 global sysvals 3327 3328 # get a list of ftrace output files 3329 files = [] 3330 for dirname, dirnames, filenames in os.walk(subdir): 3331 for filename in filenames: 3332 if(re.match('.*_ftrace.txt', filename)): 3333 files.append("%s/%s" % (dirname, filename)) 3334 3335 # process the files in order and get an array of data objects 3336 testruns = [] 3337 for file in sorted(files): 3338 if output: 3339 print("Test found in %s" % os.path.dirname(file)) 3340 sysvals.ftracefile = file 3341 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt') 3342 doesTraceLogHaveTraceEvents() 3343 sysvals.usecallgraph = False 3344 if not sysvals.usetraceeventsonly: 3345 if(not os.path.exists(sysvals.dmesgfile)): 3346 print("Skipping %s: not a valid test input" % file) 3347 continue 3348 else: 3349 if output: 3350 f = os.path.basename(sysvals.ftracefile) 3351 d = os.path.basename(sysvals.dmesgfile) 3352 print("\tInput files: %s and %s" % (f, d)) 3353 testdata = loadKernelLog() 3354 data = testdata[0] 3355 parseKernelLog(data) 3356 testdata = [data] 3357 appendIncompleteTraceLog(testdata) 3358 else: 3359 if output: 3360 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile)) 3361 testdata = parseTraceLog() 3362 data = testdata[0] 3363 data.normalizeTime(data.tSuspended) 3364 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html') 3365 data.outfile = link 3366 testruns.append(data) 3367 3368 createHTMLSummarySimple(testruns, subdir+'/summary.html') 3369 3370# Function: printHelp 3371# Description: 3372# print out the help text 3373def printHelp(): 3374 global sysvals 3375 modes = getModes() 3376 3377 print('') 3378 print('AnalyzeSuspend v%.1f' % sysvals.version) 3379 print('Usage: sudo analyze_suspend.py <options>') 3380 print('') 3381 print('Description:') 3382 print(' This tool is designed to assist kernel and OS developers in optimizing') 3383 print(' their linux stack\'s suspend/resume time. Using a kernel image built') 3384 print(' with a few extra options enabled, the tool will execute a suspend and') 3385 print(' capture dmesg and ftrace data until resume is complete. This data is') 3386 print(' transformed into a device timeline and an optional callgraph to give') 3387 print(' a detailed view of which devices/subsystems are taking the most') 3388 print(' time in suspend/resume.') 3389 print('') 3390 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS') 3391 print(' HTML output: <hostname>_<mode>.html') 3392 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt') 3393 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt') 3394 print('') 3395 print('Options:') 3396 print(' [general]') 3397 print(' -h Print this help text') 3398 print(' -v Print the current tool version') 3399 print(' -verbose Print extra information during execution and analysis') 3400 print(' -status Test to see if the system is enabled to run this tool') 3401 print(' -modes List available suspend modes') 3402 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode) 3403 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)') 3404 print(' [advanced]') 3405 print(' -f Use ftrace to create device callgraphs (default: disabled)') 3406 print(' -filter "d1 d2 ..." Filter out all but this list of dev names') 3407 print(' -x2 Run two suspend/resumes back to back (default: disabled)') 3408 print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)') 3409 print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)') 3410 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will') 3411 print(' be created in a new subdirectory with a summary page.') 3412 print(' [utilities]') 3413 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') 3414 print(' -usbtopo Print out the current USB topology with power info') 3415 print(' -usbauto Enable autosuspend for all connected USB devices') 3416 print(' [android testing]') 3417 print(' -adb binary Use the given adb binary to run the test on an android device.') 3418 print(' The device should already be connected and with root access.') 3419 print(' Commands will be executed on the device using "adb shell"') 3420 print(' [re-analyze data from previous runs]') 3421 print(' -ftrace ftracefile Create HTML output using ftrace input') 3422 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)') 3423 print(' -summary directory Create a summary of all test in this dir') 3424 print('') 3425 return True 3426 3427# ----------------- MAIN -------------------- 3428# exec start (skipped if script is loaded as library) 3429if __name__ == '__main__': 3430 cmd = '' 3431 cmdarg = '' 3432 multitest = {'run': False, 'count': 0, 'delay': 0} 3433 # loop through the command line arguments 3434 args = iter(sys.argv[1:]) 3435 for arg in args: 3436 if(arg == '-m'): 3437 try: 3438 val = args.next() 3439 except: 3440 doError('No mode supplied', True) 3441 sysvals.suspendmode = val 3442 elif(arg == '-adb'): 3443 try: 3444 val = args.next() 3445 except: 3446 doError('No adb binary supplied', True) 3447 if(not os.path.exists(val)): 3448 doError('file doesnt exist: %s' % val, False) 3449 if(not os.access(val, os.X_OK)): 3450 doError('file isnt executable: %s' % val, False) 3451 try: 3452 check = os.popen(val+' version').read().strip() 3453 except: 3454 doError('adb version failed to execute', False) 3455 if(not re.match('Android Debug Bridge .*', check)): 3456 doError('adb version failed to execute', False) 3457 sysvals.adb = val 3458 sysvals.android = True 3459 elif(arg == '-x2'): 3460 if(sysvals.postresumetime > 0): 3461 doError('-x2 is not compatible with -postres', False) 3462 sysvals.execcount = 2 3463 elif(arg == '-x2delay'): 3464 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000) 3465 elif(arg == '-postres'): 3466 if(sysvals.execcount != 1): 3467 doError('-x2 is not compatible with -postres', False) 3468 sysvals.postresumetime = getArgInt('-postres', args, 0, 3600) 3469 elif(arg == '-f'): 3470 sysvals.usecallgraph = True 3471 elif(arg == '-modes'): 3472 cmd = 'modes' 3473 elif(arg == '-fpdt'): 3474 cmd = 'fpdt' 3475 elif(arg == '-usbtopo'): 3476 cmd = 'usbtopo' 3477 elif(arg == '-usbauto'): 3478 cmd = 'usbauto' 3479 elif(arg == '-status'): 3480 cmd = 'status' 3481 elif(arg == '-verbose'): 3482 sysvals.verbose = True 3483 elif(arg == '-v'): 3484 print("Version %.1f" % sysvals.version) 3485 sys.exit() 3486 elif(arg == '-rtcwake'): 3487 sysvals.rtcwake = True 3488 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600) 3489 elif(arg == '-multi'): 3490 multitest['run'] = True 3491 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000) 3492 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600) 3493 elif(arg == '-dmesg'): 3494 try: 3495 val = args.next() 3496 except: 3497 doError('No dmesg file supplied', True) 3498 sysvals.notestrun = True 3499 sysvals.dmesgfile = val 3500 if(os.path.exists(sysvals.dmesgfile) == False): 3501 doError('%s doesnt exist' % sysvals.dmesgfile, False) 3502 elif(arg == '-ftrace'): 3503 try: 3504 val = args.next() 3505 except: 3506 doError('No ftrace file supplied', True) 3507 sysvals.notestrun = True 3508 sysvals.usecallgraph = True 3509 sysvals.ftracefile = val 3510 if(os.path.exists(sysvals.ftracefile) == False): 3511 doError('%s doesnt exist' % sysvals.ftracefile, False) 3512 elif(arg == '-summary'): 3513 try: 3514 val = args.next() 3515 except: 3516 doError('No directory supplied', True) 3517 cmd = 'summary' 3518 cmdarg = val 3519 sysvals.notestrun = True 3520 if(os.path.isdir(val) == False): 3521 doError('%s isnt accesible' % val, False) 3522 elif(arg == '-filter'): 3523 try: 3524 val = args.next() 3525 except: 3526 doError('No devnames supplied', True) 3527 sysvals.setDeviceFilter(val) 3528 elif(arg == '-h'): 3529 printHelp() 3530 sys.exit() 3531 else: 3532 doError('Invalid argument: '+arg, True) 3533 3534 # just run a utility command and exit 3535 if(cmd != ''): 3536 if(cmd == 'status'): 3537 statusCheck() 3538 elif(cmd == 'fpdt'): 3539 if(sysvals.android): 3540 doError('cannot read FPDT on android device', False) 3541 getFPDT(True) 3542 elif(cmd == 'usbtopo'): 3543 if(sysvals.android): 3544 doError('cannot read USB topology '+\ 3545 'on an android device', False) 3546 detectUSB(True) 3547 elif(cmd == 'modes'): 3548 modes = getModes() 3549 print modes 3550 elif(cmd == 'usbauto'): 3551 setUSBDevicesAuto() 3552 elif(cmd == 'summary'): 3553 print("Generating a summary of folder \"%s\"" % cmdarg) 3554 runSummary(cmdarg, True) 3555 sys.exit() 3556 3557 # run test on android device 3558 if(sysvals.android): 3559 if(sysvals.usecallgraph): 3560 doError('ftrace (-f) is not yet supported '+\ 3561 'in the android kernel', False) 3562 if(sysvals.notestrun): 3563 doError('cannot analyze test files on the '+\ 3564 'android device', False) 3565 3566 # if instructed, re-analyze existing data files 3567 if(sysvals.notestrun): 3568 rerunTest() 3569 sys.exit() 3570 3571 # verify that we can run a test 3572 if(not statusCheck()): 3573 print('Check FAILED, aborting the test run!') 3574 sys.exit() 3575 3576 if multitest['run']: 3577 # run multiple tests in a separte subdirectory 3578 s = 'x%d' % multitest['count'] 3579 subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S') 3580 os.mkdir(subdir) 3581 for i in range(multitest['count']): 3582 if(i != 0): 3583 print('Waiting %d seconds...' % (multitest['delay'])) 3584 time.sleep(multitest['delay']) 3585 print('TEST (%d/%d) START' % (i+1, multitest['count'])) 3586 runTest(subdir) 3587 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) 3588 runSummary(subdir, False) 3589 else: 3590 # run the test in the current directory 3591 runTest(".") 3592