at v4.11-rc7 174 kB view raw
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# Links: 23# Home Page 24# https://01.org/suspendresume 25# Source repo 26# https://github.com/01org/suspendresume 27# 28# Description: 29# This tool is designed to assist kernel and OS developers in optimizing 30# their linux stack's suspend/resume time. Using a kernel image built 31# with a few extra options enabled, the tool will execute a suspend and 32# will capture dmesg and ftrace data until resume is complete. This data 33# is transformed into a device timeline and a callgraph to give a quick 34# and detailed view of which devices and callbacks are taking the most 35# time in suspend/resume. The output is a single html file which can be 36# viewed in firefox or chrome. 37# 38# The following kernel build options are required: 39# CONFIG_PM_DEBUG=y 40# CONFIG_PM_SLEEP_DEBUG=y 41# CONFIG_FTRACE=y 42# CONFIG_FUNCTION_TRACER=y 43# CONFIG_FUNCTION_GRAPH_TRACER=y 44# CONFIG_KPROBES=y 45# CONFIG_KPROBES_ON_FTRACE=y 46# 47# For kernel versions older than 3.15: 48# The following additional kernel parameters are required: 49# (e.g. in file /etc/default/grub) 50# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." 51# 52 53# ----------------- LIBRARIES -------------------- 54 55import sys 56import time 57import os 58import string 59import re 60import platform 61from datetime import datetime 62import struct 63import ConfigParser 64from threading import Thread 65from subprocess import call, Popen, PIPE 66 67# ----------------- CLASSES -------------------- 68 69# Class: SystemValues 70# Description: 71# A global, single-instance container used to 72# store system values and test parameters 73class SystemValues: 74 ansi = False 75 version = '4.5' 76 verbose = False 77 addlogs = False 78 mindevlen = 0.0 79 mincglen = 0.0 80 cgphase = '' 81 cgtest = -1 82 callloopmaxgap = 0.0001 83 callloopmaxlen = 0.005 84 srgap = 0 85 cgexp = False 86 outdir = '' 87 testdir = '.' 88 tpath = '/sys/kernel/debug/tracing/' 89 fpdtpath = '/sys/firmware/acpi/tables/FPDT' 90 epath = '/sys/kernel/debug/tracing/events/power/' 91 traceevents = [ 92 'suspend_resume', 93 'device_pm_callback_end', 94 'device_pm_callback_start' 95 ] 96 logmsg = '' 97 testcommand = '' 98 mempath = '/dev/mem' 99 powerfile = '/sys/power/state' 100 suspendmode = 'mem' 101 hostname = 'localhost' 102 prefix = 'test' 103 teststamp = '' 104 dmesgstart = 0.0 105 dmesgfile = '' 106 ftracefile = '' 107 htmlfile = '' 108 embedded = False 109 rtcwake = False 110 rtcwaketime = 10 111 rtcpath = '' 112 devicefilter = [] 113 stamp = 0 114 execcount = 1 115 x2delay = 0 116 usecallgraph = False 117 usetraceevents = False 118 usetraceeventsonly = False 119 usetracemarkers = True 120 usekprobes = True 121 usedevsrc = False 122 useprocmon = False 123 notestrun = False 124 mixedphaseheight = True 125 devprops = dict() 126 predelay = 0 127 postdelay = 0 128 procexecfmt = 'ps - (?P<ps>.*)$' 129 devpropfmt = '# Device Properties: .*' 130 tracertypefmt = '# tracer: (?P<t>.*)' 131 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' 132 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ 133 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ 134 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' 135 tracefuncs = { 136 'sys_sync': dict(), 137 'pm_prepare_console': dict(), 138 'pm_notifier_call_chain': dict(), 139 'freeze_processes': dict(), 140 'freeze_kernel_threads': dict(), 141 'pm_restrict_gfp_mask': dict(), 142 'acpi_suspend_begin': dict(), 143 'suspend_console': dict(), 144 'acpi_pm_prepare': dict(), 145 'syscore_suspend': dict(), 146 'arch_enable_nonboot_cpus_end': dict(), 147 'syscore_resume': dict(), 148 'acpi_pm_finish': dict(), 149 'resume_console': dict(), 150 'acpi_pm_end': dict(), 151 'pm_restore_gfp_mask': dict(), 152 'thaw_processes': dict(), 153 'pm_restore_console': dict(), 154 'CPU_OFF': { 155 'func':'_cpu_down', 156 'args_x86_64': {'cpu':'%di:s32'}, 157 'format': 'CPU_OFF[{cpu}]' 158 }, 159 'CPU_ON': { 160 'func':'_cpu_up', 161 'args_x86_64': {'cpu':'%di:s32'}, 162 'format': 'CPU_ON[{cpu}]' 163 }, 164 } 165 dev_tracefuncs = { 166 # general wait/delay/sleep 167 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 }, 168 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 169 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 170 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 }, 171 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, 172 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, 173 'acpi_os_stall': {'ub': 1}, 174 # ACPI 175 'acpi_resume_power_resources': dict(), 176 'acpi_ps_parse_aml': dict(), 177 # filesystem 178 'ext4_sync_fs': dict(), 179 # 80211 180 'iwlagn_mac_start': dict(), 181 'iwlagn_alloc_bcast_station': dict(), 182 'iwl_trans_pcie_start_hw': dict(), 183 'iwl_trans_pcie_start_fw': dict(), 184 'iwl_run_init_ucode': dict(), 185 'iwl_load_ucode_wait_alive': dict(), 186 'iwl_alive_start': dict(), 187 'iwlagn_mac_stop': dict(), 188 'iwlagn_mac_suspend': dict(), 189 'iwlagn_mac_resume': dict(), 190 'iwlagn_mac_add_interface': dict(), 191 'iwlagn_mac_remove_interface': dict(), 192 'iwlagn_mac_change_interface': dict(), 193 'iwlagn_mac_config': dict(), 194 'iwlagn_configure_filter': dict(), 195 'iwlagn_mac_hw_scan': dict(), 196 'iwlagn_bss_info_changed': dict(), 197 'iwlagn_mac_channel_switch': dict(), 198 'iwlagn_mac_flush': dict(), 199 # ATA 200 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} }, 201 # i915 202 'i915_gem_resume': dict(), 203 'i915_restore_state': dict(), 204 'intel_opregion_setup': dict(), 205 'g4x_pre_enable_dp': dict(), 206 'vlv_pre_enable_dp': dict(), 207 'chv_pre_enable_dp': dict(), 208 'g4x_enable_dp': dict(), 209 'vlv_enable_dp': dict(), 210 'intel_hpd_init': dict(), 211 'intel_opregion_register': dict(), 212 'intel_dp_detect': dict(), 213 'intel_hdmi_detect': dict(), 214 'intel_opregion_init': dict(), 215 'intel_fbdev_set_suspend': dict(), 216 } 217 kprobes = dict() 218 timeformat = '%.3f' 219 def __init__(self): 220 # if this is a phoronix test run, set some default options 221 if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): 222 self.embedded = True 223 self.addlogs = True 224 self.htmlfile = os.environ['LOG_FILE'] 225 self.archargs = 'args_'+platform.machine() 226 self.hostname = platform.node() 227 if(self.hostname == ''): 228 self.hostname = 'localhost' 229 rtc = "rtc0" 230 if os.path.exists('/dev/rtc'): 231 rtc = os.readlink('/dev/rtc') 232 rtc = '/sys/class/rtc/'+rtc 233 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \ 234 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'): 235 self.rtcpath = rtc 236 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): 237 self.ansi = True 238 def setPrecision(self, num): 239 if num < 0 or num > 6: 240 return 241 self.timeformat = '%.{0}f'.format(num) 242 def setOutputFolder(self, value): 243 args = dict() 244 n = datetime.now() 245 args['date'] = n.strftime('%y%m%d') 246 args['time'] = n.strftime('%H%M%S') 247 args['hostname'] = self.hostname 248 self.outdir = value.format(**args) 249 def setOutputFile(self): 250 if((self.htmlfile == '') and (self.dmesgfile != '')): 251 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile) 252 if(m): 253 self.htmlfile = m.group('name')+'.html' 254 if((self.htmlfile == '') and (self.ftracefile != '')): 255 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile) 256 if(m): 257 self.htmlfile = m.group('name')+'.html' 258 if(self.htmlfile == ''): 259 self.htmlfile = 'output.html' 260 def initTestOutput(self, subdir, testpath=''): 261 self.prefix = self.hostname 262 v = open('/proc/version', 'r').read().strip() 263 kver = string.split(v)[2] 264 n = datetime.now() 265 testtime = n.strftime('suspend-%m%d%y-%H%M%S') 266 if not testpath: 267 testpath = n.strftime('suspend-%y%m%d-%H%M%S') 268 if(subdir != "."): 269 self.testdir = subdir+"/"+testpath 270 else: 271 self.testdir = testpath 272 self.teststamp = \ 273 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver 274 if(self.embedded): 275 self.dmesgfile = \ 276 '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt' 277 self.ftracefile = \ 278 '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt' 279 return 280 self.dmesgfile = \ 281 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' 282 self.ftracefile = \ 283 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' 284 self.htmlfile = \ 285 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' 286 if not os.path.isdir(self.testdir): 287 os.mkdir(self.testdir) 288 def setDeviceFilter(self, value): 289 self.devicefilter = [] 290 if value: 291 value = value.split(',') 292 for i in value: 293 self.devicefilter.append(i.strip()) 294 def rtcWakeAlarmOn(self): 295 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True) 296 outD = open(self.rtcpath+'/date', 'r').read().strip() 297 outT = open(self.rtcpath+'/time', 'r').read().strip() 298 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD) 299 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT) 300 if(mD and mT): 301 # get the current time from hardware 302 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds()) 303 dt = datetime(\ 304 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')), 305 int(mT.group('h')), int(mT.group('m')), int(mT.group('s'))) 306 nowtime = int(dt.strftime('%s')) + utcoffset 307 else: 308 # if hardware time fails, use the software time 309 nowtime = int(datetime.now().strftime('%s')) 310 alarm = nowtime + self.rtcwaketime 311 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True) 312 def rtcWakeAlarmOff(self): 313 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True) 314 def initdmesg(self): 315 # get the latest time stamp from the dmesg log 316 fp = Popen('dmesg', stdout=PIPE).stdout 317 ktime = '0' 318 for line in fp: 319 line = line.replace('\r\n', '') 320 idx = line.find('[') 321 if idx > 1: 322 line = line[idx:] 323 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 324 if(m): 325 ktime = m.group('ktime') 326 fp.close() 327 self.dmesgstart = float(ktime) 328 def getdmesg(self): 329 # store all new dmesg lines since initdmesg was called 330 fp = Popen('dmesg', stdout=PIPE).stdout 331 op = open(self.dmesgfile, 'a') 332 for line in fp: 333 line = line.replace('\r\n', '') 334 idx = line.find('[') 335 if idx > 1: 336 line = line[idx:] 337 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 338 if(not m): 339 continue 340 ktime = float(m.group('ktime')) 341 if ktime > self.dmesgstart: 342 op.write(line) 343 fp.close() 344 op.close() 345 def addFtraceFilterFunctions(self, file): 346 fp = open(file) 347 list = fp.read().split('\n') 348 fp.close() 349 for i in list: 350 if len(i) < 2: 351 continue 352 self.tracefuncs[i] = dict() 353 def getFtraceFilterFunctions(self, current): 354 rootCheck(True) 355 if not current: 356 call('cat '+self.tpath+'available_filter_functions', shell=True) 357 return 358 fp = open(self.tpath+'available_filter_functions') 359 master = fp.read().split('\n') 360 fp.close() 361 for i in self.tracefuncs: 362 if 'func' in self.tracefuncs[i]: 363 i = self.tracefuncs[i]['func'] 364 if i in master: 365 print i 366 else: 367 print self.colorText(i) 368 def setFtraceFilterFunctions(self, list): 369 fp = open(self.tpath+'available_filter_functions') 370 master = fp.read().split('\n') 371 fp.close() 372 flist = '' 373 for i in list: 374 if i not in master: 375 continue 376 if ' [' in i: 377 flist += i.split(' ')[0]+'\n' 378 else: 379 flist += i+'\n' 380 fp = open(self.tpath+'set_graph_function', 'w') 381 fp.write(flist) 382 fp.close() 383 def basicKprobe(self, name): 384 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name} 385 def defaultKprobe(self, name, kdata): 386 k = kdata 387 for field in ['name', 'format', 'func']: 388 if field not in k: 389 k[field] = name 390 if self.archargs in k: 391 k['args'] = k[self.archargs] 392 else: 393 k['args'] = dict() 394 k['format'] = name 395 self.kprobes[name] = k 396 def kprobeColor(self, name): 397 if name not in self.kprobes or 'color' not in self.kprobes[name]: 398 return '' 399 return self.kprobes[name]['color'] 400 def kprobeDisplayName(self, name, dataraw): 401 if name not in self.kprobes: 402 self.basicKprobe(name) 403 data = '' 404 quote=0 405 # first remvoe any spaces inside quotes, and the quotes 406 for c in dataraw: 407 if c == '"': 408 quote = (quote + 1) % 2 409 if quote and c == ' ': 410 data += '_' 411 elif c != '"': 412 data += c 413 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args'] 414 arglist = dict() 415 # now process the args 416 for arg in sorted(args): 417 arglist[arg] = '' 418 m = re.match('.* '+arg+'=(?P<arg>.*) ', data); 419 if m: 420 arglist[arg] = m.group('arg') 421 else: 422 m = re.match('.* '+arg+'=(?P<arg>.*)', data); 423 if m: 424 arglist[arg] = m.group('arg') 425 out = fmt.format(**arglist) 426 out = out.replace(' ', '_').replace('"', '') 427 return out 428 def kprobeText(self, kname, kprobe): 429 name = fmt = func = kname 430 args = dict() 431 if 'name' in kprobe: 432 name = kprobe['name'] 433 if 'format' in kprobe: 434 fmt = kprobe['format'] 435 if 'func' in kprobe: 436 func = kprobe['func'] 437 if self.archargs in kprobe: 438 args = kprobe[self.archargs] 439 if 'args' in kprobe: 440 args = kprobe['args'] 441 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func): 442 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func)) 443 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt): 444 if arg not in args: 445 doError('Kprobe "%s" is missing argument "%s"' % (name, arg)) 446 val = 'p:%s_cal %s' % (name, func) 447 for i in sorted(args): 448 val += ' %s=%s' % (i, args[i]) 449 val += '\nr:%s_ret %s $retval\n' % (name, func) 450 return val 451 def addKprobes(self, output=False): 452 if len(sysvals.kprobes) < 1: 453 return 454 if output: 455 print(' kprobe functions in this kernel:') 456 # first test each kprobe 457 rejects = [] 458 # sort kprobes: trace, ub-dev, custom, dev 459 kpl = [[], [], [], []] 460 for name in sorted(self.kprobes): 461 res = self.colorText('YES', 32) 462 if not self.testKprobe(name, self.kprobes[name]): 463 res = self.colorText('NO') 464 rejects.append(name) 465 else: 466 if name in self.tracefuncs: 467 kpl[0].append(name) 468 elif name in self.dev_tracefuncs: 469 if 'ub' in self.dev_tracefuncs[name]: 470 kpl[1].append(name) 471 else: 472 kpl[3].append(name) 473 else: 474 kpl[2].append(name) 475 if output: 476 print(' %s: %s' % (name, res)) 477 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3] 478 # remove all failed ones from the list 479 for name in rejects: 480 self.kprobes.pop(name) 481 # set the kprobes all at once 482 self.fsetVal('', 'kprobe_events') 483 kprobeevents = '' 484 for kp in kplist: 485 kprobeevents += self.kprobeText(kp, self.kprobes[kp]) 486 self.fsetVal(kprobeevents, 'kprobe_events') 487 # verify that the kprobes were set as ordered 488 check = self.fgetVal('kprobe_events') 489 linesout = len(kprobeevents.split('\n')) - 1 490 linesack = len(check.split('\n')) - 1 491 if output: 492 res = '%d/%d' % (linesack, linesout) 493 if linesack < linesout: 494 res = self.colorText(res, 31) 495 else: 496 res = self.colorText(res, 32) 497 print(' working kprobe functions enabled: %s' % res) 498 self.fsetVal('1', 'events/kprobes/enable') 499 def testKprobe(self, kname, kprobe): 500 self.fsetVal('0', 'events/kprobes/enable') 501 kprobeevents = self.kprobeText(kname, kprobe) 502 if not kprobeevents: 503 return False 504 try: 505 self.fsetVal(kprobeevents, 'kprobe_events') 506 check = self.fgetVal('kprobe_events') 507 except: 508 return False 509 linesout = len(kprobeevents.split('\n')) 510 linesack = len(check.split('\n')) 511 if linesack < linesout: 512 return False 513 return True 514 def fsetVal(self, val, path, mode='w'): 515 file = self.tpath+path 516 if not os.path.exists(file): 517 return False 518 try: 519 fp = open(file, mode, 0) 520 fp.write(val) 521 fp.flush() 522 fp.close() 523 except: 524 pass 525 return True 526 def fgetVal(self, path): 527 file = self.tpath+path 528 res = '' 529 if not os.path.exists(file): 530 return res 531 try: 532 fp = open(file, 'r') 533 res = fp.read() 534 fp.close() 535 except: 536 pass 537 return res 538 def cleanupFtrace(self): 539 if(self.usecallgraph or self.usetraceevents): 540 self.fsetVal('0', 'events/kprobes/enable') 541 self.fsetVal('', 'kprobe_events') 542 def setupAllKprobes(self): 543 for name in self.tracefuncs: 544 self.defaultKprobe(name, self.tracefuncs[name]) 545 for name in self.dev_tracefuncs: 546 self.defaultKprobe(name, self.dev_tracefuncs[name]) 547 def isCallgraphFunc(self, name): 548 if len(self.tracefuncs) < 1 and self.suspendmode == 'command': 549 return True 550 for i in self.tracefuncs: 551 if 'func' in self.tracefuncs[i]: 552 f = self.tracefuncs[i]['func'] 553 else: 554 f = i 555 if name == f: 556 return True 557 return False 558 def initFtrace(self, testing=False): 559 print('INITIALIZING FTRACE...') 560 # turn trace off 561 self.fsetVal('0', 'tracing_on') 562 self.cleanupFtrace() 563 # set the trace clock to global 564 self.fsetVal('global', 'trace_clock') 565 # set trace buffer to a huge value 566 self.fsetVal('nop', 'current_tracer') 567 self.fsetVal('100000', 'buffer_size_kb') 568 # go no further if this is just a status check 569 if testing: 570 return 571 # initialize the callgraph trace 572 if(self.usecallgraph): 573 # set trace type 574 self.fsetVal('function_graph', 'current_tracer') 575 self.fsetVal('', 'set_ftrace_filter') 576 # set trace format options 577 self.fsetVal('print-parent', 'trace_options') 578 self.fsetVal('funcgraph-abstime', 'trace_options') 579 self.fsetVal('funcgraph-cpu', 'trace_options') 580 self.fsetVal('funcgraph-duration', 'trace_options') 581 self.fsetVal('funcgraph-proc', 'trace_options') 582 self.fsetVal('funcgraph-tail', 'trace_options') 583 self.fsetVal('nofuncgraph-overhead', 'trace_options') 584 self.fsetVal('context-info', 'trace_options') 585 self.fsetVal('graph-time', 'trace_options') 586 self.fsetVal('0', 'max_graph_depth') 587 cf = ['dpm_run_callback'] 588 if(self.usetraceeventsonly): 589 cf += ['dpm_prepare', 'dpm_complete'] 590 for fn in self.tracefuncs: 591 if 'func' in self.tracefuncs[fn]: 592 cf.append(self.tracefuncs[fn]['func']) 593 else: 594 cf.append(fn) 595 self.setFtraceFilterFunctions(cf) 596 # initialize the kprobe trace 597 elif self.usekprobes: 598 for name in self.tracefuncs: 599 self.defaultKprobe(name, self.tracefuncs[name]) 600 if self.usedevsrc: 601 for name in self.dev_tracefuncs: 602 self.defaultKprobe(name, self.dev_tracefuncs[name]) 603 print('INITIALIZING KPROBES...') 604 self.addKprobes(self.verbose) 605 if(self.usetraceevents): 606 # turn trace events on 607 events = iter(self.traceevents) 608 for e in events: 609 self.fsetVal('1', 'events/power/'+e+'/enable') 610 # clear the trace buffer 611 self.fsetVal('', 'trace') 612 def verifyFtrace(self): 613 # files needed for any trace data 614 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock', 615 'trace_marker', 'trace_options', 'tracing_on'] 616 # files needed for callgraph trace data 617 tp = self.tpath 618 if(self.usecallgraph): 619 files += [ 620 'available_filter_functions', 621 'set_ftrace_filter', 622 'set_graph_function' 623 ] 624 for f in files: 625 if(os.path.exists(tp+f) == False): 626 return False 627 return True 628 def verifyKprobes(self): 629 # files needed for kprobes to work 630 files = ['kprobe_events', 'events'] 631 tp = self.tpath 632 for f in files: 633 if(os.path.exists(tp+f) == False): 634 return False 635 return True 636 def colorText(self, str, color=31): 637 if not self.ansi: 638 return str 639 return '\x1B[%d;40m%s\x1B[m' % (color, str) 640 641sysvals = SystemValues() 642 643# Class: DevProps 644# Description: 645# Simple class which holds property values collected 646# for all the devices used in the timeline. 647class DevProps: 648 syspath = '' 649 altname = '' 650 async = True 651 xtraclass = '' 652 xtrainfo = '' 653 def out(self, dev): 654 return '%s,%s,%d;' % (dev, self.altname, self.async) 655 def debug(self, dev): 656 print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async) 657 def altName(self, dev): 658 if not self.altname or self.altname == dev: 659 return dev 660 return '%s [%s]' % (self.altname, dev) 661 def xtraClass(self): 662 if self.xtraclass: 663 return ' '+self.xtraclass 664 if not self.async: 665 return ' sync' 666 return '' 667 def xtraInfo(self): 668 if self.xtraclass: 669 return ' '+self.xtraclass 670 if self.async: 671 return ' async_device' 672 return ' sync_device' 673 674# Class: DeviceNode 675# Description: 676# A container used to create a device hierachy, with a single root node 677# and a tree of child nodes. Used by Data.deviceTopology() 678class DeviceNode: 679 name = '' 680 children = 0 681 depth = 0 682 def __init__(self, nodename, nodedepth): 683 self.name = nodename 684 self.children = [] 685 self.depth = nodedepth 686 687# Class: Data 688# Description: 689# The primary container for suspend/resume test data. There is one for 690# each test run. The data is organized into a cronological hierarchy: 691# Data.dmesg { 692# phases { 693# 10 sequential, non-overlapping phases of S/R 694# contents: times for phase start/end, order/color data for html 695# devlist { 696# device callback or action list for this phase 697# device { 698# a single device callback or generic action 699# contents: start/stop times, pid/cpu/driver info 700# parents/children, html id for timeline/callgraph 701# optionally includes an ftrace callgraph 702# optionally includes dev/ps data 703# } 704# } 705# } 706# } 707# 708class Data: 709 dmesg = {} # root data structure 710 phases = [] # ordered list of phases 711 start = 0.0 # test start 712 end = 0.0 # test end 713 tSuspended = 0.0 # low-level suspend start 714 tResumed = 0.0 # low-level resume start 715 tKernSus = 0.0 # kernel level suspend start 716 tKernRes = 0.0 # kernel level resume end 717 tLow = 0.0 # time spent in low-level suspend (standby/freeze) 718 fwValid = False # is firmware data available 719 fwSuspend = 0 # time spent in firmware suspend 720 fwResume = 0 # time spent in firmware resume 721 dmesgtext = [] # dmesg text file in memory 722 pstl = 0 # process timeline 723 testnumber = 0 724 idstr = '' 725 html_device_id = 0 726 stamp = 0 727 outfile = '' 728 devpids = [] 729 kerror = False 730 def __init__(self, num): 731 idchar = 'abcdefghij' 732 self.pstl = dict() 733 self.testnumber = num 734 self.idstr = idchar[num] 735 self.dmesgtext = [] 736 self.phases = [] 737 self.dmesg = { # fixed list of 10 phases 738 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, 739 'row': 0, 'color': '#CCFFCC', 'order': 0}, 740 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, 741 'row': 0, 'color': '#88FF88', 'order': 1}, 742 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, 743 'row': 0, 'color': '#00AA00', 'order': 2}, 744 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 745 'row': 0, 'color': '#008888', 'order': 3}, 746 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 747 'row': 0, 'color': '#0000FF', 'order': 4}, 748 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 749 'row': 0, 'color': '#FF0000', 'order': 5}, 750 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 751 'row': 0, 'color': '#FF9900', 'order': 6}, 752 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0, 753 'row': 0, 'color': '#FFCC00', 'order': 7}, 754 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0, 755 'row': 0, 'color': '#FFFF88', 'order': 8}, 756 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0, 757 'row': 0, 'color': '#FFFFCC', 'order': 9} 758 } 759 self.phases = self.sortedPhases() 760 self.devicegroups = [] 761 for phase in self.phases: 762 self.devicegroups.append([phase]) 763 self.errorinfo = {'suspend':[],'resume':[]} 764 def extractErrorInfo(self, dmesg): 765 error = '' 766 tm = 0.0 767 for i in range(len(dmesg)): 768 if 'Call Trace:' in dmesg[i]: 769 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i]) 770 if not m: 771 continue 772 tm = float(m.group('ktime')) 773 if tm < self.start or tm > self.end: 774 continue 775 for j in range(i-10, i+1): 776 error += dmesg[j] 777 continue 778 if error: 779 m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i]) 780 if m: 781 error += dmesg[i] 782 else: 783 if tm < self.tSuspended: 784 dir = 'suspend' 785 else: 786 dir = 'resume' 787 error = error.replace('<', '&lt').replace('>', '&gt') 788 vprint('kernel error found in %s at %f' % (dir, tm)) 789 self.errorinfo[dir].append((tm, error)) 790 self.kerror = True 791 error = '' 792 def setStart(self, time): 793 self.start = time 794 def setEnd(self, time): 795 self.end = time 796 def isTraceEventOutsideDeviceCalls(self, pid, time): 797 for phase in self.phases: 798 list = self.dmesg[phase]['list'] 799 for dev in list: 800 d = list[dev] 801 if(d['pid'] == pid and time >= d['start'] and 802 time < d['end']): 803 return False 804 return True 805 def sourcePhase(self, start): 806 for phase in self.phases: 807 pend = self.dmesg[phase]['end'] 808 if start <= pend: 809 return phase 810 return 'resume_complete' 811 def sourceDevice(self, phaselist, start, end, pid, type): 812 tgtdev = '' 813 for phase in phaselist: 814 list = self.dmesg[phase]['list'] 815 for devname in list: 816 dev = list[devname] 817 # pid must match 818 if dev['pid'] != pid: 819 continue 820 devS = dev['start'] 821 devE = dev['end'] 822 if type == 'device': 823 # device target event is entirely inside the source boundary 824 if(start < devS or start >= devE or end <= devS or end > devE): 825 continue 826 elif type == 'thread': 827 # thread target event will expand the source boundary 828 if start < devS: 829 dev['start'] = start 830 if end > devE: 831 dev['end'] = end 832 tgtdev = dev 833 break 834 return tgtdev 835 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata): 836 # try to place the call in a device 837 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device') 838 # calls with device pids that occur outside device bounds are dropped 839 # TODO: include these somehow 840 if not tgtdev and pid in self.devpids: 841 return False 842 # try to place the call in a thread 843 if not tgtdev: 844 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread') 845 # create new thread blocks, expand as new calls are found 846 if not tgtdev: 847 if proc == '<...>': 848 threadname = 'kthread-%d' % (pid) 849 else: 850 threadname = '%s-%d' % (proc, pid) 851 tgtphase = self.sourcePhase(start) 852 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '') 853 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) 854 # this should not happen 855 if not tgtdev: 856 vprint('[%f - %f] %s-%d %s %s %s' % \ 857 (start, end, proc, pid, kprobename, cdata, rdata)) 858 return False 859 # place the call data inside the src element of the tgtdev 860 if('src' not in tgtdev): 861 tgtdev['src'] = [] 862 dtf = sysvals.dev_tracefuncs 863 ubiquitous = False 864 if kprobename in dtf and 'ub' in dtf[kprobename]: 865 ubiquitous = True 866 title = cdata+' '+rdata 867 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)' 868 m = re.match(mstr, title) 869 if m: 870 c = m.group('caller') 871 a = m.group('args').strip() 872 r = m.group('ret') 873 if len(r) > 6: 874 r = '' 875 else: 876 r = 'ret=%s ' % r 877 if ubiquitous and c in dtf and 'ub' in dtf[c]: 878 return False 879 color = sysvals.kprobeColor(kprobename) 880 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color) 881 tgtdev['src'].append(e) 882 return True 883 def overflowDevices(self): 884 # get a list of devices that extend beyond the end of this test run 885 devlist = [] 886 for phase in self.phases: 887 list = self.dmesg[phase]['list'] 888 for devname in list: 889 dev = list[devname] 890 if dev['end'] > self.end: 891 devlist.append(dev) 892 return devlist 893 def mergeOverlapDevices(self, devlist): 894 # merge any devices that overlap devlist 895 for dev in devlist: 896 devname = dev['name'] 897 for phase in self.phases: 898 list = self.dmesg[phase]['list'] 899 if devname not in list: 900 continue 901 tdev = list[devname] 902 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start']) 903 if o <= 0: 904 continue 905 dev['end'] = tdev['end'] 906 if 'src' not in dev or 'src' not in tdev: 907 continue 908 dev['src'] += tdev['src'] 909 del list[devname] 910 def usurpTouchingThread(self, name, dev): 911 # the caller test has priority of this thread, give it to him 912 for phase in self.phases: 913 list = self.dmesg[phase]['list'] 914 if name in list: 915 tdev = list[name] 916 if tdev['start'] - dev['end'] < 0.1: 917 dev['end'] = tdev['end'] 918 if 'src' not in dev: 919 dev['src'] = [] 920 if 'src' in tdev: 921 dev['src'] += tdev['src'] 922 del list[name] 923 break 924 def stitchTouchingThreads(self, testlist): 925 # merge any threads between tests that touch 926 for phase in self.phases: 927 list = self.dmesg[phase]['list'] 928 for devname in list: 929 dev = list[devname] 930 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']: 931 continue 932 for data in testlist: 933 data.usurpTouchingThread(devname, dev) 934 def optimizeDevSrc(self): 935 # merge any src call loops to reduce timeline size 936 for phase in self.phases: 937 list = self.dmesg[phase]['list'] 938 for dev in list: 939 if 'src' not in list[dev]: 940 continue 941 src = list[dev]['src'] 942 p = 0 943 for e in sorted(src, key=lambda event: event.time): 944 if not p or not e.repeat(p): 945 p = e 946 continue 947 # e is another iteration of p, move it into p 948 p.end = e.end 949 p.length = p.end - p.time 950 p.count += 1 951 src.remove(e) 952 def trimTimeVal(self, t, t0, dT, left): 953 if left: 954 if(t > t0): 955 if(t - dT < t0): 956 return t0 957 return t - dT 958 else: 959 return t 960 else: 961 if(t < t0 + dT): 962 if(t > t0): 963 return t0 + dT 964 return t + dT 965 else: 966 return t 967 def trimTime(self, t0, dT, left): 968 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left) 969 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left) 970 self.start = self.trimTimeVal(self.start, t0, dT, left) 971 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left) 972 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left) 973 self.end = self.trimTimeVal(self.end, t0, dT, left) 974 for phase in self.phases: 975 p = self.dmesg[phase] 976 p['start'] = self.trimTimeVal(p['start'], t0, dT, left) 977 p['end'] = self.trimTimeVal(p['end'], t0, dT, left) 978 list = p['list'] 979 for name in list: 980 d = list[name] 981 d['start'] = self.trimTimeVal(d['start'], t0, dT, left) 982 d['end'] = self.trimTimeVal(d['end'], t0, dT, left) 983 if('ftrace' in d): 984 cg = d['ftrace'] 985 cg.start = self.trimTimeVal(cg.start, t0, dT, left) 986 cg.end = self.trimTimeVal(cg.end, t0, dT, left) 987 for line in cg.list: 988 line.time = self.trimTimeVal(line.time, t0, dT, left) 989 if('src' in d): 990 for e in d['src']: 991 e.time = self.trimTimeVal(e.time, t0, dT, left) 992 def normalizeTime(self, tZero): 993 # trim out any standby or freeze clock time 994 if(self.tSuspended != self.tResumed): 995 if(self.tResumed > tZero): 996 self.trimTime(self.tSuspended, \ 997 self.tResumed-self.tSuspended, True) 998 else: 999 self.trimTime(self.tSuspended, \ 1000 self.tResumed-self.tSuspended, False) 1001 def setPhase(self, phase, ktime, isbegin): 1002 if(isbegin): 1003 self.dmesg[phase]['start'] = ktime 1004 else: 1005 self.dmesg[phase]['end'] = ktime 1006 def dmesgSortVal(self, phase): 1007 return self.dmesg[phase]['order'] 1008 def sortedPhases(self): 1009 return sorted(self.dmesg, key=self.dmesgSortVal) 1010 def sortedDevices(self, phase): 1011 list = self.dmesg[phase]['list'] 1012 slist = [] 1013 tmp = dict() 1014 for devname in list: 1015 dev = list[devname] 1016 tmp[dev['start']] = devname 1017 for t in sorted(tmp): 1018 slist.append(tmp[t]) 1019 return slist 1020 def fixupInitcalls(self, phase): 1021 # if any calls never returned, clip them at system resume end 1022 phaselist = self.dmesg[phase]['list'] 1023 for devname in phaselist: 1024 dev = phaselist[devname] 1025 if(dev['end'] < 0): 1026 for p in self.phases: 1027 if self.dmesg[p]['end'] > dev['start']: 1028 dev['end'] = self.dmesg[p]['end'] 1029 break 1030 vprint('%s (%s): callback didnt return' % (devname, phase)) 1031 def deviceFilter(self, devicefilter): 1032 for phase in self.phases: 1033 list = self.dmesg[phase]['list'] 1034 rmlist = [] 1035 for name in list: 1036 keep = False 1037 for filter in devicefilter: 1038 if filter in name or \ 1039 ('drv' in list[name] and filter in list[name]['drv']): 1040 keep = True 1041 if not keep: 1042 rmlist.append(name) 1043 for name in rmlist: 1044 del list[name] 1045 def fixupInitcallsThatDidntReturn(self): 1046 # if any calls never returned, clip them at system resume end 1047 for phase in self.phases: 1048 self.fixupInitcalls(phase) 1049 def phaseOverlap(self, phases): 1050 rmgroups = [] 1051 newgroup = [] 1052 for group in self.devicegroups: 1053 for phase in phases: 1054 if phase not in group: 1055 continue 1056 for p in group: 1057 if p not in newgroup: 1058 newgroup.append(p) 1059 if group not in rmgroups: 1060 rmgroups.append(group) 1061 for group in rmgroups: 1062 self.devicegroups.remove(group) 1063 self.devicegroups.append(newgroup) 1064 def newActionGlobal(self, name, start, end, pid=-1, color=''): 1065 # which phase is this device callback or action in 1066 targetphase = 'none' 1067 htmlclass = '' 1068 overlap = 0.0 1069 phases = [] 1070 for phase in self.phases: 1071 pstart = self.dmesg[phase]['start'] 1072 pend = self.dmesg[phase]['end'] 1073 # see if the action overlaps this phase 1074 o = max(0, min(end, pend) - max(start, pstart)) 1075 if o > 0: 1076 phases.append(phase) 1077 # set the target phase to the one that overlaps most 1078 if o > overlap: 1079 if overlap > 0 and phase == 'post_resume': 1080 continue 1081 targetphase = phase 1082 overlap = o 1083 # if no target phase was found, pin it to the edge 1084 if targetphase == 'none': 1085 p0start = self.dmesg[self.phases[0]]['start'] 1086 if start <= p0start: 1087 targetphase = self.phases[0] 1088 else: 1089 targetphase = self.phases[-1] 1090 if pid == -2: 1091 htmlclass = ' bg' 1092 elif pid == -3: 1093 htmlclass = ' ps' 1094 if len(phases) > 1: 1095 htmlclass = ' bg' 1096 self.phaseOverlap(phases) 1097 if targetphase in self.phases: 1098 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color) 1099 return (targetphase, newname) 1100 return False 1101 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''): 1102 # new device callback for a specific phase 1103 self.html_device_id += 1 1104 devid = '%s%d' % (self.idstr, self.html_device_id) 1105 list = self.dmesg[phase]['list'] 1106 length = -1.0 1107 if(start >= 0 and end >= 0): 1108 length = end - start 1109 if pid == -2: 1110 i = 2 1111 origname = name 1112 while(name in list): 1113 name = '%s[%d]' % (origname, i) 1114 i += 1 1115 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid, 1116 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv } 1117 if htmlclass: 1118 list[name]['htmlclass'] = htmlclass 1119 if color: 1120 list[name]['color'] = color 1121 return name 1122 def deviceChildren(self, devname, phase): 1123 devlist = [] 1124 list = self.dmesg[phase]['list'] 1125 for child in list: 1126 if(list[child]['par'] == devname): 1127 devlist.append(child) 1128 return devlist 1129 def printDetails(self): 1130 vprint('Timeline Details:') 1131 vprint(' test start: %f' % self.start) 1132 vprint('kernel suspend start: %f' % self.tKernSus) 1133 for phase in self.phases: 1134 dc = len(self.dmesg[phase]['list']) 1135 vprint(' %16s: %f - %f (%d devices)' % (phase, \ 1136 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) 1137 vprint(' kernel resume end: %f' % self.tKernRes) 1138 vprint(' test end: %f' % self.end) 1139 def deviceChildrenAllPhases(self, devname): 1140 devlist = [] 1141 for phase in self.phases: 1142 list = self.deviceChildren(devname, phase) 1143 for dev in list: 1144 if dev not in devlist: 1145 devlist.append(dev) 1146 return devlist 1147 def masterTopology(self, name, list, depth): 1148 node = DeviceNode(name, depth) 1149 for cname in list: 1150 # avoid recursions 1151 if name == cname: 1152 continue 1153 clist = self.deviceChildrenAllPhases(cname) 1154 cnode = self.masterTopology(cname, clist, depth+1) 1155 node.children.append(cnode) 1156 return node 1157 def printTopology(self, node): 1158 html = '' 1159 if node.name: 1160 info = '' 1161 drv = '' 1162 for phase in self.phases: 1163 list = self.dmesg[phase]['list'] 1164 if node.name in list: 1165 s = list[node.name]['start'] 1166 e = list[node.name]['end'] 1167 if list[node.name]['drv']: 1168 drv = ' {'+list[node.name]['drv']+'}' 1169 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000)) 1170 html += '<li><b>'+node.name+drv+'</b>' 1171 if info: 1172 html += '<ul>'+info+'</ul>' 1173 html += '</li>' 1174 if len(node.children) > 0: 1175 html += '<ul>' 1176 for cnode in node.children: 1177 html += self.printTopology(cnode) 1178 html += '</ul>' 1179 return html 1180 def rootDeviceList(self): 1181 # list of devices graphed 1182 real = [] 1183 for phase in self.dmesg: 1184 list = self.dmesg[phase]['list'] 1185 for dev in list: 1186 if list[dev]['pid'] >= 0 and dev not in real: 1187 real.append(dev) 1188 # list of top-most root devices 1189 rootlist = [] 1190 for phase in self.dmesg: 1191 list = self.dmesg[phase]['list'] 1192 for dev in list: 1193 pdev = list[dev]['par'] 1194 pid = list[dev]['pid'] 1195 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)): 1196 continue 1197 if pdev and pdev not in real and pdev not in rootlist: 1198 rootlist.append(pdev) 1199 return rootlist 1200 def deviceTopology(self): 1201 rootlist = self.rootDeviceList() 1202 master = self.masterTopology('', rootlist, 0) 1203 return self.printTopology(master) 1204 def selectTimelineDevices(self, widfmt, tTotal, mindevlen): 1205 # only select devices that will actually show up in html 1206 self.tdevlist = dict() 1207 for phase in self.dmesg: 1208 devlist = [] 1209 list = self.dmesg[phase]['list'] 1210 for dev in list: 1211 length = (list[dev]['end'] - list[dev]['start']) * 1000 1212 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal) 1213 if width != '0.000000' and length >= mindevlen: 1214 devlist.append(dev) 1215 self.tdevlist[phase] = devlist 1216 def addHorizontalDivider(self, devname, devend): 1217 phase = 'suspend_prepare' 1218 self.newAction(phase, devname, -2, '', \ 1219 self.start, devend, '', ' sec', '') 1220 if phase not in self.tdevlist: 1221 self.tdevlist[phase] = [] 1222 self.tdevlist[phase].append(devname) 1223 d = DevItem(0, phase, self.dmesg[phase]['list'][devname]) 1224 return d 1225 def addProcessUsageEvent(self, name, times): 1226 # get the start and end times for this process 1227 maxC = 0 1228 tlast = 0 1229 start = -1 1230 end = -1 1231 for t in sorted(times): 1232 if tlast == 0: 1233 tlast = t 1234 continue 1235 if name in self.pstl[t]: 1236 if start == -1 or tlast < start: 1237 start = tlast 1238 if end == -1 or t > end: 1239 end = t 1240 tlast = t 1241 if start == -1 or end == -1: 1242 return 0 1243 # add a new action for this process and get the object 1244 out = self.newActionGlobal(name, start, end, -3) 1245 if not out: 1246 return 0 1247 phase, devname = out 1248 dev = self.dmesg[phase]['list'][devname] 1249 # get the cpu exec data 1250 tlast = 0 1251 clast = 0 1252 cpuexec = dict() 1253 for t in sorted(times): 1254 if tlast == 0 or t <= start or t > end: 1255 tlast = t 1256 continue 1257 list = self.pstl[t] 1258 c = 0 1259 if name in list: 1260 c = list[name] 1261 if c > maxC: 1262 maxC = c 1263 if c != clast: 1264 key = (tlast, t) 1265 cpuexec[key] = c 1266 tlast = t 1267 clast = c 1268 dev['cpuexec'] = cpuexec 1269 return maxC 1270 def createProcessUsageEvents(self): 1271 # get an array of process names 1272 proclist = [] 1273 for t in self.pstl: 1274 pslist = self.pstl[t] 1275 for ps in pslist: 1276 if ps not in proclist: 1277 proclist.append(ps) 1278 # get a list of data points for suspend and resume 1279 tsus = [] 1280 tres = [] 1281 for t in sorted(self.pstl): 1282 if t < self.tSuspended: 1283 tsus.append(t) 1284 else: 1285 tres.append(t) 1286 # process the events for suspend and resume 1287 if len(proclist) > 0: 1288 vprint('Process Execution:') 1289 for ps in proclist: 1290 c = self.addProcessUsageEvent(ps, tsus) 1291 if c > 0: 1292 vprint('%25s (sus): %d' % (ps, c)) 1293 c = self.addProcessUsageEvent(ps, tres) 1294 if c > 0: 1295 vprint('%25s (res): %d' % (ps, c)) 1296 1297# Class: DevFunction 1298# Description: 1299# A container for kprobe function data we want in the dev timeline 1300class DevFunction: 1301 row = 0 1302 count = 1 1303 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color): 1304 self.name = name 1305 self.args = args 1306 self.caller = caller 1307 self.ret = ret 1308 self.time = start 1309 self.length = end - start 1310 self.end = end 1311 self.ubiquitous = u 1312 self.proc = proc 1313 self.pid = pid 1314 self.color = color 1315 def title(self): 1316 cnt = '' 1317 if self.count > 1: 1318 cnt = '(x%d)' % self.count 1319 l = '%0.3fms' % (self.length * 1000) 1320 if self.ubiquitous: 1321 title = '%s(%s)%s <- %s, %s(%s)' % \ 1322 (self.name, self.args, cnt, self.caller, self.ret, l) 1323 else: 1324 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l) 1325 return title.replace('"', '') 1326 def text(self): 1327 if self.count > 1: 1328 text = '%s(x%d)' % (self.name, self.count) 1329 else: 1330 text = self.name 1331 return text 1332 def repeat(self, tgt): 1333 # is the tgt call just a repeat of this call (e.g. are we in a loop) 1334 dt = self.time - tgt.end 1335 # only combine calls if -all- attributes are identical 1336 if tgt.caller == self.caller and \ 1337 tgt.name == self.name and tgt.args == self.args and \ 1338 tgt.proc == self.proc and tgt.pid == self.pid and \ 1339 tgt.ret == self.ret and dt >= 0 and \ 1340 dt <= sysvals.callloopmaxgap and \ 1341 self.length < sysvals.callloopmaxlen: 1342 return True 1343 return False 1344 1345# Class: FTraceLine 1346# Description: 1347# A container for a single line of ftrace data. There are six basic types: 1348# callgraph line: 1349# call: " dpm_run_callback() {" 1350# return: " }" 1351# leaf: " dpm_run_callback();" 1352# trace event: 1353# tracing_mark_write: SUSPEND START or RESUME COMPLETE 1354# suspend_resume: phase or custom exec block data 1355# device_pm_callback: device callback info 1356class FTraceLine: 1357 time = 0.0 1358 length = 0.0 1359 fcall = False 1360 freturn = False 1361 fevent = False 1362 fkprobe = False 1363 depth = 0 1364 name = '' 1365 type = '' 1366 def __init__(self, t, m='', d=''): 1367 self.time = float(t) 1368 if not m and not d: 1369 return 1370 # is this a trace event 1371 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)): 1372 if(d == 'traceevent'): 1373 # nop format trace event 1374 msg = m 1375 else: 1376 # function_graph format trace event 1377 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m) 1378 msg = em.group('msg') 1379 1380 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg) 1381 if(emm): 1382 self.name = emm.group('msg') 1383 self.type = emm.group('call') 1384 else: 1385 self.name = msg 1386 km = re.match('^(?P<n>.*)_cal$', self.type) 1387 if km: 1388 self.fcall = True 1389 self.fkprobe = True 1390 self.type = km.group('n') 1391 return 1392 km = re.match('^(?P<n>.*)_ret$', self.type) 1393 if km: 1394 self.freturn = True 1395 self.fkprobe = True 1396 self.type = km.group('n') 1397 return 1398 self.fevent = True 1399 return 1400 # convert the duration to seconds 1401 if(d): 1402 self.length = float(d)/1000000 1403 # the indentation determines the depth 1404 match = re.match('^(?P<d> *)(?P<o>.*)$', m) 1405 if(not match): 1406 return 1407 self.depth = self.getDepth(match.group('d')) 1408 m = match.group('o') 1409 # function return 1410 if(m[0] == '}'): 1411 self.freturn = True 1412 if(len(m) > 1): 1413 # includes comment with function name 1414 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m) 1415 if(match): 1416 self.name = match.group('n').strip() 1417 # function call 1418 else: 1419 self.fcall = True 1420 # function call with children 1421 if(m[-1] == '{'): 1422 match = re.match('^(?P<n>.*) *\(.*', m) 1423 if(match): 1424 self.name = match.group('n').strip() 1425 # function call with no children (leaf) 1426 elif(m[-1] == ';'): 1427 self.freturn = True 1428 match = re.match('^(?P<n>.*) *\(.*', m) 1429 if(match): 1430 self.name = match.group('n').strip() 1431 # something else (possibly a trace marker) 1432 else: 1433 self.name = m 1434 def getDepth(self, str): 1435 return len(str)/2 1436 def debugPrint(self, dev=''): 1437 if(self.freturn and self.fcall): 1438 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ 1439 self.depth, self.name, self.length*1000000)) 1440 elif(self.freturn): 1441 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ 1442 self.depth, self.name, self.length*1000000)) 1443 else: 1444 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ 1445 self.depth, self.name, self.length*1000000)) 1446 def startMarker(self): 1447 # Is this the starting line of a suspend? 1448 if not self.fevent: 1449 return False 1450 if sysvals.usetracemarkers: 1451 if(self.name == 'SUSPEND START'): 1452 return True 1453 return False 1454 else: 1455 if(self.type == 'suspend_resume' and 1456 re.match('suspend_enter\[.*\] begin', self.name)): 1457 return True 1458 return False 1459 def endMarker(self): 1460 # Is this the ending line of a resume? 1461 if not self.fevent: 1462 return False 1463 if sysvals.usetracemarkers: 1464 if(self.name == 'RESUME COMPLETE'): 1465 return True 1466 return False 1467 else: 1468 if(self.type == 'suspend_resume' and 1469 re.match('thaw_processes\[.*\] end', self.name)): 1470 return True 1471 return False 1472 1473# Class: FTraceCallGraph 1474# Description: 1475# A container for the ftrace callgraph of a single recursive function. 1476# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph 1477# Each instance is tied to a single device in a single phase, and is 1478# comprised of an ordered list of FTraceLine objects 1479class FTraceCallGraph: 1480 start = -1.0 1481 end = -1.0 1482 list = [] 1483 invalid = False 1484 depth = 0 1485 pid = 0 1486 def __init__(self, pid): 1487 self.start = -1.0 1488 self.end = -1.0 1489 self.list = [] 1490 self.depth = 0 1491 self.pid = pid 1492 def addLine(self, line, debug=False): 1493 # if this is already invalid, just leave 1494 if(self.invalid): 1495 return False 1496 # invalidate on too much data or bad depth 1497 if(len(self.list) >= 1000000 or self.depth < 0): 1498 self.invalidate(line) 1499 return False 1500 # compare current depth with this lines pre-call depth 1501 prelinedep = line.depth 1502 if(line.freturn and not line.fcall): 1503 prelinedep += 1 1504 last = 0 1505 lasttime = line.time 1506 virtualfname = 'execution_misalignment' 1507 if len(self.list) > 0: 1508 last = self.list[-1] 1509 lasttime = last.time 1510 # handle low misalignments by inserting returns 1511 if prelinedep < self.depth: 1512 if debug and last: 1513 print '-------- task %d --------' % self.pid 1514 last.debugPrint() 1515 idx = 0 1516 # add return calls to get the depth down 1517 while prelinedep < self.depth: 1518 if debug: 1519 print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep) 1520 self.depth -= 1 1521 if idx == 0 and last and last.fcall and not last.freturn: 1522 # special case, turn last call into a leaf 1523 last.depth = self.depth 1524 last.freturn = True 1525 last.length = line.time - last.time 1526 if debug: 1527 last.debugPrint() 1528 else: 1529 vline = FTraceLine(lasttime) 1530 vline.depth = self.depth 1531 vline.name = virtualfname 1532 vline.freturn = True 1533 self.list.append(vline) 1534 if debug: 1535 vline.debugPrint() 1536 idx += 1 1537 if debug: 1538 line.debugPrint() 1539 print '' 1540 # handle high misalignments by inserting calls 1541 elif prelinedep > self.depth: 1542 if debug and last: 1543 print '-------- task %d --------' % self.pid 1544 last.debugPrint() 1545 idx = 0 1546 # add calls to get the depth up 1547 while prelinedep > self.depth: 1548 if debug: 1549 print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep) 1550 if idx == 0 and line.freturn and not line.fcall: 1551 # special case, turn this return into a leaf 1552 line.fcall = True 1553 prelinedep -= 1 1554 else: 1555 vline = FTraceLine(lasttime) 1556 vline.depth = self.depth 1557 vline.name = virtualfname 1558 vline.fcall = True 1559 if debug: 1560 vline.debugPrint() 1561 self.list.append(vline) 1562 self.depth += 1 1563 if not last: 1564 self.start = vline.time 1565 idx += 1 1566 if debug: 1567 line.debugPrint() 1568 print '' 1569 # process the call and set the new depth 1570 if(line.fcall and not line.freturn): 1571 self.depth += 1 1572 elif(line.freturn and not line.fcall): 1573 self.depth -= 1 1574 if len(self.list) < 1: 1575 self.start = line.time 1576 self.list.append(line) 1577 if(line.depth == 0 and line.freturn): 1578 if(self.start < 0): 1579 self.start = line.time 1580 self.end = line.time 1581 if line.fcall: 1582 self.end += line.length 1583 if self.list[0].name == virtualfname: 1584 self.invalid = True 1585 return True 1586 return False 1587 def invalidate(self, line): 1588 if(len(self.list) > 0): 1589 first = self.list[0] 1590 self.list = [] 1591 self.list.append(first) 1592 self.invalid = True 1593 id = 'task %s' % (self.pid) 1594 window = '(%f - %f)' % (self.start, line.time) 1595 if(self.depth < 0): 1596 vprint('Too much data for '+id+\ 1597 ' (buffer overflow), ignoring this callback') 1598 else: 1599 vprint('Too much data for '+id+\ 1600 ' '+window+', ignoring this callback') 1601 def slice(self, t0, tN): 1602 minicg = FTraceCallGraph(0) 1603 count = -1 1604 firstdepth = 0 1605 for l in self.list: 1606 if(l.time < t0 or l.time > tN): 1607 continue 1608 if(count < 0): 1609 if(not l.fcall or l.name == 'dev_driver_string'): 1610 continue 1611 firstdepth = l.depth 1612 count = 0 1613 l.depth -= firstdepth 1614 minicg.addLine(l) 1615 if((count == 0 and l.freturn and l.fcall) or 1616 (count > 0 and l.depth <= 0)): 1617 break 1618 count += 1 1619 return minicg 1620 def repair(self, enddepth): 1621 # bring the depth back to 0 with additional returns 1622 fixed = False 1623 last = self.list[-1] 1624 for i in reversed(range(enddepth)): 1625 t = FTraceLine(last.time) 1626 t.depth = i 1627 t.freturn = True 1628 fixed = self.addLine(t) 1629 if fixed: 1630 self.end = last.time 1631 return True 1632 return False 1633 def postProcess(self, debug=False): 1634 stack = dict() 1635 cnt = 0 1636 for l in self.list: 1637 if(l.fcall and not l.freturn): 1638 stack[l.depth] = l 1639 cnt += 1 1640 elif(l.freturn and not l.fcall): 1641 if(l.depth not in stack): 1642 if debug: 1643 print 'Post Process Error: Depth missing' 1644 l.debugPrint() 1645 return False 1646 # transfer total time from return line to call line 1647 stack[l.depth].length = l.length 1648 stack.pop(l.depth) 1649 l.length = 0 1650 cnt -= 1 1651 if(cnt == 0): 1652 # trace caught the whole call tree 1653 return True 1654 elif(cnt < 0): 1655 if debug: 1656 print 'Post Process Error: Depth is less than 0' 1657 return False 1658 # trace ended before call tree finished 1659 return self.repair(cnt) 1660 def deviceMatch(self, pid, data): 1661 found = False 1662 # add the callgraph data to the device hierarchy 1663 borderphase = { 1664 'dpm_prepare': 'suspend_prepare', 1665 'dpm_complete': 'resume_complete' 1666 } 1667 if(self.list[0].name in borderphase): 1668 p = borderphase[self.list[0].name] 1669 list = data.dmesg[p]['list'] 1670 for devname in list: 1671 dev = list[devname] 1672 if(pid == dev['pid'] and 1673 self.start <= dev['start'] and 1674 self.end >= dev['end']): 1675 dev['ftrace'] = self.slice(dev['start'], dev['end']) 1676 found = True 1677 return found 1678 for p in data.phases: 1679 if(data.dmesg[p]['start'] <= self.start and 1680 self.start <= data.dmesg[p]['end']): 1681 list = data.dmesg[p]['list'] 1682 for devname in list: 1683 dev = list[devname] 1684 if(pid == dev['pid'] and 1685 self.start <= dev['start'] and 1686 self.end >= dev['end']): 1687 dev['ftrace'] = self 1688 found = True 1689 break 1690 break 1691 return found 1692 def newActionFromFunction(self, data): 1693 name = self.list[0].name 1694 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']: 1695 return 1696 fs = self.start 1697 fe = self.end 1698 if fs < data.start or fe > data.end: 1699 return 1700 phase = '' 1701 for p in data.phases: 1702 if(data.dmesg[p]['start'] <= self.start and 1703 self.start < data.dmesg[p]['end']): 1704 phase = p 1705 break 1706 if not phase: 1707 return 1708 out = data.newActionGlobal(name, fs, fe, -2) 1709 if out: 1710 phase, myname = out 1711 data.dmesg[phase]['list'][myname]['ftrace'] = self 1712 def debugPrint(self): 1713 print('[%f - %f] %s (%d)') % (self.start, self.end, self.list[0].name, self.pid) 1714 for l in self.list: 1715 if(l.freturn and l.fcall): 1716 print('%f (%02d): %s(); (%.3f us)' % (l.time, \ 1717 l.depth, l.name, l.length*1000000)) 1718 elif(l.freturn): 1719 print('%f (%02d): %s} (%.3f us)' % (l.time, \ 1720 l.depth, l.name, l.length*1000000)) 1721 else: 1722 print('%f (%02d): %s() { (%.3f us)' % (l.time, \ 1723 l.depth, l.name, l.length*1000000)) 1724 print(' ') 1725 1726class DevItem: 1727 def __init__(self, test, phase, dev): 1728 self.test = test 1729 self.phase = phase 1730 self.dev = dev 1731 def isa(self, cls): 1732 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']: 1733 return True 1734 return False 1735 1736# Class: Timeline 1737# Description: 1738# A container for a device timeline which calculates 1739# all the html properties to display it correctly 1740class Timeline: 1741 html = {} 1742 height = 0 # total timeline height 1743 scaleH = 20 # timescale (top) row height 1744 rowH = 30 # device row height 1745 bodyH = 0 # body height 1746 rows = 0 # total timeline rows 1747 rowlines = dict() 1748 rowheight = dict() 1749 def __init__(self, rowheight, scaleheight): 1750 self.rowH = rowheight 1751 self.scaleH = scaleheight 1752 self.html = { 1753 'header': '', 1754 'timeline': '', 1755 'legend': '', 1756 } 1757 # Function: getDeviceRows 1758 # Description: 1759 # determine how may rows the device funcs will take 1760 # Arguments: 1761 # rawlist: the list of devices/actions for a single phase 1762 # Output: 1763 # The total number of rows needed to display this phase of the timeline 1764 def getDeviceRows(self, rawlist): 1765 # clear all rows and set them to undefined 1766 sortdict = dict() 1767 for item in rawlist: 1768 item.row = -1 1769 sortdict[item] = item.length 1770 sortlist = sorted(sortdict, key=sortdict.get, reverse=True) 1771 remaining = len(sortlist) 1772 rowdata = dict() 1773 row = 1 1774 # try to pack each row with as many ranges as possible 1775 while(remaining > 0): 1776 if(row not in rowdata): 1777 rowdata[row] = [] 1778 for i in sortlist: 1779 if(i.row >= 0): 1780 continue 1781 s = i.time 1782 e = i.time + i.length 1783 valid = True 1784 for ritem in rowdata[row]: 1785 rs = ritem.time 1786 re = ritem.time + ritem.length 1787 if(not (((s <= rs) and (e <= rs)) or 1788 ((s >= re) and (e >= re)))): 1789 valid = False 1790 break 1791 if(valid): 1792 rowdata[row].append(i) 1793 i.row = row 1794 remaining -= 1 1795 row += 1 1796 return row 1797 # Function: getPhaseRows 1798 # Description: 1799 # Organize the timeline entries into the smallest 1800 # number of rows possible, with no entry overlapping 1801 # Arguments: 1802 # devlist: the list of devices/actions in a group of contiguous phases 1803 # Output: 1804 # The total number of rows needed to display this phase of the timeline 1805 def getPhaseRows(self, devlist, row=0): 1806 # clear all rows and set them to undefined 1807 remaining = len(devlist) 1808 rowdata = dict() 1809 sortdict = dict() 1810 myphases = [] 1811 # initialize all device rows to -1 and calculate devrows 1812 for item in devlist: 1813 dev = item.dev 1814 tp = (item.test, item.phase) 1815 if tp not in myphases: 1816 myphases.append(tp) 1817 dev['row'] = -1 1818 # sort by length 1st, then name 2nd 1819 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name']) 1820 if 'src' in dev: 1821 dev['devrows'] = self.getDeviceRows(dev['src']) 1822 # sort the devlist by length so that large items graph on top 1823 sortlist = sorted(sortdict, key=sortdict.get, reverse=True) 1824 orderedlist = [] 1825 for item in sortlist: 1826 if item.dev['pid'] == -2: 1827 orderedlist.append(item) 1828 for item in sortlist: 1829 if item not in orderedlist: 1830 orderedlist.append(item) 1831 # try to pack each row with as many devices as possible 1832 while(remaining > 0): 1833 rowheight = 1 1834 if(row not in rowdata): 1835 rowdata[row] = [] 1836 for item in orderedlist: 1837 dev = item.dev 1838 if(dev['row'] < 0): 1839 s = dev['start'] 1840 e = dev['end'] 1841 valid = True 1842 for ritem in rowdata[row]: 1843 rs = ritem.dev['start'] 1844 re = ritem.dev['end'] 1845 if(not (((s <= rs) and (e <= rs)) or 1846 ((s >= re) and (e >= re)))): 1847 valid = False 1848 break 1849 if(valid): 1850 rowdata[row].append(item) 1851 dev['row'] = row 1852 remaining -= 1 1853 if 'devrows' in dev and dev['devrows'] > rowheight: 1854 rowheight = dev['devrows'] 1855 for t, p in myphases: 1856 if t not in self.rowlines or t not in self.rowheight: 1857 self.rowlines[t] = dict() 1858 self.rowheight[t] = dict() 1859 if p not in self.rowlines[t] or p not in self.rowheight[t]: 1860 self.rowlines[t][p] = dict() 1861 self.rowheight[t][p] = dict() 1862 rh = self.rowH 1863 # section headers should use a different row height 1864 if len(rowdata[row]) == 1 and \ 1865 'htmlclass' in rowdata[row][0].dev and \ 1866 'sec' in rowdata[row][0].dev['htmlclass']: 1867 rh = 15 1868 self.rowlines[t][p][row] = rowheight 1869 self.rowheight[t][p][row] = rowheight * rh 1870 row += 1 1871 if(row > self.rows): 1872 self.rows = int(row) 1873 return row 1874 def phaseRowHeight(self, test, phase, row): 1875 return self.rowheight[test][phase][row] 1876 def phaseRowTop(self, test, phase, row): 1877 top = 0 1878 for i in sorted(self.rowheight[test][phase]): 1879 if i >= row: 1880 break 1881 top += self.rowheight[test][phase][i] 1882 return top 1883 # Function: calcTotalRows 1884 # Description: 1885 # Calculate the heights and offsets for the header and rows 1886 def calcTotalRows(self): 1887 maxrows = 0 1888 standardphases = [] 1889 for t in self.rowlines: 1890 for p in self.rowlines[t]: 1891 total = 0 1892 for i in sorted(self.rowlines[t][p]): 1893 total += self.rowlines[t][p][i] 1894 if total > maxrows: 1895 maxrows = total 1896 if total == len(self.rowlines[t][p]): 1897 standardphases.append((t, p)) 1898 self.height = self.scaleH + (maxrows*self.rowH) 1899 self.bodyH = self.height - self.scaleH 1900 # if there is 1 line per row, draw them the standard way 1901 for t, p in standardphases: 1902 for i in sorted(self.rowheight[t][p]): 1903 self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p]) 1904 # Function: createTimeScale 1905 # Description: 1906 # Create the timescale for a timeline block 1907 # Arguments: 1908 # m0: start time (mode begin) 1909 # mMax: end time (mode end) 1910 # tTotal: total timeline time 1911 # mode: suspend or resume 1912 # Output: 1913 # The html code needed to display the time scale 1914 def createTimeScale(self, m0, mMax, tTotal, mode): 1915 timescale = '<div class="t" style="right:{0}%">{1}</div>\n' 1916 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n' 1917 output = '<div class="timescale">\n' 1918 # set scale for timeline 1919 mTotal = mMax - m0 1920 tS = 0.1 1921 if(tTotal <= 0): 1922 return output+'</div>\n' 1923 if(tTotal > 4): 1924 tS = 1 1925 divTotal = int(mTotal/tS) + 1 1926 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal 1927 for i in range(divTotal): 1928 htmlline = '' 1929 if(mode == 'resume'): 1930 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal)) 1931 val = '%0.fms' % (float(i)*tS*1000) 1932 htmlline = timescale.format(pos, val) 1933 if(i == 0): 1934 htmlline = rline 1935 else: 1936 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge) 1937 val = '%0.fms' % (float(i-divTotal+1)*tS*1000) 1938 if(i == divTotal - 1): 1939 val = 'Suspend' 1940 htmlline = timescale.format(pos, val) 1941 output += htmlline 1942 output += '</div>\n' 1943 return output 1944 1945# Class: TestProps 1946# Description: 1947# A list of values describing the properties of these test runs 1948class TestProps: 1949 stamp = '' 1950 S0i3 = False 1951 fwdata = [] 1952 ftrace_line_fmt_fg = \ 1953 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ 1954 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ 1955 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)' 1956 ftrace_line_fmt_nop = \ 1957 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ 1958 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ 1959 '(?P<msg>.*)' 1960 ftrace_line_fmt = ftrace_line_fmt_nop 1961 cgformat = False 1962 data = 0 1963 ktemp = dict() 1964 def __init__(self): 1965 self.ktemp = dict() 1966 def setTracerType(self, tracer): 1967 if(tracer == 'function_graph'): 1968 self.cgformat = True 1969 self.ftrace_line_fmt = self.ftrace_line_fmt_fg 1970 elif(tracer == 'nop'): 1971 self.ftrace_line_fmt = self.ftrace_line_fmt_nop 1972 else: 1973 doError('Invalid tracer format: [%s]' % tracer) 1974 1975# Class: TestRun 1976# Description: 1977# A container for a suspend/resume test run. This is necessary as 1978# there could be more than one, and they need to be separate. 1979class TestRun: 1980 ftemp = dict() 1981 ttemp = dict() 1982 data = 0 1983 def __init__(self, dataobj): 1984 self.data = dataobj 1985 self.ftemp = dict() 1986 self.ttemp = dict() 1987 1988class ProcessMonitor: 1989 proclist = dict() 1990 running = False 1991 def procstat(self): 1992 c = ['cat /proc/[1-9]*/stat 2>/dev/null'] 1993 process = Popen(c, shell=True, stdout=PIPE) 1994 running = dict() 1995 for line in process.stdout: 1996 data = line.split() 1997 pid = data[0] 1998 name = re.sub('[()]', '', data[1]) 1999 user = int(data[13]) 2000 kern = int(data[14]) 2001 kjiff = ujiff = 0 2002 if pid not in self.proclist: 2003 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern} 2004 else: 2005 val = self.proclist[pid] 2006 ujiff = user - val['user'] 2007 kjiff = kern - val['kern'] 2008 val['user'] = user 2009 val['kern'] = kern 2010 if ujiff > 0 or kjiff > 0: 2011 running[pid] = ujiff + kjiff 2012 result = process.wait() 2013 out = '' 2014 for pid in running: 2015 jiffies = running[pid] 2016 val = self.proclist[pid] 2017 if out: 2018 out += ',' 2019 out += '%s-%s %d' % (val['name'], pid, jiffies) 2020 return 'ps - '+out 2021 def processMonitor(self, tid): 2022 while self.running: 2023 out = self.procstat() 2024 if out: 2025 sysvals.fsetVal(out, 'trace_marker') 2026 def start(self): 2027 self.thread = Thread(target=self.processMonitor, args=(0,)) 2028 self.running = True 2029 self.thread.start() 2030 def stop(self): 2031 self.running = False 2032 2033# ----------------- FUNCTIONS -------------------- 2034 2035# Function: vprint 2036# Description: 2037# verbose print (prints only with -verbose option) 2038# Arguments: 2039# msg: the debug/log message to print 2040def vprint(msg): 2041 sysvals.logmsg += msg+'\n' 2042 if(sysvals.verbose): 2043 print(msg) 2044 2045# Function: parseStamp 2046# Description: 2047# Pull in the stamp comment line from the data file(s), 2048# create the stamp, and add it to the global sysvals object 2049# Arguments: 2050# m: the valid re.match output for the stamp line 2051def parseStamp(line, data): 2052 m = re.match(sysvals.stampfmt, line) 2053 data.stamp = {'time': '', 'host': '', 'mode': ''} 2054 dt = datetime(int(m.group('y'))+2000, int(m.group('m')), 2055 int(m.group('d')), int(m.group('H')), int(m.group('M')), 2056 int(m.group('S'))) 2057 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p') 2058 data.stamp['host'] = m.group('host') 2059 data.stamp['mode'] = m.group('mode') 2060 data.stamp['kernel'] = m.group('kernel') 2061 sysvals.hostname = data.stamp['host'] 2062 sysvals.suspendmode = data.stamp['mode'] 2063 if sysvals.suspendmode == 'command' and sysvals.ftracefile != '': 2064 modes = ['on', 'freeze', 'standby', 'mem'] 2065 out = Popen(['grep', 'suspend_enter', sysvals.ftracefile], 2066 stderr=PIPE, stdout=PIPE).stdout.read() 2067 m = re.match('.* suspend_enter\[(?P<mode>.*)\]', out) 2068 if m and m.group('mode') in ['1', '2', '3']: 2069 sysvals.suspendmode = modes[int(m.group('mode'))] 2070 data.stamp['mode'] = sysvals.suspendmode 2071 if not sysvals.stamp: 2072 sysvals.stamp = data.stamp 2073 2074# Function: diffStamp 2075# Description: 2076# compare the host, kernel, and mode fields in 3 stamps 2077# Arguments: 2078# stamp1: string array with mode, kernel, and host 2079# stamp2: string array with mode, kernel, and host 2080# Return: 2081# True if stamps differ, False if they're the same 2082def diffStamp(stamp1, stamp2): 2083 if 'host' in stamp1 and 'host' in stamp2: 2084 if stamp1['host'] != stamp2['host']: 2085 return True 2086 if 'kernel' in stamp1 and 'kernel' in stamp2: 2087 if stamp1['kernel'] != stamp2['kernel']: 2088 return True 2089 if 'mode' in stamp1 and 'mode' in stamp2: 2090 if stamp1['mode'] != stamp2['mode']: 2091 return True 2092 return False 2093 2094# Function: doesTraceLogHaveTraceEvents 2095# Description: 2096# Quickly determine if the ftrace log has some or all of the trace events 2097# required for primary parsing. Set the usetraceevents and/or 2098# usetraceeventsonly flags in the global sysvals object 2099def doesTraceLogHaveTraceEvents(): 2100 # check for kprobes 2101 sysvals.usekprobes = False 2102 out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True) 2103 if(out == 0): 2104 sysvals.usekprobes = True 2105 # check for callgraph data on trace event blocks 2106 out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True) 2107 if(out == 0): 2108 sysvals.usekprobes = True 2109 out = Popen(['head', '-1', sysvals.ftracefile], 2110 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') 2111 m = re.match(sysvals.stampfmt, out) 2112 if m and m.group('mode') == 'command': 2113 sysvals.usetraceeventsonly = True 2114 sysvals.usetraceevents = True 2115 return 2116 # figure out what level of trace events are supported 2117 sysvals.usetraceeventsonly = True 2118 sysvals.usetraceevents = False 2119 for e in sysvals.traceevents: 2120 out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True) 2121 if(out != 0): 2122 sysvals.usetraceeventsonly = False 2123 if(e == 'suspend_resume' and out == 0): 2124 sysvals.usetraceevents = True 2125 # determine is this log is properly formatted 2126 for e in ['SUSPEND START', 'RESUME COMPLETE']: 2127 out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True) 2128 if(out != 0): 2129 sysvals.usetracemarkers = False 2130 2131# Function: appendIncompleteTraceLog 2132# Description: 2133# [deprecated for kernel 3.15 or newer] 2134# Legacy support of ftrace outputs that lack the device_pm_callback 2135# and/or suspend_resume trace events. The primary data should be 2136# taken from dmesg, and this ftrace is used only for callgraph data 2137# or custom actions in the timeline. The data is appended to the Data 2138# objects provided. 2139# Arguments: 2140# testruns: the array of Data objects obtained from parseKernelLog 2141def appendIncompleteTraceLog(testruns): 2142 # create TestRun vessels for ftrace parsing 2143 testcnt = len(testruns) 2144 testidx = 0 2145 testrun = [] 2146 for data in testruns: 2147 testrun.append(TestRun(data)) 2148 2149 # extract the callgraph and traceevent data 2150 vprint('Analyzing the ftrace data...') 2151 tp = TestProps() 2152 tf = open(sysvals.ftracefile, 'r') 2153 data = 0 2154 for line in tf: 2155 # remove any latent carriage returns 2156 line = line.replace('\r\n', '') 2157 # grab the time stamp 2158 m = re.match(sysvals.stampfmt, line) 2159 if(m): 2160 tp.stamp = line 2161 continue 2162 # determine the trace data type (required for further parsing) 2163 m = re.match(sysvals.tracertypefmt, line) 2164 if(m): 2165 tp.setTracerType(m.group('t')) 2166 continue 2167 # device properties line 2168 if(re.match(sysvals.devpropfmt, line)): 2169 devProps(line) 2170 continue 2171 # parse only valid lines, if this is not one move on 2172 m = re.match(tp.ftrace_line_fmt, line) 2173 if(not m): 2174 continue 2175 # gather the basic message data from the line 2176 m_time = m.group('time') 2177 m_pid = m.group('pid') 2178 m_msg = m.group('msg') 2179 if(tp.cgformat): 2180 m_param3 = m.group('dur') 2181 else: 2182 m_param3 = 'traceevent' 2183 if(m_time and m_pid and m_msg): 2184 t = FTraceLine(m_time, m_msg, m_param3) 2185 pid = int(m_pid) 2186 else: 2187 continue 2188 # the line should be a call, return, or event 2189 if(not t.fcall and not t.freturn and not t.fevent): 2190 continue 2191 # look for the suspend start marker 2192 if(t.startMarker()): 2193 data = testrun[testidx].data 2194 parseStamp(tp.stamp, data) 2195 data.setStart(t.time) 2196 continue 2197 if(not data): 2198 continue 2199 # find the end of resume 2200 if(t.endMarker()): 2201 data.setEnd(t.time) 2202 testidx += 1 2203 if(testidx >= testcnt): 2204 break 2205 continue 2206 # trace event processing 2207 if(t.fevent): 2208 # general trace events have two types, begin and end 2209 if(re.match('(?P<name>.*) begin$', t.name)): 2210 isbegin = True 2211 elif(re.match('(?P<name>.*) end$', t.name)): 2212 isbegin = False 2213 else: 2214 continue 2215 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 2216 if(m): 2217 val = m.group('val') 2218 if val == '0': 2219 name = m.group('name') 2220 else: 2221 name = m.group('name')+'['+val+']' 2222 else: 2223 m = re.match('(?P<name>.*) .*', t.name) 2224 name = m.group('name') 2225 # special processing for trace events 2226 if re.match('dpm_prepare\[.*', name): 2227 continue 2228 elif re.match('machine_suspend.*', name): 2229 continue 2230 elif re.match('suspend_enter\[.*', name): 2231 if(not isbegin): 2232 data.dmesg['suspend_prepare']['end'] = t.time 2233 continue 2234 elif re.match('dpm_suspend\[.*', name): 2235 if(not isbegin): 2236 data.dmesg['suspend']['end'] = t.time 2237 continue 2238 elif re.match('dpm_suspend_late\[.*', name): 2239 if(isbegin): 2240 data.dmesg['suspend_late']['start'] = t.time 2241 else: 2242 data.dmesg['suspend_late']['end'] = t.time 2243 continue 2244 elif re.match('dpm_suspend_noirq\[.*', name): 2245 if(isbegin): 2246 data.dmesg['suspend_noirq']['start'] = t.time 2247 else: 2248 data.dmesg['suspend_noirq']['end'] = t.time 2249 continue 2250 elif re.match('dpm_resume_noirq\[.*', name): 2251 if(isbegin): 2252 data.dmesg['resume_machine']['end'] = t.time 2253 data.dmesg['resume_noirq']['start'] = t.time 2254 else: 2255 data.dmesg['resume_noirq']['end'] = t.time 2256 continue 2257 elif re.match('dpm_resume_early\[.*', name): 2258 if(isbegin): 2259 data.dmesg['resume_early']['start'] = t.time 2260 else: 2261 data.dmesg['resume_early']['end'] = t.time 2262 continue 2263 elif re.match('dpm_resume\[.*', name): 2264 if(isbegin): 2265 data.dmesg['resume']['start'] = t.time 2266 else: 2267 data.dmesg['resume']['end'] = t.time 2268 continue 2269 elif re.match('dpm_complete\[.*', name): 2270 if(isbegin): 2271 data.dmesg['resume_complete']['start'] = t.time 2272 else: 2273 data.dmesg['resume_complete']['end'] = t.time 2274 continue 2275 # skip trace events inside devices calls 2276 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)): 2277 continue 2278 # global events (outside device calls) are simply graphed 2279 if(isbegin): 2280 # store each trace event in ttemp 2281 if(name not in testrun[testidx].ttemp): 2282 testrun[testidx].ttemp[name] = [] 2283 testrun[testidx].ttemp[name].append(\ 2284 {'begin': t.time, 'end': t.time}) 2285 else: 2286 # finish off matching trace event in ttemp 2287 if(name in testrun[testidx].ttemp): 2288 testrun[testidx].ttemp[name][-1]['end'] = t.time 2289 # call/return processing 2290 elif sysvals.usecallgraph: 2291 # create a callgraph object for the data 2292 if(pid not in testrun[testidx].ftemp): 2293 testrun[testidx].ftemp[pid] = [] 2294 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid)) 2295 # when the call is finished, see which device matches it 2296 cg = testrun[testidx].ftemp[pid][-1] 2297 if(cg.addLine(t)): 2298 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid)) 2299 tf.close() 2300 2301 for test in testrun: 2302 # add the traceevent data to the device hierarchy 2303 if(sysvals.usetraceevents): 2304 for name in test.ttemp: 2305 for event in test.ttemp[name]: 2306 test.data.newActionGlobal(name, event['begin'], event['end']) 2307 2308 # add the callgraph data to the device hierarchy 2309 for pid in test.ftemp: 2310 for cg in test.ftemp[pid]: 2311 if len(cg.list) < 1 or cg.invalid: 2312 continue 2313 if(not cg.postProcess()): 2314 id = 'task %s cpu %s' % (pid, m.group('cpu')) 2315 vprint('Sanity check failed for '+\ 2316 id+', ignoring this callback') 2317 continue 2318 callstart = cg.start 2319 callend = cg.end 2320 for p in test.data.phases: 2321 if(test.data.dmesg[p]['start'] <= callstart and 2322 callstart <= test.data.dmesg[p]['end']): 2323 list = test.data.dmesg[p]['list'] 2324 for devname in list: 2325 dev = list[devname] 2326 if(pid == dev['pid'] and 2327 callstart <= dev['start'] and 2328 callend >= dev['end']): 2329 dev['ftrace'] = cg 2330 break 2331 2332 test.data.printDetails() 2333 2334# Function: parseTraceLog 2335# Description: 2336# Analyze an ftrace log output file generated from this app during 2337# the execution phase. Used when the ftrace log is the primary data source 2338# and includes the suspend_resume and device_pm_callback trace events 2339# The ftrace filename is taken from sysvals 2340# Output: 2341# An array of Data objects 2342def parseTraceLog(): 2343 vprint('Analyzing the ftrace data...') 2344 if(os.path.exists(sysvals.ftracefile) == False): 2345 doError('%s does not exist' % sysvals.ftracefile) 2346 2347 sysvals.setupAllKprobes() 2348 tracewatch = [] 2349 if sysvals.usekprobes: 2350 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', 2351 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF'] 2352 2353 # extract the callgraph and traceevent data 2354 tp = TestProps() 2355 testruns = [] 2356 testdata = [] 2357 testrun = 0 2358 data = 0 2359 tf = open(sysvals.ftracefile, 'r') 2360 phase = 'suspend_prepare' 2361 for line in tf: 2362 # remove any latent carriage returns 2363 line = line.replace('\r\n', '') 2364 # stamp line: each stamp means a new test run 2365 m = re.match(sysvals.stampfmt, line) 2366 if(m): 2367 tp.stamp = line 2368 continue 2369 # firmware line: pull out any firmware data 2370 m = re.match(sysvals.firmwarefmt, line) 2371 if(m): 2372 tp.fwdata.append((int(m.group('s')), int(m.group('r')))) 2373 continue 2374 # tracer type line: determine the trace data type 2375 m = re.match(sysvals.tracertypefmt, line) 2376 if(m): 2377 tp.setTracerType(m.group('t')) 2378 continue 2379 # device properties line 2380 if(re.match(sysvals.devpropfmt, line)): 2381 devProps(line) 2382 continue 2383 # ignore all other commented lines 2384 if line[0] == '#': 2385 continue 2386 # ftrace line: parse only valid lines 2387 m = re.match(tp.ftrace_line_fmt, line) 2388 if(not m): 2389 continue 2390 # gather the basic message data from the line 2391 m_time = m.group('time') 2392 m_proc = m.group('proc') 2393 m_pid = m.group('pid') 2394 m_msg = m.group('msg') 2395 if(tp.cgformat): 2396 m_param3 = m.group('dur') 2397 else: 2398 m_param3 = 'traceevent' 2399 if(m_time and m_pid and m_msg): 2400 t = FTraceLine(m_time, m_msg, m_param3) 2401 pid = int(m_pid) 2402 else: 2403 continue 2404 # the line should be a call, return, or event 2405 if(not t.fcall and not t.freturn and not t.fevent): 2406 continue 2407 # find the start of suspend 2408 if(t.startMarker()): 2409 phase = 'suspend_prepare' 2410 data = Data(len(testdata)) 2411 testdata.append(data) 2412 testrun = TestRun(data) 2413 testruns.append(testrun) 2414 parseStamp(tp.stamp, data) 2415 data.setStart(t.time) 2416 data.tKernSus = t.time 2417 continue 2418 if(not data): 2419 continue 2420 # process cpu exec line 2421 if t.type == 'tracing_mark_write': 2422 m = re.match(sysvals.procexecfmt, t.name) 2423 if(m): 2424 proclist = dict() 2425 for ps in m.group('ps').split(','): 2426 val = ps.split() 2427 if not val: 2428 continue 2429 name = val[0].replace('--', '-') 2430 proclist[name] = int(val[1]) 2431 data.pstl[t.time] = proclist 2432 continue 2433 # find the end of resume 2434 if(t.endMarker()): 2435 data.setEnd(t.time) 2436 if data.tKernRes == 0.0: 2437 data.tKernRes = t.time 2438 if data.dmesg['resume_complete']['end'] < 0: 2439 data.dmesg['resume_complete']['end'] = t.time 2440 if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber: 2441 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber] 2442 if(data.tSuspended != 0 and data.tResumed != 0 and \ 2443 (data.fwSuspend > 0 or data.fwResume > 0)): 2444 data.fwValid = True 2445 if(not sysvals.usetracemarkers): 2446 # no trace markers? then quit and be sure to finish recording 2447 # the event we used to trigger resume end 2448 if(len(testrun.ttemp['thaw_processes']) > 0): 2449 # if an entry exists, assume this is its end 2450 testrun.ttemp['thaw_processes'][-1]['end'] = t.time 2451 break 2452 continue 2453 # trace event processing 2454 if(t.fevent): 2455 if(phase == 'post_resume'): 2456 data.setEnd(t.time) 2457 if(t.type == 'suspend_resume'): 2458 # suspend_resume trace events have two types, begin and end 2459 if(re.match('(?P<name>.*) begin$', t.name)): 2460 isbegin = True 2461 elif(re.match('(?P<name>.*) end$', t.name)): 2462 isbegin = False 2463 else: 2464 continue 2465 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name) 2466 if(m): 2467 val = m.group('val') 2468 if val == '0': 2469 name = m.group('name') 2470 else: 2471 name = m.group('name')+'['+val+']' 2472 else: 2473 m = re.match('(?P<name>.*) .*', t.name) 2474 name = m.group('name') 2475 # ignore these events 2476 if(name.split('[')[0] in tracewatch): 2477 continue 2478 # -- phase changes -- 2479 # start of kernel suspend 2480 if(re.match('suspend_enter\[.*', t.name)): 2481 if(isbegin): 2482 data.dmesg[phase]['start'] = t.time 2483 data.tKernSus = t.time 2484 continue 2485 # suspend_prepare start 2486 elif(re.match('dpm_prepare\[.*', t.name)): 2487 phase = 'suspend_prepare' 2488 if(not isbegin): 2489 data.dmesg[phase]['end'] = t.time 2490 continue 2491 # suspend start 2492 elif(re.match('dpm_suspend\[.*', t.name)): 2493 phase = 'suspend' 2494 data.setPhase(phase, t.time, isbegin) 2495 continue 2496 # suspend_late start 2497 elif(re.match('dpm_suspend_late\[.*', t.name)): 2498 phase = 'suspend_late' 2499 data.setPhase(phase, t.time, isbegin) 2500 continue 2501 # suspend_noirq start 2502 elif(re.match('dpm_suspend_noirq\[.*', t.name)): 2503 phase = 'suspend_noirq' 2504 data.setPhase(phase, t.time, isbegin) 2505 if(not isbegin): 2506 phase = 'suspend_machine' 2507 data.dmesg[phase]['start'] = t.time 2508 continue 2509 # suspend_machine/resume_machine 2510 elif(re.match('machine_suspend\[.*', t.name)): 2511 if(isbegin): 2512 phase = 'suspend_machine' 2513 data.dmesg[phase]['end'] = t.time 2514 data.tSuspended = t.time 2515 else: 2516 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3): 2517 data.dmesg['suspend_machine']['end'] = t.time 2518 data.tSuspended = t.time 2519 phase = 'resume_machine' 2520 data.dmesg[phase]['start'] = t.time 2521 data.tResumed = t.time 2522 data.tLow = data.tResumed - data.tSuspended 2523 continue 2524 # acpi_suspend 2525 elif(re.match('acpi_suspend\[.*', t.name)): 2526 # acpi_suspend[0] S0i3 2527 if(re.match('acpi_suspend\[0\] begin', t.name)): 2528 if(sysvals.suspendmode == 'mem'): 2529 tp.S0i3 = True 2530 data.dmesg['suspend_machine']['end'] = t.time 2531 data.tSuspended = t.time 2532 continue 2533 # resume_noirq start 2534 elif(re.match('dpm_resume_noirq\[.*', t.name)): 2535 phase = 'resume_noirq' 2536 data.setPhase(phase, t.time, isbegin) 2537 if(isbegin): 2538 data.dmesg['resume_machine']['end'] = t.time 2539 continue 2540 # resume_early start 2541 elif(re.match('dpm_resume_early\[.*', t.name)): 2542 phase = 'resume_early' 2543 data.setPhase(phase, t.time, isbegin) 2544 continue 2545 # resume start 2546 elif(re.match('dpm_resume\[.*', t.name)): 2547 phase = 'resume' 2548 data.setPhase(phase, t.time, isbegin) 2549 continue 2550 # resume complete start 2551 elif(re.match('dpm_complete\[.*', t.name)): 2552 phase = 'resume_complete' 2553 if(isbegin): 2554 data.dmesg[phase]['start'] = t.time 2555 continue 2556 # skip trace events inside devices calls 2557 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)): 2558 continue 2559 # global events (outside device calls) are graphed 2560 if(name not in testrun.ttemp): 2561 testrun.ttemp[name] = [] 2562 if(isbegin): 2563 # create a new list entry 2564 testrun.ttemp[name].append(\ 2565 {'begin': t.time, 'end': t.time, 'pid': pid}) 2566 else: 2567 if(len(testrun.ttemp[name]) > 0): 2568 # if an entry exists, assume this is its end 2569 testrun.ttemp[name][-1]['end'] = t.time 2570 elif(phase == 'post_resume'): 2571 # post resume events can just have ends 2572 testrun.ttemp[name].append({ 2573 'begin': data.dmesg[phase]['start'], 2574 'end': t.time}) 2575 # device callback start 2576 elif(t.type == 'device_pm_callback_start'): 2577 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ 2578 t.name); 2579 if(not m): 2580 continue 2581 drv = m.group('drv') 2582 n = m.group('d') 2583 p = m.group('p') 2584 if(n and p): 2585 data.newAction(phase, n, pid, p, t.time, -1, drv) 2586 if pid not in data.devpids: 2587 data.devpids.append(pid) 2588 # device callback finish 2589 elif(t.type == 'device_pm_callback_end'): 2590 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name); 2591 if(not m): 2592 continue 2593 n = m.group('d') 2594 list = data.dmesg[phase]['list'] 2595 if(n in list): 2596 dev = list[n] 2597 dev['length'] = t.time - dev['start'] 2598 dev['end'] = t.time 2599 # kprobe event processing 2600 elif(t.fkprobe): 2601 kprobename = t.type 2602 kprobedata = t.name 2603 key = (kprobename, pid) 2604 # displayname is generated from kprobe data 2605 displayname = '' 2606 if(t.fcall): 2607 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata) 2608 if not displayname: 2609 continue 2610 if(key not in tp.ktemp): 2611 tp.ktemp[key] = [] 2612 tp.ktemp[key].append({ 2613 'pid': pid, 2614 'begin': t.time, 2615 'end': t.time, 2616 'name': displayname, 2617 'cdata': kprobedata, 2618 'proc': m_proc, 2619 }) 2620 elif(t.freturn): 2621 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1: 2622 continue 2623 e = tp.ktemp[key][-1] 2624 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001: 2625 tp.ktemp[key].pop() 2626 else: 2627 e['end'] = t.time 2628 e['rdata'] = kprobedata 2629 # end of kernel resume 2630 if(kprobename == 'pm_notifier_call_chain' or \ 2631 kprobename == 'pm_restore_console'): 2632 data.dmesg[phase]['end'] = t.time 2633 data.tKernRes = t.time 2634 2635 # callgraph processing 2636 elif sysvals.usecallgraph: 2637 # create a callgraph object for the data 2638 key = (m_proc, pid) 2639 if(key not in testrun.ftemp): 2640 testrun.ftemp[key] = [] 2641 testrun.ftemp[key].append(FTraceCallGraph(pid)) 2642 # when the call is finished, see which device matches it 2643 cg = testrun.ftemp[key][-1] 2644 if(cg.addLine(t)): 2645 testrun.ftemp[key].append(FTraceCallGraph(pid)) 2646 tf.close() 2647 2648 if sysvals.suspendmode == 'command': 2649 for test in testruns: 2650 for p in test.data.phases: 2651 if p == 'suspend_prepare': 2652 test.data.dmesg[p]['start'] = test.data.start 2653 test.data.dmesg[p]['end'] = test.data.end 2654 else: 2655 test.data.dmesg[p]['start'] = test.data.end 2656 test.data.dmesg[p]['end'] = test.data.end 2657 test.data.tSuspended = test.data.end 2658 test.data.tResumed = test.data.end 2659 test.data.tLow = 0 2660 test.data.fwValid = False 2661 2662 # dev source and procmon events can be unreadable with mixed phase height 2663 if sysvals.usedevsrc or sysvals.useprocmon: 2664 sysvals.mixedphaseheight = False 2665 2666 for i in range(len(testruns)): 2667 test = testruns[i] 2668 data = test.data 2669 # find the total time range for this test (begin, end) 2670 tlb, tle = data.start, data.end 2671 if i < len(testruns) - 1: 2672 tle = testruns[i+1].data.start 2673 # add the process usage data to the timeline 2674 if sysvals.useprocmon: 2675 data.createProcessUsageEvents() 2676 # add the traceevent data to the device hierarchy 2677 if(sysvals.usetraceevents): 2678 # add actual trace funcs 2679 for name in test.ttemp: 2680 for event in test.ttemp[name]: 2681 data.newActionGlobal(name, event['begin'], event['end'], event['pid']) 2682 # add the kprobe based virtual tracefuncs as actual devices 2683 for key in tp.ktemp: 2684 name, pid = key 2685 if name not in sysvals.tracefuncs: 2686 continue 2687 for e in tp.ktemp[key]: 2688 kb, ke = e['begin'], e['end'] 2689 if kb == ke or tlb > kb or tle <= kb: 2690 continue 2691 color = sysvals.kprobeColor(name) 2692 data.newActionGlobal(e['name'], kb, ke, pid, color) 2693 # add config base kprobes and dev kprobes 2694 if sysvals.usedevsrc: 2695 for key in tp.ktemp: 2696 name, pid = key 2697 if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs: 2698 continue 2699 for e in tp.ktemp[key]: 2700 kb, ke = e['begin'], e['end'] 2701 if kb == ke or tlb > kb or tle <= kb: 2702 continue 2703 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb, 2704 ke, e['cdata'], e['rdata']) 2705 if sysvals.usecallgraph: 2706 # add the callgraph data to the device hierarchy 2707 sortlist = dict() 2708 for key in test.ftemp: 2709 proc, pid = key 2710 for cg in test.ftemp[key]: 2711 if len(cg.list) < 1 or cg.invalid: 2712 continue 2713 if(not cg.postProcess()): 2714 id = 'task %s' % (pid) 2715 vprint('Sanity check failed for '+\ 2716 id+', ignoring this callback') 2717 continue 2718 # match cg data to devices 2719 if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, data): 2720 sortkey = '%f%f%d' % (cg.start, cg.end, pid) 2721 sortlist[sortkey] = cg 2722 # create blocks for orphan cg data 2723 for sortkey in sorted(sortlist): 2724 cg = sortlist[sortkey] 2725 name = cg.list[0].name 2726 if sysvals.isCallgraphFunc(name): 2727 vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name)) 2728 cg.newActionFromFunction(data) 2729 2730 if sysvals.suspendmode == 'command': 2731 for data in testdata: 2732 data.printDetails() 2733 return testdata 2734 2735 # fill in any missing phases 2736 for data in testdata: 2737 lp = data.phases[0] 2738 for p in data.phases: 2739 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 2740 vprint('WARNING: phase "%s" is missing!' % p) 2741 if(data.dmesg[p]['start'] < 0): 2742 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 2743 if(p == 'resume_machine'): 2744 data.tSuspended = data.dmesg[lp]['end'] 2745 data.tResumed = data.dmesg[lp]['end'] 2746 data.tLow = 0 2747 if(data.dmesg[p]['end'] < 0): 2748 data.dmesg[p]['end'] = data.dmesg[p]['start'] 2749 if(p != lp and not ('machine' in p and 'machine' in lp)): 2750 data.dmesg[lp]['end'] = data.dmesg[p]['start'] 2751 lp = p 2752 2753 if(len(sysvals.devicefilter) > 0): 2754 data.deviceFilter(sysvals.devicefilter) 2755 data.fixupInitcallsThatDidntReturn() 2756 if sysvals.usedevsrc: 2757 data.optimizeDevSrc() 2758 data.printDetails() 2759 2760 # x2: merge any overlapping devices between test runs 2761 if sysvals.usedevsrc and len(testdata) > 1: 2762 tc = len(testdata) 2763 for i in range(tc - 1): 2764 devlist = testdata[i].overflowDevices() 2765 for j in range(i + 1, tc): 2766 testdata[j].mergeOverlapDevices(devlist) 2767 testdata[0].stitchTouchingThreads(testdata[1:]) 2768 return testdata 2769 2770# Function: loadKernelLog 2771# Description: 2772# [deprecated for kernel 3.15.0 or newer] 2773# load the dmesg file into memory and fix up any ordering issues 2774# The dmesg filename is taken from sysvals 2775# Output: 2776# An array of empty Data objects with only their dmesgtext attributes set 2777def loadKernelLog(justtext=False): 2778 vprint('Analyzing the dmesg data...') 2779 if(os.path.exists(sysvals.dmesgfile) == False): 2780 doError('%s does not exist' % sysvals.dmesgfile) 2781 2782 if justtext: 2783 dmesgtext = [] 2784 # there can be multiple test runs in a single file 2785 tp = TestProps() 2786 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown') 2787 testruns = [] 2788 data = 0 2789 lf = open(sysvals.dmesgfile, 'r') 2790 for line in lf: 2791 line = line.replace('\r\n', '') 2792 idx = line.find('[') 2793 if idx > 1: 2794 line = line[idx:] 2795 m = re.match(sysvals.stampfmt, line) 2796 if(m): 2797 tp.stamp = line 2798 continue 2799 m = re.match(sysvals.firmwarefmt, line) 2800 if(m): 2801 tp.fwdata.append((int(m.group('s')), int(m.group('r')))) 2802 continue 2803 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 2804 if(not m): 2805 continue 2806 msg = m.group("msg") 2807 if justtext: 2808 dmesgtext.append(line) 2809 continue 2810 if(re.match('PM: Syncing filesystems.*', msg)): 2811 if(data): 2812 testruns.append(data) 2813 data = Data(len(testruns)) 2814 parseStamp(tp.stamp, data) 2815 if len(tp.fwdata) > data.testnumber: 2816 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber] 2817 if(data.fwSuspend > 0 or data.fwResume > 0): 2818 data.fwValid = True 2819 if(not data): 2820 continue 2821 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) 2822 if(m): 2823 sysvals.stamp['kernel'] = m.group('k') 2824 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg) 2825 if(m): 2826 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m') 2827 data.dmesgtext.append(line) 2828 lf.close() 2829 2830 if justtext: 2831 return dmesgtext 2832 if data: 2833 testruns.append(data) 2834 if len(testruns) < 1: 2835 doError(' dmesg log has no suspend/resume data: %s' \ 2836 % sysvals.dmesgfile) 2837 2838 # fix lines with same timestamp/function with the call and return swapped 2839 for data in testruns: 2840 last = '' 2841 for line in data.dmesgtext: 2842 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ 2843 '(?P<f>.*)\+ @ .*, parent: .*', line) 2844 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ 2845 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last) 2846 if(mc and mr and (mc.group('t') == mr.group('t')) and 2847 (mc.group('f') == mr.group('f'))): 2848 i = data.dmesgtext.index(last) 2849 j = data.dmesgtext.index(line) 2850 data.dmesgtext[i] = line 2851 data.dmesgtext[j] = last 2852 last = line 2853 return testruns 2854 2855# Function: parseKernelLog 2856# Description: 2857# [deprecated for kernel 3.15.0 or newer] 2858# Analyse a dmesg log output file generated from this app during 2859# the execution phase. Create a set of device structures in memory 2860# for subsequent formatting in the html output file 2861# This call is only for legacy support on kernels where the ftrace 2862# data lacks the suspend_resume or device_pm_callbacks trace events. 2863# Arguments: 2864# data: an empty Data object (with dmesgtext) obtained from loadKernelLog 2865# Output: 2866# The filled Data object 2867def parseKernelLog(data): 2868 phase = 'suspend_runtime' 2869 2870 if(data.fwValid): 2871 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \ 2872 (data.fwSuspend, data.fwResume)) 2873 2874 # dmesg phase match table 2875 dm = { 2876 'suspend_prepare': 'PM: Syncing filesystems.*', 2877 'suspend': 'PM: Entering [a-z]* sleep.*', 2878 'suspend_late': 'PM: suspend of devices complete after.*', 2879 'suspend_noirq': 'PM: late suspend of devices complete after.*', 2880 'suspend_machine': 'PM: noirq suspend of devices complete after.*', 2881 'resume_machine': 'ACPI: Low-level resume complete.*', 2882 'resume_noirq': 'ACPI: Waking up from system sleep state.*', 2883 'resume_early': 'PM: noirq resume of devices complete after.*', 2884 'resume': 'PM: early resume of devices complete after.*', 2885 'resume_complete': 'PM: resume of devices complete after.*', 2886 'post_resume': '.*Restarting tasks \.\.\..*', 2887 } 2888 if(sysvals.suspendmode == 'standby'): 2889 dm['resume_machine'] = 'PM: Restoring platform NVS memory' 2890 elif(sysvals.suspendmode == 'disk'): 2891 dm['suspend_late'] = 'PM: freeze of devices complete after.*' 2892 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*' 2893 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*' 2894 dm['resume_machine'] = 'PM: Restoring platform NVS memory' 2895 dm['resume_early'] = 'PM: noirq restore of devices complete after.*' 2896 dm['resume'] = 'PM: early restore of devices complete after.*' 2897 dm['resume_complete'] = 'PM: restore of devices complete after.*' 2898 elif(sysvals.suspendmode == 'freeze'): 2899 dm['resume_machine'] = 'ACPI: resume from mwait' 2900 2901 # action table (expected events that occur and show up in dmesg) 2902 at = { 2903 'sync_filesystems': { 2904 'smsg': 'PM: Syncing filesystems.*', 2905 'emsg': 'PM: Preparing system for mem sleep.*' }, 2906 'freeze_user_processes': { 2907 'smsg': 'Freezing user space processes .*', 2908 'emsg': 'Freezing remaining freezable tasks.*' }, 2909 'freeze_tasks': { 2910 'smsg': 'Freezing remaining freezable tasks.*', 2911 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' }, 2912 'ACPI prepare': { 2913 'smsg': 'ACPI: Preparing to enter system sleep state.*', 2914 'emsg': 'PM: Saving platform NVS memory.*' }, 2915 'PM vns': { 2916 'smsg': 'PM: Saving platform NVS memory.*', 2917 'emsg': 'Disabling non-boot CPUs .*' }, 2918 } 2919 2920 t0 = -1.0 2921 cpu_start = -1.0 2922 prevktime = -1.0 2923 actions = dict() 2924 for line in data.dmesgtext: 2925 # parse each dmesg line into the time and message 2926 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) 2927 if(m): 2928 val = m.group('ktime') 2929 try: 2930 ktime = float(val) 2931 except: 2932 continue 2933 msg = m.group('msg') 2934 # initialize data start to first line time 2935 if t0 < 0: 2936 data.setStart(ktime) 2937 t0 = ktime 2938 else: 2939 continue 2940 2941 # hack for determining resume_machine end for freeze 2942 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ 2943 and phase == 'resume_machine' and \ 2944 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 2945 data.dmesg['resume_machine']['end'] = ktime 2946 phase = 'resume_noirq' 2947 data.dmesg[phase]['start'] = ktime 2948 2949 # suspend start 2950 if(re.match(dm['suspend_prepare'], msg)): 2951 phase = 'suspend_prepare' 2952 data.dmesg[phase]['start'] = ktime 2953 data.setStart(ktime) 2954 data.tKernSus = ktime 2955 # suspend start 2956 elif(re.match(dm['suspend'], msg)): 2957 data.dmesg['suspend_prepare']['end'] = ktime 2958 phase = 'suspend' 2959 data.dmesg[phase]['start'] = ktime 2960 # suspend_late start 2961 elif(re.match(dm['suspend_late'], msg)): 2962 data.dmesg['suspend']['end'] = ktime 2963 phase = 'suspend_late' 2964 data.dmesg[phase]['start'] = ktime 2965 # suspend_noirq start 2966 elif(re.match(dm['suspend_noirq'], msg)): 2967 data.dmesg['suspend_late']['end'] = ktime 2968 phase = 'suspend_noirq' 2969 data.dmesg[phase]['start'] = ktime 2970 # suspend_machine start 2971 elif(re.match(dm['suspend_machine'], msg)): 2972 data.dmesg['suspend_noirq']['end'] = ktime 2973 phase = 'suspend_machine' 2974 data.dmesg[phase]['start'] = ktime 2975 # resume_machine start 2976 elif(re.match(dm['resume_machine'], msg)): 2977 if(sysvals.suspendmode in ['freeze', 'standby']): 2978 data.tSuspended = prevktime 2979 data.dmesg['suspend_machine']['end'] = prevktime 2980 else: 2981 data.tSuspended = ktime 2982 data.dmesg['suspend_machine']['end'] = ktime 2983 phase = 'resume_machine' 2984 data.tResumed = ktime 2985 data.tLow = data.tResumed - data.tSuspended 2986 data.dmesg[phase]['start'] = ktime 2987 # resume_noirq start 2988 elif(re.match(dm['resume_noirq'], msg)): 2989 data.dmesg['resume_machine']['end'] = ktime 2990 phase = 'resume_noirq' 2991 data.dmesg[phase]['start'] = ktime 2992 # resume_early start 2993 elif(re.match(dm['resume_early'], msg)): 2994 data.dmesg['resume_noirq']['end'] = ktime 2995 phase = 'resume_early' 2996 data.dmesg[phase]['start'] = ktime 2997 # resume start 2998 elif(re.match(dm['resume'], msg)): 2999 data.dmesg['resume_early']['end'] = ktime 3000 phase = 'resume' 3001 data.dmesg[phase]['start'] = ktime 3002 # resume complete start 3003 elif(re.match(dm['resume_complete'], msg)): 3004 data.dmesg['resume']['end'] = ktime 3005 phase = 'resume_complete' 3006 data.dmesg[phase]['start'] = ktime 3007 # post resume start 3008 elif(re.match(dm['post_resume'], msg)): 3009 data.dmesg['resume_complete']['end'] = ktime 3010 data.setEnd(ktime) 3011 data.tKernRes = ktime 3012 break 3013 3014 # -- device callbacks -- 3015 if(phase in data.phases): 3016 # device init call 3017 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 3018 sm = re.match('calling (?P<f>.*)\+ @ '+\ 3019 '(?P<n>.*), parent: (?P<p>.*)', msg); 3020 f = sm.group('f') 3021 n = sm.group('n') 3022 p = sm.group('p') 3023 if(f and n and p): 3024 data.newAction(phase, f, int(n), p, ktime, -1, '') 3025 # device init return 3026 elif(re.match('call (?P<f>.*)\+ returned .* after '+\ 3027 '(?P<t>.*) usecs', msg)): 3028 sm = re.match('call (?P<f>.*)\+ returned .* after '+\ 3029 '(?P<t>.*) usecs(?P<a>.*)', msg); 3030 f = sm.group('f') 3031 t = sm.group('t') 3032 list = data.dmesg[phase]['list'] 3033 if(f in list): 3034 dev = list[f] 3035 dev['length'] = int(t) 3036 dev['end'] = ktime 3037 3038 # if trace events are not available, these are better than nothing 3039 if(not sysvals.usetraceevents): 3040 # look for known actions 3041 for a in at: 3042 if(re.match(at[a]['smsg'], msg)): 3043 if(a not in actions): 3044 actions[a] = [] 3045 actions[a].append({'begin': ktime, 'end': ktime}) 3046 if(re.match(at[a]['emsg'], msg)): 3047 if(a in actions): 3048 actions[a][-1]['end'] = ktime 3049 # now look for CPU on/off events 3050 if(re.match('Disabling non-boot CPUs .*', msg)): 3051 # start of first cpu suspend 3052 cpu_start = ktime 3053 elif(re.match('Enabling non-boot CPUs .*', msg)): 3054 # start of first cpu resume 3055 cpu_start = ktime 3056 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)): 3057 # end of a cpu suspend, start of the next 3058 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg) 3059 cpu = 'CPU'+m.group('cpu') 3060 if(cpu not in actions): 3061 actions[cpu] = [] 3062 actions[cpu].append({'begin': cpu_start, 'end': ktime}) 3063 cpu_start = ktime 3064 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)): 3065 # end of a cpu resume, start of the next 3066 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg) 3067 cpu = 'CPU'+m.group('cpu') 3068 if(cpu not in actions): 3069 actions[cpu] = [] 3070 actions[cpu].append({'begin': cpu_start, 'end': ktime}) 3071 cpu_start = ktime 3072 prevktime = ktime 3073 3074 # fill in any missing phases 3075 lp = data.phases[0] 3076 for p in data.phases: 3077 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 3078 print('WARNING: phase "%s" is missing, something went wrong!' % p) 3079 print(' In %s, this dmesg line denotes the start of %s:' % \ 3080 (sysvals.suspendmode, p)) 3081 print(' "%s"' % dm[p]) 3082 if(data.dmesg[p]['start'] < 0): 3083 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 3084 if(p == 'resume_machine'): 3085 data.tSuspended = data.dmesg[lp]['end'] 3086 data.tResumed = data.dmesg[lp]['end'] 3087 data.tLow = 0 3088 if(data.dmesg[p]['end'] < 0): 3089 data.dmesg[p]['end'] = data.dmesg[p]['start'] 3090 lp = p 3091 3092 # fill in any actions we've found 3093 for name in actions: 3094 for event in actions[name]: 3095 data.newActionGlobal(name, event['begin'], event['end']) 3096 3097 data.printDetails() 3098 if(len(sysvals.devicefilter) > 0): 3099 data.deviceFilter(sysvals.devicefilter) 3100 data.fixupInitcallsThatDidntReturn() 3101 return True 3102 3103# Function: createHTMLSummarySimple 3104# Description: 3105# Create summary html file for a series of tests 3106# Arguments: 3107# testruns: array of Data objects from parseTraceLog 3108def createHTMLSummarySimple(testruns, htmlfile): 3109 # print out the basic summary of all the tests 3110 hf = open(htmlfile, 'w') 3111 3112 # write the html header first (html head, css code, up to body start) 3113 html = '<!DOCTYPE html>\n<html>\n<head>\n\ 3114 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 3115 <title>AnalyzeSuspend Summary</title>\n\ 3116 <style type=\'text/css\'>\n\ 3117 body {overflow-y: scroll;}\n\ 3118 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\ 3119 table {width:100%;border-collapse: collapse;}\n\ 3120 .summary {font: 22px Arial;border:1px solid;}\n\ 3121 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\ 3122 td {text-align: center;}\n\ 3123 tr.alt td {background-color:#EAF2D3;}\n\ 3124 tr.avg td {background-color:#BDE34C;}\n\ 3125 a:link {color: #90B521;}\n\ 3126 a:visited {color: #495E09;}\n\ 3127 a:hover {color: #B1DF28;}\n\ 3128 a:active {color: #FFFFFF;}\n\ 3129 </style>\n</head>\n<body>\n' 3130 3131 # group test header 3132 count = len(testruns) 3133 headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n' 3134 html += headline_stamp.format(sysvals.stamp['host'], 3135 sysvals.stamp['kernel'], sysvals.stamp['mode'], 3136 sysvals.stamp['time'], count) 3137 3138 # check to see if all the tests have the same value 3139 stampcolumns = False 3140 for data in testruns: 3141 if diffStamp(sysvals.stamp, data.stamp): 3142 stampcolumns = True 3143 break 3144 3145 th = '\t<th>{0}</th>\n' 3146 td = '\t<td>{0}</td>\n' 3147 tdlink = '\t<td><a href="{0}">Click Here</a></td>\n' 3148 3149 # table header 3150 html += '<table class="summary">\n<tr>\n' 3151 html += th.format("Test #") 3152 if stampcolumns: 3153 html += th.format("Hostname") 3154 html += th.format("Kernel Version") 3155 html += th.format("Suspend Mode") 3156 html += th.format("Test Time") 3157 html += th.format("Suspend Time") 3158 html += th.format("Resume Time") 3159 html += th.format("Detail") 3160 html += '</tr>\n' 3161 3162 # test data, 1 row per test 3163 sTimeAvg = 0.0 3164 rTimeAvg = 0.0 3165 num = 1 3166 for data in testruns: 3167 # data.end is the end of post_resume 3168 resumeEnd = data.dmesg['resume_complete']['end'] 3169 if num % 2 == 1: 3170 html += '<tr class="alt">\n' 3171 else: 3172 html += '<tr>\n' 3173 3174 # test num 3175 html += td.format("test %d" % num) 3176 num += 1 3177 if stampcolumns: 3178 # host name 3179 val = "unknown" 3180 if('host' in data.stamp): 3181 val = data.stamp['host'] 3182 html += td.format(val) 3183 # host kernel 3184 val = "unknown" 3185 if('kernel' in data.stamp): 3186 val = data.stamp['kernel'] 3187 html += td.format(val) 3188 # suspend mode 3189 val = "unknown" 3190 if('mode' in data.stamp): 3191 val = data.stamp['mode'] 3192 html += td.format(val) 3193 # test time 3194 val = "unknown" 3195 if('time' in data.stamp): 3196 val = data.stamp['time'] 3197 html += td.format(val) 3198 # suspend time 3199 sTime = (data.tSuspended - data.start)*1000 3200 sTimeAvg += sTime 3201 html += td.format("%3.3f ms" % sTime) 3202 # resume time 3203 rTime = (resumeEnd - data.tResumed)*1000 3204 rTimeAvg += rTime 3205 html += td.format("%3.3f ms" % rTime) 3206 # link to the output html 3207 html += tdlink.format(data.outfile) 3208 3209 html += '</tr>\n' 3210 3211 # last line: test average 3212 if(count > 0): 3213 sTimeAvg /= count 3214 rTimeAvg /= count 3215 html += '<tr class="avg">\n' 3216 html += td.format('Average') # name 3217 if stampcolumns: 3218 html += td.format('') # host 3219 html += td.format('') # kernel 3220 html += td.format('') # mode 3221 html += td.format('') # time 3222 html += td.format("%3.3f ms" % sTimeAvg) # suspend time 3223 html += td.format("%3.3f ms" % rTimeAvg) # resume time 3224 html += td.format('') # output link 3225 html += '</tr>\n' 3226 3227 # flush the data to file 3228 hf.write(html+'</table>\n') 3229 hf.write('</body>\n</html>\n') 3230 hf.close() 3231 3232def htmlTitle(): 3233 modename = { 3234 'freeze': 'Freeze (S0)', 3235 'standby': 'Standby (S1)', 3236 'mem': 'Suspend (S3)', 3237 'disk': 'Hibernate (S4)' 3238 } 3239 kernel = sysvals.stamp['kernel'] 3240 host = sysvals.hostname[0].upper()+sysvals.hostname[1:] 3241 mode = sysvals.suspendmode 3242 if sysvals.suspendmode in modename: 3243 mode = modename[sysvals.suspendmode] 3244 return host+' '+mode+' '+kernel 3245 3246def ordinal(value): 3247 suffix = 'th' 3248 if value < 10 or value > 19: 3249 if value % 10 == 1: 3250 suffix = 'st' 3251 elif value % 10 == 2: 3252 suffix = 'nd' 3253 elif value % 10 == 3: 3254 suffix = 'rd' 3255 return '%d%s' % (value, suffix) 3256 3257# Function: createHTML 3258# Description: 3259# Create the output html file from the resident test data 3260# Arguments: 3261# testruns: array of Data objects from parseKernelLog or parseTraceLog 3262# Output: 3263# True if the html file was created, false if it failed 3264def createHTML(testruns): 3265 if len(testruns) < 1: 3266 print('ERROR: Not enough test data to build a timeline') 3267 return 3268 3269 kerror = False 3270 for data in testruns: 3271 if data.kerror: 3272 kerror = True 3273 data.normalizeTime(testruns[-1].tSuspended) 3274 3275 x2changes = ['', 'absolute'] 3276 if len(testruns) > 1: 3277 x2changes = ['1', 'relative'] 3278 # html function templates 3279 headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version 3280 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n' 3281 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0] 3282 html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n' 3283 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n' 3284 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n' 3285 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n' 3286 html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n' 3287 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR&rarr;</div>\n' 3288 html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n' 3289 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n' 3290 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n' 3291 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n' 3292 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n' 3293 html_timetotal = '<table class="time1">\n<tr>'\ 3294 '<td class="green" title="{3}">{2} Suspend Time: <b>{0} ms</b></td>'\ 3295 '<td class="yellow" title="{4}">{2} Resume Time: <b>{1} ms</b></td>'\ 3296 '</tr>\n</table>\n' 3297 html_timetotal2 = '<table class="time1">\n<tr>'\ 3298 '<td class="green" title="{4}">{3} Suspend Time: <b>{0} ms</b></td>'\ 3299 '<td class="gray" title="time spent in low-power mode with clock running">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\ 3300 '<td class="yellow" title="{5}">{3} Resume Time: <b>{2} ms</b></td>'\ 3301 '</tr>\n</table>\n' 3302 html_timetotal3 = '<table class="time1">\n<tr>'\ 3303 '<td class="green">Execution Time: <b>{0} ms</b></td>'\ 3304 '<td class="yellow">Command: <b>{1}</b></td>'\ 3305 '</tr>\n</table>\n' 3306 html_timegroups = '<table class="time2">\n<tr>'\ 3307 '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\ 3308 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\ 3309 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\ 3310 '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\ 3311 '</tr>\n</table>\n' 3312 3313 # html format variables 3314 hoverZ = 'z-index:8;' 3315 if sysvals.usedevsrc: 3316 hoverZ = '' 3317 scaleH = 20 3318 scaleTH = 20 3319 if kerror: 3320 scaleH = 40 3321 scaleTH = 60 3322 3323 # device timeline 3324 vprint('Creating Device Timeline...') 3325 3326 devtl = Timeline(30, scaleH) 3327 3328 # Generate the header for this timeline 3329 for data in testruns: 3330 tTotal = data.end - data.start 3331 sktime = (data.dmesg['suspend_machine']['end'] - \ 3332 data.tKernSus) * 1000 3333 rktime = (data.dmesg['resume_complete']['end'] - \ 3334 data.dmesg['resume_machine']['start']) * 1000 3335 if(tTotal == 0): 3336 print('ERROR: No timeline data') 3337 sys.exit() 3338 if(data.tLow > 0): 3339 low_time = '%.0f'%(data.tLow*1000) 3340 if sysvals.suspendmode == 'command': 3341 run_time = '%.0f'%((data.end-data.start)*1000) 3342 if sysvals.testcommand: 3343 testdesc = sysvals.testcommand 3344 else: 3345 testdesc = 'unknown' 3346 if(len(testruns) > 1): 3347 testdesc = ordinal(data.testnumber+1)+' '+testdesc 3348 thtml = html_timetotal3.format(run_time, testdesc) 3349 devtl.html['header'] += thtml 3350 elif data.fwValid: 3351 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0)) 3352 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0)) 3353 testdesc1 = 'Total' 3354 testdesc2 = '' 3355 stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode 3356 rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode 3357 if(len(testruns) > 1): 3358 testdesc1 = testdesc2 = ordinal(data.testnumber+1) 3359 testdesc2 += ' ' 3360 if(data.tLow == 0): 3361 thtml = html_timetotal.format(suspend_time, \ 3362 resume_time, testdesc1, stitle, rtitle) 3363 else: 3364 thtml = html_timetotal2.format(suspend_time, low_time, \ 3365 resume_time, testdesc1, stitle, rtitle) 3366 devtl.html['header'] += thtml 3367 sftime = '%.3f'%(data.fwSuspend / 1000000.0) 3368 rftime = '%.3f'%(data.fwResume / 1000000.0) 3369 devtl.html['header'] += html_timegroups.format('%.3f'%sktime, \ 3370 sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode) 3371 else: 3372 suspend_time = '%.3f' % sktime 3373 resume_time = '%.3f' % rktime 3374 testdesc = 'Kernel' 3375 stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode 3376 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode 3377 if(len(testruns) > 1): 3378 testdesc = ordinal(data.testnumber+1)+' '+testdesc 3379 if(data.tLow == 0): 3380 thtml = html_timetotal.format(suspend_time, \ 3381 resume_time, testdesc, stitle, rtitle) 3382 else: 3383 thtml = html_timetotal2.format(suspend_time, low_time, \ 3384 resume_time, testdesc, stitle, rtitle) 3385 devtl.html['header'] += thtml 3386 3387 # time scale for potentially multiple datasets 3388 t0 = testruns[0].start 3389 tMax = testruns[-1].end 3390 tTotal = tMax - t0 3391 3392 # determine the maximum number of rows we need to draw 3393 fulllist = [] 3394 threadlist = [] 3395 pscnt = 0 3396 devcnt = 0 3397 for data in testruns: 3398 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen) 3399 for group in data.devicegroups: 3400 devlist = [] 3401 for phase in group: 3402 for devname in data.tdevlist[phase]: 3403 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname]) 3404 devlist.append(d) 3405 if d.isa('kth'): 3406 threadlist.append(d) 3407 else: 3408 if d.isa('ps'): 3409 pscnt += 1 3410 else: 3411 devcnt += 1 3412 fulllist.append(d) 3413 if sysvals.mixedphaseheight: 3414 devtl.getPhaseRows(devlist) 3415 if not sysvals.mixedphaseheight: 3416 if len(threadlist) > 0 and len(fulllist) > 0: 3417 if pscnt > 0 and devcnt > 0: 3418 msg = 'user processes & device pm callbacks' 3419 elif pscnt > 0: 3420 msg = 'user processes' 3421 else: 3422 msg = 'device pm callbacks' 3423 d = testruns[0].addHorizontalDivider(msg, testruns[-1].end) 3424 fulllist.insert(0, d) 3425 devtl.getPhaseRows(fulllist) 3426 if len(threadlist) > 0: 3427 d = testruns[0].addHorizontalDivider('asynchronous kernel threads', testruns[-1].end) 3428 threadlist.insert(0, d) 3429 devtl.getPhaseRows(threadlist, devtl.rows) 3430 devtl.calcTotalRows() 3431 3432 # create bounding box, add buttons 3433 if sysvals.suspendmode != 'command': 3434 devtl.html['timeline'] += html_devlist1 3435 if len(testruns) > 1: 3436 devtl.html['timeline'] += html_devlist2 3437 devtl.html['timeline'] += html_zoombox 3438 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) 3439 3440 # draw the full timeline 3441 phases = {'suspend':[],'resume':[]} 3442 for phase in data.dmesg: 3443 if 'resume' in phase: 3444 phases['resume'].append(phase) 3445 else: 3446 phases['suspend'].append(phase) 3447 3448 # draw each test run chronologically 3449 for data in testruns: 3450 # now draw the actual timeline blocks 3451 for dir in phases: 3452 # draw suspend and resume blocks separately 3453 bname = '%s%d' % (dir[0], data.testnumber) 3454 if dir == 'suspend': 3455 m0 = testruns[data.testnumber].start 3456 mMax = testruns[data.testnumber].tSuspended 3457 mTotal = mMax - m0 3458 left = '%f' % (((m0-t0)*100.0)/tTotal) 3459 else: 3460 m0 = testruns[data.testnumber].tSuspended 3461 mMax = testruns[data.testnumber].end 3462 # in an x2 run, remove any gap between blocks 3463 if len(testruns) > 1 and data.testnumber == 0: 3464 mMax = testruns[1].start 3465 mTotal = mMax - m0 3466 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal) 3467 # if a timeline block is 0 length, skip altogether 3468 if mTotal == 0: 3469 continue 3470 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal) 3471 devtl.html['timeline'] += html_tblock.format(bname, left, width, devtl.scaleH) 3472 for b in sorted(phases[dir]): 3473 # draw the phase color background 3474 phase = data.dmesg[b] 3475 length = phase['end']-phase['start'] 3476 left = '%f' % (((phase['start']-m0)*100.0)/mTotal) 3477 width = '%f' % ((length*100.0)/mTotal) 3478 devtl.html['timeline'] += html_phase.format(left, width, \ 3479 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ 3480 data.dmesg[b]['color'], '') 3481 for e in data.errorinfo[dir]: 3482 # draw red lines for any kernel errors found 3483 t, err = e 3484 right = '%f' % (((mMax-t)*100.0)/mTotal) 3485 devtl.html['timeline'] += html_error.format(right, err) 3486 for b in sorted(phases[dir]): 3487 # draw the devices for this phase 3488 phaselist = data.dmesg[b]['list'] 3489 for d in data.tdevlist[b]: 3490 name = d 3491 drv = '' 3492 dev = phaselist[d] 3493 xtraclass = '' 3494 xtrainfo = '' 3495 xtrastyle = '' 3496 if 'htmlclass' in dev: 3497 xtraclass = dev['htmlclass'] 3498 if 'color' in dev: 3499 xtrastyle = 'background-color:%s;' % dev['color'] 3500 if(d in sysvals.devprops): 3501 name = sysvals.devprops[d].altName(d) 3502 xtraclass = sysvals.devprops[d].xtraClass() 3503 xtrainfo = sysvals.devprops[d].xtraInfo() 3504 elif xtraclass == ' kth': 3505 xtrainfo = ' kernel_thread' 3506 if('drv' in dev and dev['drv']): 3507 drv = ' {%s}' % dev['drv'] 3508 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row']) 3509 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row']) 3510 top = '%.3f' % (rowtop + devtl.scaleH) 3511 left = '%f' % (((dev['start']-m0)*100)/mTotal) 3512 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal) 3513 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) 3514 title = name+drv+xtrainfo+length 3515 if sysvals.suspendmode == 'command': 3516 title += sysvals.testcommand 3517 elif xtraclass == ' ps': 3518 if 'suspend' in b: 3519 title += 'pre_suspend_process' 3520 else: 3521 title += 'post_resume_process' 3522 else: 3523 title += b 3524 devtl.html['timeline'] += html_device.format(dev['id'], \ 3525 title, left, top, '%.3f'%rowheight, width, \ 3526 d+drv, xtraclass, xtrastyle) 3527 if('cpuexec' in dev): 3528 for t in sorted(dev['cpuexec']): 3529 start, end = t 3530 j = float(dev['cpuexec'][t]) / 5 3531 if j > 1.0: 3532 j = 1.0 3533 height = '%.3f' % (rowheight/3) 3534 top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3) 3535 left = '%f' % (((start-m0)*100)/mTotal) 3536 width = '%f' % ((end-start)*100/mTotal) 3537 color = 'rgba(255, 0, 0, %f)' % j 3538 devtl.html['timeline'] += \ 3539 html_cpuexec.format(left, top, height, width, color) 3540 if('src' not in dev): 3541 continue 3542 # draw any trace events for this device 3543 for e in dev['src']: 3544 height = '%.3f' % devtl.rowH 3545 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH)) 3546 left = '%f' % (((e.time-m0)*100)/mTotal) 3547 width = '%f' % (e.length*100/mTotal) 3548 xtrastyle = '' 3549 if e.color: 3550 xtrastyle = 'background:%s;' % e.color 3551 devtl.html['timeline'] += \ 3552 html_traceevent.format(e.title(), \ 3553 left, top, height, width, e.text(), '', xtrastyle) 3554 # draw the time scale, try to make the number of labels readable 3555 devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir) 3556 devtl.html['timeline'] += '</div>\n' 3557 3558 # timeline is finished 3559 devtl.html['timeline'] += '</div>\n</div>\n' 3560 3561 # draw a legend which describes the phases by color 3562 if sysvals.suspendmode != 'command': 3563 data = testruns[-1] 3564 devtl.html['legend'] = '<div class="legend">\n' 3565 pdelta = 100.0/len(data.phases) 3566 pmargin = pdelta / 4.0 3567 for phase in data.phases: 3568 tmp = phase.split('_') 3569 id = tmp[0][0] 3570 if(len(tmp) > 1): 3571 id += tmp[1][0] 3572 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) 3573 name = string.replace(phase, '_', ' &nbsp;') 3574 devtl.html['legend'] += html_legend.format(order, \ 3575 data.dmesg[phase]['color'], name, id) 3576 devtl.html['legend'] += '</div>\n' 3577 3578 hf = open(sysvals.htmlfile, 'w') 3579 3580 if not sysvals.cgexp: 3581 cgchk = 'checked' 3582 cgnchk = 'not(:checked)' 3583 else: 3584 cgchk = 'not(:checked)' 3585 cgnchk = 'checked' 3586 3587 # write the html header first (html head, css code, up to body start) 3588 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\ 3589 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ 3590 <title>'+htmlTitle()+'</title>\n\ 3591 <style type=\'text/css\'>\n\ 3592 body {overflow-y:scroll;}\n\ 3593 .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\ 3594 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\ 3595 .callgraph article * {padding-left:28px;}\n\ 3596 h1 {color:black;font:bold 30px Times;}\n\ 3597 t0 {color:black;font:bold 30px Times;}\n\ 3598 t1 {color:black;font:30px Times;}\n\ 3599 t2 {color:black;font:25px Times;}\n\ 3600 t3 {color:black;font:20px Times;white-space:nowrap;}\n\ 3601 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\ 3602 cS {font:bold 13px Times;}\n\ 3603 table {width:100%;}\n\ 3604 .gray {background-color:rgba(80,80,80,0.1);}\n\ 3605 .green {background-color:rgba(204,255,204,0.4);}\n\ 3606 .purple {background-color:rgba(128,0,128,0.2);}\n\ 3607 .yellow {background-color:rgba(255,255,204,0.4);}\n\ 3608 .time1 {font:22px Arial;border:1px solid;}\n\ 3609 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\ 3610 td {text-align:center;}\n\ 3611 r {color:#500000;font:15px Tahoma;}\n\ 3612 n {color:#505050;font:15px Tahoma;}\n\ 3613 .tdhl {color:red;}\n\ 3614 .hide {display:none;}\n\ 3615 .pf {display:none;}\n\ 3616 .pf:'+cgchk+' + 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\ 3617 .pf:'+cgnchk+' ~ 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\ 3618 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\ 3619 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\ 3620 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\ 3621 .thread {position:absolute;height:0%;overflow:hidden;z-index:7;line-height:30px;font-size:14px;border:1px solid;text-align:center;white-space:nowrap;}\n\ 3622 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\ 3623 .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\ 3624 .thread.sec,.thread.sec:hover {background-color:black;border:0;color:white;line-height:15px;font-size:10px;}\n\ 3625 .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\ 3626 .hover.sync {background-color:white;}\n\ 3627 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background-color:white;}\n\ 3628 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\ 3629 .traceevent {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\ 3630 .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\ 3631 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\ 3632 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\ 3633 .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\ 3634 .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\ 3635 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\ 3636 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\ 3637 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\ 3638 .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\ 3639 .devlist {position:'+x2changes[1]+';width:190px;}\n\ 3640 a:link {color:white;text-decoration:none;}\n\ 3641 a:visited {color:white;}\n\ 3642 a:hover {color:white;}\n\ 3643 a:active {color:white;}\n\ 3644 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\ 3645 #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\ 3646 .tblock {position:absolute;height:100%;background-color:#ddd;}\n\ 3647 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\ 3648 .bg {z-index:1;}\n\ 3649 </style>\n</head>\n<body>\n' 3650 3651 # no header or css if its embedded 3652 if(sysvals.embedded): 3653 hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' % 3654 (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \ 3655 data.fwSuspend/1000000, data.fwResume/1000000)) 3656 else: 3657 hf.write(html_header) 3658 3659 # write the test title and general info header 3660 if(sysvals.stamp['time'] != ""): 3661 hf.write(headline_version) 3662 if sysvals.logmsg: 3663 hf.write('<button id="showtest" class="logbtn">log</button>') 3664 if sysvals.addlogs and sysvals.dmesgfile: 3665 hf.write('<button id="showdmesg" class="logbtn">dmesg</button>') 3666 if sysvals.addlogs and sysvals.ftracefile: 3667 hf.write('<button id="showftrace" class="logbtn">ftrace</button>') 3668 hf.write(headline_stamp.format(sysvals.stamp['host'], 3669 sysvals.stamp['kernel'], sysvals.stamp['mode'], \ 3670 sysvals.stamp['time'])) 3671 3672 # write the device timeline 3673 hf.write(devtl.html['header']) 3674 hf.write(devtl.html['timeline']) 3675 hf.write(devtl.html['legend']) 3676 hf.write('<div id="devicedetailtitle"></div>\n') 3677 hf.write('<div id="devicedetail" style="display:none;">\n') 3678 # draw the colored boxes for the device detail section 3679 for data in testruns: 3680 hf.write('<div id="devicedetail%d">\n' % data.testnumber) 3681 pscolor = 'linear-gradient(to top left, #ccc, #eee)' 3682 hf.write(html_phaselet.format('pre_suspend_process', \ 3683 '0', '0', pscolor)) 3684 for b in data.phases: 3685 phase = data.dmesg[b] 3686 length = phase['end']-phase['start'] 3687 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 3688 width = '%.3f' % ((length*100.0)/tTotal) 3689 hf.write(html_phaselet.format(b, left, width, \ 3690 data.dmesg[b]['color'])) 3691 hf.write(html_phaselet.format('post_resume_process', \ 3692 '0', '0', pscolor)) 3693 if sysvals.suspendmode == 'command': 3694 hf.write(html_phaselet.format('cmdexec', '0', '0', pscolor)) 3695 hf.write('</div>\n') 3696 hf.write('</div>\n') 3697 3698 # write the ftrace data (callgraph) 3699 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest: 3700 data = testruns[sysvals.cgtest] 3701 else: 3702 data = testruns[-1] 3703 if(sysvals.usecallgraph and not sysvals.embedded): 3704 hf.write('<section id="callgraphs" class="callgraph">\n') 3705 # write out the ftrace data converted to html 3706 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' 3707 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n' 3708 html_func_end = '</article>\n' 3709 html_func_leaf = '<article>{0} {1}</article>\n' 3710 num = 0 3711 for p in data.phases: 3712 if sysvals.cgphase and p != sysvals.cgphase: 3713 continue 3714 list = data.dmesg[p]['list'] 3715 for devname in data.sortedDevices(p): 3716 if('ftrace' not in list[devname]): 3717 continue 3718 devid = list[devname]['id'] 3719 cg = list[devname]['ftrace'] 3720 clen = (cg.end - cg.start) * 1000 3721 if clen < sysvals.mincglen: 3722 continue 3723 fmt = '<r>(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')</r>' 3724 flen = fmt % (clen, cg.start, cg.end) 3725 name = devname 3726 if(devname in sysvals.devprops): 3727 name = sysvals.devprops[devname].altName(devname) 3728 if sysvals.suspendmode == 'command': 3729 ftitle = name 3730 else: 3731 ftitle = name+' '+p 3732 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \ 3733 num, ftitle, flen)) 3734 num += 1 3735 for line in cg.list: 3736 if(line.length < 0.000000001): 3737 flen = '' 3738 else: 3739 fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>' 3740 flen = fmt % (line.length*1000, line.time) 3741 if(line.freturn and line.fcall): 3742 hf.write(html_func_leaf.format(line.name, flen)) 3743 elif(line.freturn): 3744 hf.write(html_func_end) 3745 else: 3746 hf.write(html_func_start.format(num, line.name, flen)) 3747 num += 1 3748 hf.write(html_func_end) 3749 hf.write('\n\n </section>\n') 3750 3751 # add the test log as a hidden div 3752 if sysvals.logmsg: 3753 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n') 3754 # add the dmesg log as a hidden div 3755 if sysvals.addlogs and sysvals.dmesgfile: 3756 hf.write('<div id="dmesglog" style="display:none;">\n') 3757 lf = open(sysvals.dmesgfile, 'r') 3758 for line in lf: 3759 line = line.replace('<', '&lt').replace('>', '&gt') 3760 hf.write(line) 3761 lf.close() 3762 hf.write('</div>\n') 3763 # add the ftrace log as a hidden div 3764 if sysvals.addlogs and sysvals.ftracefile: 3765 hf.write('<div id="ftracelog" style="display:none;">\n') 3766 lf = open(sysvals.ftracefile, 'r') 3767 for line in lf: 3768 hf.write(line) 3769 lf.close() 3770 hf.write('</div>\n') 3771 3772 if(not sysvals.embedded): 3773 # write the footer and close 3774 addScriptCode(hf, testruns) 3775 hf.write('</body>\n</html>\n') 3776 else: 3777 # embedded out will be loaded in a page, skip the js 3778 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000 3779 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000 3780 # add js code in a div entry for later evaluation 3781 detail = 'var bounds = [%f,%f];\n' % (t0, tMax) 3782 detail += 'var devtable = [\n' 3783 for data in testruns: 3784 topo = data.deviceTopology() 3785 detail += '\t"%s",\n' % (topo) 3786 detail += '];\n' 3787 hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n') 3788 hf.close() 3789 return True 3790 3791# Function: addScriptCode 3792# Description: 3793# Adds the javascript code to the output html 3794# Arguments: 3795# hf: the open html file pointer 3796# testruns: array of Data objects from parseKernelLog or parseTraceLog 3797def addScriptCode(hf, testruns): 3798 t0 = testruns[0].start * 1000 3799 tMax = testruns[-1].end * 1000 3800 # create an array in javascript memory with the device details 3801 detail = ' var devtable = [];\n' 3802 for data in testruns: 3803 topo = data.deviceTopology() 3804 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo) 3805 detail += ' var bounds = [%f,%f];\n' % (t0, tMax) 3806 # add the code which will manipulate the data in the browser 3807 script_code = \ 3808 '<script type="text/javascript">\n'+detail+\ 3809 ' var resolution = -1;\n'\ 3810 ' var dragval = [0, 0];\n'\ 3811 ' function redrawTimescale(t0, tMax, tS) {\n'\ 3812 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cS>&larr;R</cS></div>\';\n'\ 3813 ' var tTotal = tMax - t0;\n'\ 3814 ' var list = document.getElementsByClassName("tblock");\n'\ 3815 ' for (var i = 0; i < list.length; i++) {\n'\ 3816 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\ 3817 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\ 3818 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\ 3819 ' var mMax = m0 + mTotal;\n'\ 3820 ' var html = "";\n'\ 3821 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\ 3822 ' if(divTotal > 1000) continue;\n'\ 3823 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\ 3824 ' var pos = 0.0, val = 0.0;\n'\ 3825 ' for (var j = 0; j < divTotal; j++) {\n'\ 3826 ' var htmlline = "";\n'\ 3827 ' if(list[i].id[5] == "r") {\n'\ 3828 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\ 3829 ' val = (j)*tS;\n'\ 3830 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\ 3831 ' if(j == 0)\n'\ 3832 ' htmlline = rline;\n'\ 3833 ' } else {\n'\ 3834 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\ 3835 ' val = (j-divTotal+1)*tS;\n'\ 3836 ' if(j == divTotal - 1)\n'\ 3837 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S&rarr;</cS></div>\';\n'\ 3838 ' else\n'\ 3839 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\ 3840 ' }\n'\ 3841 ' html += htmlline;\n'\ 3842 ' }\n'\ 3843 ' timescale.innerHTML = html;\n'\ 3844 ' }\n'\ 3845 ' }\n'\ 3846 ' function zoomTimeline() {\n'\ 3847 ' var dmesg = document.getElementById("dmesg");\n'\ 3848 ' var zoombox = document.getElementById("dmesgzoombox");\n'\ 3849 ' var left = zoombox.scrollLeft;\n'\ 3850 ' var val = parseFloat(dmesg.style.width);\n'\ 3851 ' var newval = 100;\n'\ 3852 ' var sh = window.outerWidth / 2;\n'\ 3853 ' if(this.id == "zoomin") {\n'\ 3854 ' newval = val * 1.2;\n'\ 3855 ' if(newval > 910034) newval = 910034;\n'\ 3856 ' dmesg.style.width = newval+"%";\n'\ 3857 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\ 3858 ' } else if (this.id == "zoomout") {\n'\ 3859 ' newval = val / 1.2;\n'\ 3860 ' if(newval < 100) newval = 100;\n'\ 3861 ' dmesg.style.width = newval+"%";\n'\ 3862 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\ 3863 ' } else {\n'\ 3864 ' zoombox.scrollLeft = 0;\n'\ 3865 ' dmesg.style.width = "100%";\n'\ 3866 ' }\n'\ 3867 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\ 3868 ' var t0 = bounds[0];\n'\ 3869 ' var tMax = bounds[1];\n'\ 3870 ' var tTotal = tMax - t0;\n'\ 3871 ' var wTotal = tTotal * 100.0 / newval;\n'\ 3872 ' var idx = 7*window.innerWidth/1100;\n'\ 3873 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\ 3874 ' if(i >= tS.length) i = tS.length - 1;\n'\ 3875 ' if(tS[i] == resolution) return;\n'\ 3876 ' resolution = tS[i];\n'\ 3877 ' redrawTimescale(t0, tMax, tS[i]);\n'\ 3878 ' }\n'\ 3879 ' function deviceName(title) {\n'\ 3880 ' var name = title.slice(0, title.indexOf(" ("));\n'\ 3881 ' return name;\n'\ 3882 ' }\n'\ 3883 ' function deviceHover() {\n'\ 3884 ' var name = deviceName(this.title);\n'\ 3885 ' var dmesg = document.getElementById("dmesg");\n'\ 3886 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 3887 ' var cpu = -1;\n'\ 3888 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ 3889 ' cpu = parseInt(name.slice(7));\n'\ 3890 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ 3891 ' cpu = parseInt(name.slice(8));\n'\ 3892 ' for (var i = 0; i < dev.length; i++) {\n'\ 3893 ' dname = deviceName(dev[i].title);\n'\ 3894 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\ 3895 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 3896 ' (name == dname))\n'\ 3897 ' {\n'\ 3898 ' dev[i].className = "hover "+cname;\n'\ 3899 ' } else {\n'\ 3900 ' dev[i].className = cname;\n'\ 3901 ' }\n'\ 3902 ' }\n'\ 3903 ' }\n'\ 3904 ' function deviceUnhover() {\n'\ 3905 ' var dmesg = document.getElementById("dmesg");\n'\ 3906 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 3907 ' for (var i = 0; i < dev.length; i++) {\n'\ 3908 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\ 3909 ' }\n'\ 3910 ' }\n'\ 3911 ' function deviceTitle(title, total, cpu) {\n'\ 3912 ' var prefix = "Total";\n'\ 3913 ' if(total.length > 3) {\n'\ 3914 ' prefix = "Average";\n'\ 3915 ' total[1] = (total[1]+total[3])/2;\n'\ 3916 ' total[2] = (total[2]+total[4])/2;\n'\ 3917 ' }\n'\ 3918 ' var devtitle = document.getElementById("devicedetailtitle");\n'\ 3919 ' var name = deviceName(title);\n'\ 3920 ' if(cpu >= 0) name = "CPU"+cpu;\n'\ 3921 ' var driver = "";\n'\ 3922 ' var tS = "<t2>(</t2>";\n'\ 3923 ' var tR = "<t2>)</t2>";\n'\ 3924 ' if(total[1] > 0)\n'\ 3925 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\ 3926 ' if(total[2] > 0)\n'\ 3927 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\ 3928 ' var s = title.indexOf("{");\n'\ 3929 ' var e = title.indexOf("}");\n'\ 3930 ' if((s >= 0) && (e >= 0))\n'\ 3931 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\ 3932 ' if(total[1] > 0 && total[2] > 0)\n'\ 3933 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\ 3934 ' else\n'\ 3935 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\ 3936 ' return name;\n'\ 3937 ' }\n'\ 3938 ' function deviceDetail() {\n'\ 3939 ' var devinfo = document.getElementById("devicedetail");\n'\ 3940 ' devinfo.style.display = "block";\n'\ 3941 ' var name = deviceName(this.title);\n'\ 3942 ' var cpu = -1;\n'\ 3943 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\ 3944 ' cpu = parseInt(name.slice(7));\n'\ 3945 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\ 3946 ' cpu = parseInt(name.slice(8));\n'\ 3947 ' var dmesg = document.getElementById("dmesg");\n'\ 3948 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 3949 ' var idlist = [];\n'\ 3950 ' var pdata = [[]];\n'\ 3951 ' if(document.getElementById("devicedetail1"))\n'\ 3952 ' pdata = [[], []];\n'\ 3953 ' var pd = pdata[0];\n'\ 3954 ' var total = [0.0, 0.0, 0.0];\n'\ 3955 ' for (var i = 0; i < dev.length; i++) {\n'\ 3956 ' dname = deviceName(dev[i].title);\n'\ 3957 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\ 3958 ' (name == dname))\n'\ 3959 ' {\n'\ 3960 ' idlist[idlist.length] = dev[i].id;\n'\ 3961 ' var tidx = 1;\n'\ 3962 ' if(dev[i].id[0] == "a") {\n'\ 3963 ' pd = pdata[0];\n'\ 3964 ' } else {\n'\ 3965 ' if(pdata.length == 1) pdata[1] = [];\n'\ 3966 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\ 3967 ' pd = pdata[1];\n'\ 3968 ' tidx = 3;\n'\ 3969 ' }\n'\ 3970 ' var info = dev[i].title.split(" ");\n'\ 3971 ' var pname = info[info.length-1];\n'\ 3972 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\ 3973 ' total[0] += pd[pname];\n'\ 3974 ' if(pname.indexOf("suspend") >= 0)\n'\ 3975 ' total[tidx] += pd[pname];\n'\ 3976 ' else\n'\ 3977 ' total[tidx+1] += pd[pname];\n'\ 3978 ' }\n'\ 3979 ' }\n'\ 3980 ' var devname = deviceTitle(this.title, total, cpu);\n'\ 3981 ' var left = 0.0;\n'\ 3982 ' for (var t = 0; t < pdata.length; t++) {\n'\ 3983 ' pd = pdata[t];\n'\ 3984 ' devinfo = document.getElementById("devicedetail"+t);\n'\ 3985 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\ 3986 ' for (var i = 0; i < phases.length; i++) {\n'\ 3987 ' if(phases[i].id in pd) {\n'\ 3988 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\ 3989 ' var fs = 32;\n'\ 3990 ' if(w < 8) fs = 4*w | 0;\n'\ 3991 ' var fs2 = fs*3/4;\n'\ 3992 ' phases[i].style.width = w+"%";\n'\ 3993 ' phases[i].style.left = left+"%";\n'\ 3994 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\ 3995 ' left += w;\n'\ 3996 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\ 3997 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\ 3998 ' phases[i].innerHTML = time+pname;\n'\ 3999 ' } else {\n'\ 4000 ' phases[i].style.width = "0%";\n'\ 4001 ' phases[i].style.left = left+"%";\n'\ 4002 ' }\n'\ 4003 ' }\n'\ 4004 ' }\n'\ 4005 ' var cglist = document.getElementById("callgraphs");\n'\ 4006 ' if(!cglist) return;\n'\ 4007 ' var cg = cglist.getElementsByClassName("atop");\n'\ 4008 ' if(cg.length < 10) return;\n'\ 4009 ' for (var i = 0; i < cg.length; i++) {\n'\ 4010 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\ 4011 ' cg[i].style.display = "block";\n'\ 4012 ' } else {\n'\ 4013 ' cg[i].style.display = "none";\n'\ 4014 ' }\n'\ 4015 ' }\n'\ 4016 ' }\n'\ 4017 ' function devListWindow(e) {\n'\ 4018 ' var win = window.open();\n'\ 4019 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\ 4020 ' "<style type=\\"text/css\\">"+\n'\ 4021 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\ 4022 ' "</style>"\n'\ 4023 ' var dt = devtable[0];\n'\ 4024 ' if(e.target.id != "devlist1")\n'\ 4025 ' dt = devtable[1];\n'\ 4026 ' win.document.write(html+dt);\n'\ 4027 ' }\n'\ 4028 ' function errWindow() {\n'\ 4029 ' var text = this.id;\n'\ 4030 ' var win = window.open();\n'\ 4031 ' win.document.write("<pre>"+text+"</pre>");\n'\ 4032 ' win.document.close();\n'\ 4033 ' }\n'\ 4034 ' function logWindow(e) {\n'\ 4035 ' var name = e.target.id.slice(4);\n'\ 4036 ' var win = window.open();\n'\ 4037 ' var log = document.getElementById(name+"log");\n'\ 4038 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\ 4039 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\ 4040 ' win.document.close();\n'\ 4041 ' }\n'\ 4042 ' function onClickPhase(e) {\n'\ 4043 ' }\n'\ 4044 ' function onMouseDown(e) {\n'\ 4045 ' dragval[0] = e.clientX;\n'\ 4046 ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\ 4047 ' document.onmousemove = onMouseMove;\n'\ 4048 ' }\n'\ 4049 ' function onMouseMove(e) {\n'\ 4050 ' var zoombox = document.getElementById("dmesgzoombox");\n'\ 4051 ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\ 4052 ' }\n'\ 4053 ' function onMouseUp(e) {\n'\ 4054 ' document.onmousemove = null;\n'\ 4055 ' }\n'\ 4056 ' function onKeyPress(e) {\n'\ 4057 ' var c = e.charCode;\n'\ 4058 ' if(c != 42 && c != 43 && c != 45) return;\n'\ 4059 ' var click = document.createEvent("Events");\n'\ 4060 ' click.initEvent("click", true, false);\n'\ 4061 ' if(c == 43) \n'\ 4062 ' document.getElementById("zoomin").dispatchEvent(click);\n'\ 4063 ' else if(c == 45)\n'\ 4064 ' document.getElementById("zoomout").dispatchEvent(click);\n'\ 4065 ' else if(c == 42)\n'\ 4066 ' document.getElementById("zoomdef").dispatchEvent(click);\n'\ 4067 ' }\n'\ 4068 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\ 4069 ' window.addEventListener("load", function () {\n'\ 4070 ' var dmesg = document.getElementById("dmesg");\n'\ 4071 ' dmesg.style.width = "100%"\n'\ 4072 ' dmesg.onmousedown = onMouseDown;\n'\ 4073 ' document.onmouseup = onMouseUp;\n'\ 4074 ' document.onkeypress = onKeyPress;\n'\ 4075 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\ 4076 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\ 4077 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\ 4078 ' var list = document.getElementsByClassName("square");\n'\ 4079 ' for (var i = 0; i < list.length; i++)\n'\ 4080 ' list[i].onclick = onClickPhase;\n'\ 4081 ' var list = document.getElementsByClassName("err");\n'\ 4082 ' for (var i = 0; i < list.length; i++)\n'\ 4083 ' list[i].onclick = errWindow;\n'\ 4084 ' var list = document.getElementsByClassName("logbtn");\n'\ 4085 ' for (var i = 0; i < list.length; i++)\n'\ 4086 ' list[i].onclick = logWindow;\n'\ 4087 ' list = document.getElementsByClassName("devlist");\n'\ 4088 ' for (var i = 0; i < list.length; i++)\n'\ 4089 ' list[i].onclick = devListWindow;\n'\ 4090 ' var dev = dmesg.getElementsByClassName("thread");\n'\ 4091 ' for (var i = 0; i < dev.length; i++) {\n'\ 4092 ' dev[i].onclick = deviceDetail;\n'\ 4093 ' dev[i].onmouseover = deviceHover;\n'\ 4094 ' dev[i].onmouseout = deviceUnhover;\n'\ 4095 ' }\n'\ 4096 ' zoomTimeline();\n'\ 4097 ' });\n'\ 4098 '</script>\n' 4099 hf.write(script_code); 4100 4101# Function: executeSuspend 4102# Description: 4103# Execute system suspend through the sysfs interface, then copy the output 4104# dmesg and ftrace files to the test output directory. 4105def executeSuspend(): 4106 pm = ProcessMonitor() 4107 tp = sysvals.tpath 4108 fwdata = [] 4109 # mark the start point in the kernel ring buffer just as we start 4110 sysvals.initdmesg() 4111 # start ftrace 4112 if(sysvals.usecallgraph or sysvals.usetraceevents): 4113 print('START TRACING') 4114 sysvals.fsetVal('1', 'tracing_on') 4115 if sysvals.useprocmon: 4116 pm.start() 4117 # execute however many s/r runs requested 4118 for count in range(1,sysvals.execcount+1): 4119 # x2delay in between test runs 4120 if(count > 1 and sysvals.x2delay > 0): 4121 sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker') 4122 time.sleep(sysvals.x2delay/1000.0) 4123 sysvals.fsetVal('WAIT END', 'trace_marker') 4124 # start message 4125 if sysvals.testcommand != '': 4126 print('COMMAND START') 4127 else: 4128 if(sysvals.rtcwake): 4129 print('SUSPEND START') 4130 else: 4131 print('SUSPEND START (press a key to resume)') 4132 # set rtcwake 4133 if(sysvals.rtcwake): 4134 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) 4135 sysvals.rtcWakeAlarmOn() 4136 # start of suspend trace marker 4137 if(sysvals.usecallgraph or sysvals.usetraceevents): 4138 sysvals.fsetVal('SUSPEND START', 'trace_marker') 4139 # predelay delay 4140 if(count == 1 and sysvals.predelay > 0): 4141 sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker') 4142 time.sleep(sysvals.predelay/1000.0) 4143 sysvals.fsetVal('WAIT END', 'trace_marker') 4144 # initiate suspend or command 4145 if sysvals.testcommand != '': 4146 call(sysvals.testcommand+' 2>&1', shell=True); 4147 else: 4148 pf = open(sysvals.powerfile, 'w') 4149 pf.write(sysvals.suspendmode) 4150 # execution will pause here 4151 try: 4152 pf.close() 4153 except: 4154 pass 4155 if(sysvals.rtcwake): 4156 sysvals.rtcWakeAlarmOff() 4157 # postdelay delay 4158 if(count == sysvals.execcount and sysvals.postdelay > 0): 4159 sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker') 4160 time.sleep(sysvals.postdelay/1000.0) 4161 sysvals.fsetVal('WAIT END', 'trace_marker') 4162 # return from suspend 4163 print('RESUME COMPLETE') 4164 if(sysvals.usecallgraph or sysvals.usetraceevents): 4165 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') 4166 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): 4167 fwdata.append(getFPDT(False)) 4168 # stop ftrace 4169 if(sysvals.usecallgraph or sysvals.usetraceevents): 4170 if sysvals.useprocmon: 4171 pm.stop() 4172 sysvals.fsetVal('0', 'tracing_on') 4173 print('CAPTURING TRACE') 4174 writeDatafileHeader(sysvals.ftracefile, fwdata) 4175 call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True) 4176 sysvals.fsetVal('', 'trace') 4177 devProps() 4178 # grab a copy of the dmesg output 4179 print('CAPTURING DMESG') 4180 writeDatafileHeader(sysvals.dmesgfile, fwdata) 4181 sysvals.getdmesg() 4182 4183def writeDatafileHeader(filename, fwdata): 4184 fp = open(filename, 'a') 4185 fp.write(sysvals.teststamp+'\n') 4186 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): 4187 for fw in fwdata: 4188 if(fw): 4189 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) 4190 fp.close() 4191 4192# Function: setUSBDevicesAuto 4193# Description: 4194# Set the autosuspend control parameter of all USB devices to auto 4195# This can be dangerous, so use at your own risk, most devices are set 4196# to always-on since the kernel cant determine if the device can 4197# properly autosuspend 4198def setUSBDevicesAuto(): 4199 rootCheck(True) 4200 for dirname, dirnames, filenames in os.walk('/sys/devices'): 4201 if(re.match('.*/usb[0-9]*.*', dirname) and 4202 'idVendor' in filenames and 'idProduct' in filenames): 4203 call('echo auto > %s/power/control' % dirname, shell=True) 4204 name = dirname.split('/')[-1] 4205 desc = Popen(['cat', '%s/product' % dirname], 4206 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') 4207 ctrl = Popen(['cat', '%s/power/control' % dirname], 4208 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') 4209 print('control is %s for %6s: %s' % (ctrl, name, desc)) 4210 4211# Function: yesno 4212# Description: 4213# Print out an equivalent Y or N for a set of known parameter values 4214# Output: 4215# 'Y', 'N', or ' ' if the value is unknown 4216def yesno(val): 4217 yesvals = ['auto', 'enabled', 'active', '1'] 4218 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported'] 4219 if val in yesvals: 4220 return 'Y' 4221 elif val in novals: 4222 return 'N' 4223 return ' ' 4224 4225# Function: ms2nice 4226# Description: 4227# Print out a very concise time string in minutes and seconds 4228# Output: 4229# The time string, e.g. "1901m16s" 4230def ms2nice(val): 4231 ms = 0 4232 try: 4233 ms = int(val) 4234 except: 4235 return 0.0 4236 m = ms / 60000 4237 s = (ms / 1000) - (m * 60) 4238 return '%3dm%2ds' % (m, s) 4239 4240# Function: detectUSB 4241# Description: 4242# Detect all the USB hosts and devices currently connected and add 4243# a list of USB device names to sysvals for better timeline readability 4244def detectUSB(): 4245 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''} 4246 power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'', 4247 'control':'', 'persist':'', 'runtime_enabled':'', 4248 'runtime_status':'', 'runtime_usage':'', 4249 'runtime_active_time':'', 4250 'runtime_suspended_time':'', 4251 'active_duration':'', 4252 'connected_duration':''} 4253 4254 print('LEGEND') 4255 print('---------------------------------------------------------------------------------------------') 4256 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)') 4257 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)') 4258 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)') 4259 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)') 4260 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)') 4261 print(' U = runtime usage count') 4262 print('---------------------------------------------------------------------------------------------') 4263 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT') 4264 print('---------------------------------------------------------------------------------------------') 4265 4266 for dirname, dirnames, filenames in os.walk('/sys/devices'): 4267 if(re.match('.*/usb[0-9]*.*', dirname) and 4268 'idVendor' in filenames and 'idProduct' in filenames): 4269 for i in field: 4270 field[i] = Popen(['cat', '%s/%s' % (dirname, i)], 4271 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') 4272 name = dirname.split('/')[-1] 4273 for i in power: 4274 power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)], 4275 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '') 4276 if(re.match('usb[0-9]*', name)): 4277 first = '%-8s' % name 4278 else: 4279 first = '%8s' % name 4280 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \ 4281 (first, field['idVendor'], field['idProduct'], \ 4282 field['product'][0:20], field['speed'], \ 4283 yesno(power['async']), \ 4284 yesno(power['control']), \ 4285 yesno(power['persist']), \ 4286 yesno(power['runtime_enabled']), \ 4287 yesno(power['runtime_status']), \ 4288 power['runtime_usage'], \ 4289 power['autosuspend'], \ 4290 ms2nice(power['runtime_active_time']), \ 4291 ms2nice(power['runtime_suspended_time']), \ 4292 ms2nice(power['active_duration']), \ 4293 ms2nice(power['connected_duration']))) 4294 4295# Function: devProps 4296# Description: 4297# Retrieve a list of properties for all devices in the trace log 4298def devProps(data=0): 4299 props = dict() 4300 4301 if data: 4302 idx = data.index(': ') + 2 4303 if idx >= len(data): 4304 return 4305 devlist = data[idx:].split(';') 4306 for dev in devlist: 4307 f = dev.split(',') 4308 if len(f) < 3: 4309 continue 4310 dev = f[0] 4311 props[dev] = DevProps() 4312 props[dev].altname = f[1] 4313 if int(f[2]): 4314 props[dev].async = True 4315 else: 4316 props[dev].async = False 4317 sysvals.devprops = props 4318 if sysvals.suspendmode == 'command' and 'testcommandstring' in props: 4319 sysvals.testcommand = props['testcommandstring'].altname 4320 return 4321 4322 if(os.path.exists(sysvals.ftracefile) == False): 4323 doError('%s does not exist' % sysvals.ftracefile) 4324 4325 # first get the list of devices we need properties for 4326 msghead = 'Additional data added by AnalyzeSuspend' 4327 alreadystamped = False 4328 tp = TestProps() 4329 tf = open(sysvals.ftracefile, 'r') 4330 for line in tf: 4331 if msghead in line: 4332 alreadystamped = True 4333 continue 4334 # determine the trace data type (required for further parsing) 4335 m = re.match(sysvals.tracertypefmt, line) 4336 if(m): 4337 tp.setTracerType(m.group('t')) 4338 continue 4339 # parse only valid lines, if this is not one move on 4340 m = re.match(tp.ftrace_line_fmt, line) 4341 if(not m or 'device_pm_callback_start' not in line): 4342 continue 4343 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg')); 4344 if(not m): 4345 continue 4346 dev = m.group('d') 4347 if dev not in props: 4348 props[dev] = DevProps() 4349 tf.close() 4350 4351 if not alreadystamped and sysvals.suspendmode == 'command': 4352 out = '#\n# '+msghead+'\n# Device Properties: ' 4353 out += 'testcommandstring,%s,0;' % (sysvals.testcommand) 4354 with open(sysvals.ftracefile, 'a') as fp: 4355 fp.write(out+'\n') 4356 sysvals.devprops = props 4357 return 4358 4359 # now get the syspath for each of our target devices 4360 for dirname, dirnames, filenames in os.walk('/sys/devices'): 4361 if(re.match('.*/power', dirname) and 'async' in filenames): 4362 dev = dirname.split('/')[-2] 4363 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)): 4364 props[dev].syspath = dirname[:-6] 4365 4366 # now fill in the properties for our target devices 4367 for dev in props: 4368 dirname = props[dev].syspath 4369 if not dirname or not os.path.exists(dirname): 4370 continue 4371 with open(dirname+'/power/async') as fp: 4372 text = fp.read() 4373 props[dev].async = False 4374 if 'enabled' in text: 4375 props[dev].async = True 4376 fields = os.listdir(dirname) 4377 if 'product' in fields: 4378 with open(dirname+'/product') as fp: 4379 props[dev].altname = fp.read() 4380 elif 'name' in fields: 4381 with open(dirname+'/name') as fp: 4382 props[dev].altname = fp.read() 4383 elif 'model' in fields: 4384 with open(dirname+'/model') as fp: 4385 props[dev].altname = fp.read() 4386 elif 'description' in fields: 4387 with open(dirname+'/description') as fp: 4388 props[dev].altname = fp.read() 4389 elif 'id' in fields: 4390 with open(dirname+'/id') as fp: 4391 props[dev].altname = fp.read() 4392 elif 'idVendor' in fields and 'idProduct' in fields: 4393 idv, idp = '', '' 4394 with open(dirname+'/idVendor') as fp: 4395 idv = fp.read().strip() 4396 with open(dirname+'/idProduct') as fp: 4397 idp = fp.read().strip() 4398 props[dev].altname = '%s:%s' % (idv, idp) 4399 4400 if props[dev].altname: 4401 out = props[dev].altname.strip().replace('\n', ' ') 4402 out = out.replace(',', ' ') 4403 out = out.replace(';', ' ') 4404 props[dev].altname = out 4405 4406 # and now write the data to the ftrace file 4407 if not alreadystamped: 4408 out = '#\n# '+msghead+'\n# Device Properties: ' 4409 for dev in sorted(props): 4410 out += props[dev].out(dev) 4411 with open(sysvals.ftracefile, 'a') as fp: 4412 fp.write(out+'\n') 4413 4414 sysvals.devprops = props 4415 4416# Function: getModes 4417# Description: 4418# Determine the supported power modes on this system 4419# Output: 4420# A string list of the available modes 4421def getModes(): 4422 modes = '' 4423 if(os.path.exists(sysvals.powerfile)): 4424 fp = open(sysvals.powerfile, 'r') 4425 modes = string.split(fp.read()) 4426 fp.close() 4427 return modes 4428 4429# Function: getFPDT 4430# Description: 4431# Read the acpi bios tables and pull out FPDT, the firmware data 4432# Arguments: 4433# output: True to output the info to stdout, False otherwise 4434def getFPDT(output): 4435 rectype = {} 4436 rectype[0] = 'Firmware Basic Boot Performance Record' 4437 rectype[1] = 'S3 Performance Table Record' 4438 prectype = {} 4439 prectype[0] = 'Basic S3 Resume Performance Record' 4440 prectype[1] = 'Basic S3 Suspend Performance Record' 4441 4442 rootCheck(True) 4443 if(not os.path.exists(sysvals.fpdtpath)): 4444 if(output): 4445 doError('file does not exist: %s' % sysvals.fpdtpath) 4446 return False 4447 if(not os.access(sysvals.fpdtpath, os.R_OK)): 4448 if(output): 4449 doError('file is not readable: %s' % sysvals.fpdtpath) 4450 return False 4451 if(not os.path.exists(sysvals.mempath)): 4452 if(output): 4453 doError('file does not exist: %s' % sysvals.mempath) 4454 return False 4455 if(not os.access(sysvals.mempath, os.R_OK)): 4456 if(output): 4457 doError('file is not readable: %s' % sysvals.mempath) 4458 return False 4459 4460 fp = open(sysvals.fpdtpath, 'rb') 4461 buf = fp.read() 4462 fp.close() 4463 4464 if(len(buf) < 36): 4465 if(output): 4466 doError('Invalid FPDT table data, should '+\ 4467 'be at least 36 bytes') 4468 return False 4469 4470 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36]) 4471 if(output): 4472 print('') 4473 print('Firmware Performance Data Table (%s)' % table[0]) 4474 print(' Signature : %s' % table[0]) 4475 print(' Table Length : %u' % table[1]) 4476 print(' Revision : %u' % table[2]) 4477 print(' Checksum : 0x%x' % table[3]) 4478 print(' OEM ID : %s' % table[4]) 4479 print(' OEM Table ID : %s' % table[5]) 4480 print(' OEM Revision : %u' % table[6]) 4481 print(' Creator ID : %s' % table[7]) 4482 print(' Creator Revision : 0x%x' % table[8]) 4483 print('') 4484 4485 if(table[0] != 'FPDT'): 4486 if(output): 4487 doError('Invalid FPDT table') 4488 return False 4489 if(len(buf) <= 36): 4490 return False 4491 i = 0 4492 fwData = [0, 0] 4493 records = buf[36:] 4494 fp = open(sysvals.mempath, 'rb') 4495 while(i < len(records)): 4496 header = struct.unpack('HBB', records[i:i+4]) 4497 if(header[0] not in rectype): 4498 i += header[1] 4499 continue 4500 if(header[1] != 16): 4501 i += header[1] 4502 continue 4503 addr = struct.unpack('Q', records[i+8:i+16])[0] 4504 try: 4505 fp.seek(addr) 4506 first = fp.read(8) 4507 except: 4508 if(output): 4509 print('Bad address 0x%x in %s' % (addr, sysvals.mempath)) 4510 return [0, 0] 4511 rechead = struct.unpack('4sI', first) 4512 recdata = fp.read(rechead[1]-8) 4513 if(rechead[0] == 'FBPT'): 4514 record = struct.unpack('HBBIQQQQQ', recdata) 4515 if(output): 4516 print('%s (%s)' % (rectype[header[0]], rechead[0])) 4517 print(' Reset END : %u ns' % record[4]) 4518 print(' OS Loader LoadImage Start : %u ns' % record[5]) 4519 print(' OS Loader StartImage Start : %u ns' % record[6]) 4520 print(' ExitBootServices Entry : %u ns' % record[7]) 4521 print(' ExitBootServices Exit : %u ns' % record[8]) 4522 elif(rechead[0] == 'S3PT'): 4523 if(output): 4524 print('%s (%s)' % (rectype[header[0]], rechead[0])) 4525 j = 0 4526 while(j < len(recdata)): 4527 prechead = struct.unpack('HBB', recdata[j:j+4]) 4528 if(prechead[0] not in prectype): 4529 continue 4530 if(prechead[0] == 0): 4531 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]]) 4532 fwData[1] = record[2] 4533 if(output): 4534 print(' %s' % prectype[prechead[0]]) 4535 print(' Resume Count : %u' % \ 4536 record[1]) 4537 print(' FullResume : %u ns' % \ 4538 record[2]) 4539 print(' AverageResume : %u ns' % \ 4540 record[3]) 4541 elif(prechead[0] == 1): 4542 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]]) 4543 fwData[0] = record[1] - record[0] 4544 if(output): 4545 print(' %s' % prectype[prechead[0]]) 4546 print(' SuspendStart : %u ns' % \ 4547 record[0]) 4548 print(' SuspendEnd : %u ns' % \ 4549 record[1]) 4550 print(' SuspendTime : %u ns' % \ 4551 fwData[0]) 4552 j += prechead[1] 4553 if(output): 4554 print('') 4555 i += header[1] 4556 fp.close() 4557 return fwData 4558 4559# Function: statusCheck 4560# Description: 4561# Verify that the requested command and options will work, and 4562# print the results to the terminal 4563# Output: 4564# True if the test will work, False if not 4565def statusCheck(probecheck=False): 4566 status = True 4567 4568 print('Checking this system (%s)...' % platform.node()) 4569 4570 # check we have root access 4571 res = sysvals.colorText('NO (No features of this tool will work!)') 4572 if(rootCheck(False)): 4573 res = 'YES' 4574 print(' have root access: %s' % res) 4575 if(res != 'YES'): 4576 print(' Try running this script with sudo') 4577 return False 4578 4579 # check sysfs is mounted 4580 res = sysvals.colorText('NO (No features of this tool will work!)') 4581 if(os.path.exists(sysvals.powerfile)): 4582 res = 'YES' 4583 print(' is sysfs mounted: %s' % res) 4584 if(res != 'YES'): 4585 return False 4586 4587 # check target mode is a valid mode 4588 if sysvals.suspendmode != 'command': 4589 res = sysvals.colorText('NO') 4590 modes = getModes() 4591 if(sysvals.suspendmode in modes): 4592 res = 'YES' 4593 else: 4594 status = False 4595 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 4596 if(res == 'NO'): 4597 print(' valid power modes are: %s' % modes) 4598 print(' please choose one with -m') 4599 4600 # check if ftrace is available 4601 res = sysvals.colorText('NO') 4602 ftgood = sysvals.verifyFtrace() 4603 if(ftgood): 4604 res = 'YES' 4605 elif(sysvals.usecallgraph): 4606 status = False 4607 print(' is ftrace supported: %s' % res) 4608 4609 # check if kprobes are available 4610 res = sysvals.colorText('NO') 4611 sysvals.usekprobes = sysvals.verifyKprobes() 4612 if(sysvals.usekprobes): 4613 res = 'YES' 4614 else: 4615 sysvals.usedevsrc = False 4616 print(' are kprobes supported: %s' % res) 4617 4618 # what data source are we using 4619 res = 'DMESG' 4620 if(ftgood): 4621 sysvals.usetraceeventsonly = True 4622 sysvals.usetraceevents = False 4623 for e in sysvals.traceevents: 4624 check = False 4625 if(os.path.exists(sysvals.epath+e)): 4626 check = True 4627 if(not check): 4628 sysvals.usetraceeventsonly = False 4629 if(e == 'suspend_resume' and check): 4630 sysvals.usetraceevents = True 4631 if(sysvals.usetraceevents and sysvals.usetraceeventsonly): 4632 res = 'FTRACE (all trace events found)' 4633 elif(sysvals.usetraceevents): 4634 res = 'DMESG and FTRACE (suspend_resume trace event found)' 4635 print(' timeline data source: %s' % res) 4636 4637 # check if rtcwake 4638 res = sysvals.colorText('NO') 4639 if(sysvals.rtcpath != ''): 4640 res = 'YES' 4641 elif(sysvals.rtcwake): 4642 status = False 4643 print(' is rtcwake supported: %s' % res) 4644 4645 if not probecheck: 4646 return status 4647 4648 # verify kprobes 4649 if sysvals.usekprobes: 4650 for name in sysvals.tracefuncs: 4651 sysvals.defaultKprobe(name, sysvals.tracefuncs[name]) 4652 if sysvals.usedevsrc: 4653 for name in sysvals.dev_tracefuncs: 4654 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name]) 4655 sysvals.addKprobes(True) 4656 4657 return status 4658 4659# Function: doError 4660# Description: 4661# generic error function for catastrphic failures 4662# Arguments: 4663# msg: the error message to print 4664# help: True if printHelp should be called after, False otherwise 4665def doError(msg, help=False): 4666 if(help == True): 4667 printHelp() 4668 print('ERROR: %s\n') % msg 4669 sys.exit() 4670 4671# Function: rootCheck 4672# Description: 4673# quick check to see if we have root access 4674def rootCheck(fatal): 4675 if(os.access(sysvals.powerfile, os.W_OK)): 4676 return True 4677 if fatal: 4678 doError('This command must be run as root') 4679 return False 4680 4681# Function: getArgInt 4682# Description: 4683# pull out an integer argument from the command line with checks 4684def getArgInt(name, args, min, max, main=True): 4685 if main: 4686 try: 4687 arg = args.next() 4688 except: 4689 doError(name+': no argument supplied', True) 4690 else: 4691 arg = args 4692 try: 4693 val = int(arg) 4694 except: 4695 doError(name+': non-integer value given', True) 4696 if(val < min or val > max): 4697 doError(name+': value should be between %d and %d' % (min, max), True) 4698 return val 4699 4700# Function: getArgFloat 4701# Description: 4702# pull out a float argument from the command line with checks 4703def getArgFloat(name, args, min, max, main=True): 4704 if main: 4705 try: 4706 arg = args.next() 4707 except: 4708 doError(name+': no argument supplied', True) 4709 else: 4710 arg = args 4711 try: 4712 val = float(arg) 4713 except: 4714 doError(name+': non-numerical value given', True) 4715 if(val < min or val > max): 4716 doError(name+': value should be between %f and %f' % (min, max), True) 4717 return val 4718 4719def processData(): 4720 print('PROCESSING DATA') 4721 if(sysvals.usetraceeventsonly): 4722 testruns = parseTraceLog() 4723 if sysvals.dmesgfile: 4724 dmesgtext = loadKernelLog(True) 4725 for data in testruns: 4726 data.extractErrorInfo(dmesgtext) 4727 else: 4728 testruns = loadKernelLog() 4729 for data in testruns: 4730 parseKernelLog(data) 4731 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)): 4732 appendIncompleteTraceLog(testruns) 4733 createHTML(testruns) 4734 4735# Function: rerunTest 4736# Description: 4737# generate an output from an existing set of ftrace/dmesg logs 4738def rerunTest(): 4739 if sysvals.ftracefile: 4740 doesTraceLogHaveTraceEvents() 4741 if not sysvals.dmesgfile and not sysvals.usetraceeventsonly: 4742 doError('recreating this html output requires a dmesg file') 4743 sysvals.setOutputFile() 4744 vprint('Output file: %s' % sysvals.htmlfile) 4745 if(os.path.exists(sysvals.htmlfile) and not os.access(sysvals.htmlfile, os.W_OK)): 4746 doError('missing permission to write to %s' % sysvals.htmlfile) 4747 processData() 4748 4749# Function: runTest 4750# Description: 4751# execute a suspend/resume, gather the logs, and generate the output 4752def runTest(subdir, testpath=''): 4753 # prepare for the test 4754 sysvals.initFtrace() 4755 sysvals.initTestOutput(subdir, testpath) 4756 vprint('Output files:\n\t%s\n\t%s\n\t%s' % \ 4757 (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile)) 4758 4759 # execute the test 4760 executeSuspend() 4761 sysvals.cleanupFtrace() 4762 processData() 4763 4764 # if running as root, change output dir owner to sudo_user 4765 if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \ 4766 'SUDO_USER' in os.environ: 4767 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' 4768 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True) 4769 4770# Function: runSummary 4771# Description: 4772# create a summary of tests in a sub-directory 4773def runSummary(subdir, output): 4774 # get a list of ftrace output files 4775 files = [] 4776 for dirname, dirnames, filenames in os.walk(subdir): 4777 for filename in filenames: 4778 if(re.match('.*_ftrace.txt', filename)): 4779 files.append("%s/%s" % (dirname, filename)) 4780 4781 # process the files in order and get an array of data objects 4782 testruns = [] 4783 for file in sorted(files): 4784 if output: 4785 print("Test found in %s" % os.path.dirname(file)) 4786 sysvals.ftracefile = file 4787 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt') 4788 doesTraceLogHaveTraceEvents() 4789 sysvals.usecallgraph = False 4790 if not sysvals.usetraceeventsonly: 4791 if(not os.path.exists(sysvals.dmesgfile)): 4792 print("Skipping %s: not a valid test input" % file) 4793 continue 4794 else: 4795 if output: 4796 f = os.path.basename(sysvals.ftracefile) 4797 d = os.path.basename(sysvals.dmesgfile) 4798 print("\tInput files: %s and %s" % (f, d)) 4799 testdata = loadKernelLog() 4800 data = testdata[0] 4801 parseKernelLog(data) 4802 testdata = [data] 4803 appendIncompleteTraceLog(testdata) 4804 else: 4805 if output: 4806 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile)) 4807 testdata = parseTraceLog() 4808 data = testdata[0] 4809 data.normalizeTime(data.tSuspended) 4810 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html') 4811 data.outfile = link 4812 testruns.append(data) 4813 4814 createHTMLSummarySimple(testruns, subdir+'/summary.html') 4815 4816# Function: checkArgBool 4817# Description: 4818# check if a boolean string value is true or false 4819def checkArgBool(value): 4820 yes = ['1', 'true', 'yes', 'on'] 4821 if value.lower() in yes: 4822 return True 4823 return False 4824 4825# Function: configFromFile 4826# Description: 4827# Configure the script via the info in a config file 4828def configFromFile(file): 4829 Config = ConfigParser.ConfigParser() 4830 4831 Config.read(file) 4832 sections = Config.sections() 4833 overridekprobes = False 4834 overridedevkprobes = False 4835 if 'Settings' in sections: 4836 for opt in Config.options('Settings'): 4837 value = Config.get('Settings', opt).lower() 4838 if(opt.lower() == 'verbose'): 4839 sysvals.verbose = checkArgBool(value) 4840 elif(opt.lower() == 'addlogs'): 4841 sysvals.addlogs = checkArgBool(value) 4842 elif(opt.lower() == 'dev'): 4843 sysvals.usedevsrc = checkArgBool(value) 4844 elif(opt.lower() == 'proc'): 4845 sysvals.useprocmon = checkArgBool(value) 4846 elif(opt.lower() == 'x2'): 4847 if checkArgBool(value): 4848 sysvals.execcount = 2 4849 elif(opt.lower() == 'callgraph'): 4850 sysvals.usecallgraph = checkArgBool(value) 4851 elif(opt.lower() == 'override-timeline-functions'): 4852 overridekprobes = checkArgBool(value) 4853 elif(opt.lower() == 'override-dev-timeline-functions'): 4854 overridedevkprobes = checkArgBool(value) 4855 elif(opt.lower() == 'devicefilter'): 4856 sysvals.setDeviceFilter(value) 4857 elif(opt.lower() == 'expandcg'): 4858 sysvals.cgexp = checkArgBool(value) 4859 elif(opt.lower() == 'srgap'): 4860 if checkArgBool(value): 4861 sysvals.srgap = 5 4862 elif(opt.lower() == 'mode'): 4863 sysvals.suspendmode = value 4864 elif(opt.lower() == 'command'): 4865 sysvals.testcommand = value 4866 elif(opt.lower() == 'x2delay'): 4867 sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False) 4868 elif(opt.lower() == 'predelay'): 4869 sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False) 4870 elif(opt.lower() == 'postdelay'): 4871 sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False) 4872 elif(opt.lower() == 'rtcwake'): 4873 sysvals.rtcwake = True 4874 sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False) 4875 elif(opt.lower() == 'timeprec'): 4876 sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False)) 4877 elif(opt.lower() == 'mindev'): 4878 sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False) 4879 elif(opt.lower() == 'callloop-maxgap'): 4880 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False) 4881 elif(opt.lower() == 'callloop-maxlen'): 4882 sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False) 4883 elif(opt.lower() == 'mincg'): 4884 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False) 4885 elif(opt.lower() == 'output-dir'): 4886 sysvals.setOutputFolder(value) 4887 4888 if sysvals.suspendmode == 'command' and not sysvals.testcommand: 4889 doError('No command supplied for mode "command"') 4890 4891 # compatibility errors 4892 if sysvals.usedevsrc and sysvals.usecallgraph: 4893 doError('-dev is not compatible with -f') 4894 if sysvals.usecallgraph and sysvals.useprocmon: 4895 doError('-proc is not compatible with -f') 4896 4897 if overridekprobes: 4898 sysvals.tracefuncs = dict() 4899 if overridedevkprobes: 4900 sysvals.dev_tracefuncs = dict() 4901 4902 kprobes = dict() 4903 kprobesec = 'dev_timeline_functions_'+platform.machine() 4904 if kprobesec in sections: 4905 for name in Config.options(kprobesec): 4906 text = Config.get(kprobesec, name) 4907 kprobes[name] = (text, True) 4908 kprobesec = 'timeline_functions_'+platform.machine() 4909 if kprobesec in sections: 4910 for name in Config.options(kprobesec): 4911 if name in kprobes: 4912 doError('Duplicate timeline function found "%s"' % (name)) 4913 text = Config.get(kprobesec, name) 4914 kprobes[name] = (text, False) 4915 4916 for name in kprobes: 4917 function = name 4918 format = name 4919 color = '' 4920 args = dict() 4921 text, dev = kprobes[name] 4922 data = text.split() 4923 i = 0 4924 for val in data: 4925 # bracketted strings are special formatting, read them separately 4926 if val[0] == '[' and val[-1] == ']': 4927 for prop in val[1:-1].split(','): 4928 p = prop.split('=') 4929 if p[0] == 'color': 4930 try: 4931 color = int(p[1], 16) 4932 color = '#'+p[1] 4933 except: 4934 color = p[1] 4935 continue 4936 # first real arg should be the format string 4937 if i == 0: 4938 format = val 4939 # all other args are actual function args 4940 else: 4941 d = val.split('=') 4942 args[d[0]] = d[1] 4943 i += 1 4944 if not function or not format: 4945 doError('Invalid kprobe: %s' % name) 4946 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format): 4947 if arg not in args: 4948 doError('Kprobe "%s" is missing argument "%s"' % (name, arg)) 4949 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs): 4950 doError('Duplicate timeline function found "%s"' % (name)) 4951 4952 kp = { 4953 'name': name, 4954 'func': function, 4955 'format': format, 4956 sysvals.archargs: args 4957 } 4958 if color: 4959 kp['color'] = color 4960 if dev: 4961 sysvals.dev_tracefuncs[name] = kp 4962 else: 4963 sysvals.tracefuncs[name] = kp 4964 4965# Function: printHelp 4966# Description: 4967# print out the help text 4968def printHelp(): 4969 modes = getModes() 4970 4971 print('') 4972 print('AnalyzeSuspend v%s' % sysvals.version) 4973 print('Usage: sudo analyze_suspend.py <options>') 4974 print('') 4975 print('Description:') 4976 print(' This tool is designed to assist kernel and OS developers in optimizing') 4977 print(' their linux stack\'s suspend/resume time. Using a kernel image built') 4978 print(' with a few extra options enabled, the tool will execute a suspend and') 4979 print(' capture dmesg and ftrace data until resume is complete. This data is') 4980 print(' transformed into a device timeline and an optional callgraph to give') 4981 print(' a detailed view of which devices/subsystems are taking the most') 4982 print(' time in suspend/resume.') 4983 print('') 4984 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS') 4985 print(' HTML output: <hostname>_<mode>.html') 4986 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt') 4987 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt') 4988 print('') 4989 print('Options:') 4990 print(' [general]') 4991 print(' -h Print this help text') 4992 print(' -v Print the current tool version') 4993 print(' -config fn Pull arguments and config options from file fn') 4994 print(' -verbose Print extra information during execution and analysis') 4995 print(' -status Test to see if the system is enabled to run this tool') 4996 print(' -modes List available suspend modes') 4997 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode) 4998 print(' -o subdir Override the output subdirectory') 4999 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)') 5000 print(' -addlogs Add the dmesg and ftrace logs to the html output') 5001 print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)') 5002 print(' [advanced]') 5003 print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"') 5004 print(' -proc Add usermode process info into the timeline (default: disabled)') 5005 print(' -dev Add kernel function calls and threads to the timeline (default: disabled)') 5006 print(' -x2 Run two suspend/resumes back to back (default: disabled)') 5007 print(' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)') 5008 print(' -predelay t Include t ms delay before 1st suspend (default: 0 ms)') 5009 print(' -postdelay t Include t ms delay after last resume (default: 0 ms)') 5010 print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)') 5011 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will') 5012 print(' be created in a new subdirectory with a summary page.') 5013 print(' [debug]') 5014 print(' -f Use ftrace to create device callgraphs (default: disabled)') 5015 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') 5016 print(' -flist Print the list of functions currently being captured in ftrace') 5017 print(' -flistall Print all functions capable of being captured in ftrace') 5018 print(' -fadd file Add functions to be graphed in the timeline from a list in a text file') 5019 print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names') 5020 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') 5021 print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)') 5022 print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)') 5023 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)') 5024 print(' [utilities]') 5025 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') 5026 print(' -usbtopo Print out the current USB topology with power info') 5027 print(' -usbauto Enable autosuspend for all connected USB devices') 5028 print(' [re-analyze data from previous runs]') 5029 print(' -ftrace ftracefile Create HTML output using ftrace input') 5030 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)') 5031 print(' -summary directory Create a summary of all test in this dir') 5032 print('') 5033 return True 5034 5035# ----------------- MAIN -------------------- 5036# exec start (skipped if script is loaded as library) 5037if __name__ == '__main__': 5038 cmd = '' 5039 cmdarg = '' 5040 multitest = {'run': False, 'count': 0, 'delay': 0} 5041 simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status'] 5042 # loop through the command line arguments 5043 args = iter(sys.argv[1:]) 5044 for arg in args: 5045 if(arg == '-m'): 5046 try: 5047 val = args.next() 5048 except: 5049 doError('No mode supplied', True) 5050 if val == 'command' and not sysvals.testcommand: 5051 doError('No command supplied for mode "command"', True) 5052 sysvals.suspendmode = val 5053 elif(arg in simplecmds): 5054 cmd = arg[1:] 5055 elif(arg == '-h'): 5056 printHelp() 5057 sys.exit() 5058 elif(arg == '-v'): 5059 print("Version %s" % sysvals.version) 5060 sys.exit() 5061 elif(arg == '-x2'): 5062 sysvals.execcount = 2 5063 elif(arg == '-x2delay'): 5064 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000) 5065 elif(arg == '-predelay'): 5066 sysvals.predelay = getArgInt('-predelay', args, 0, 60000) 5067 elif(arg == '-postdelay'): 5068 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000) 5069 elif(arg == '-f'): 5070 sysvals.usecallgraph = True 5071 elif(arg == '-addlogs'): 5072 sysvals.addlogs = True 5073 elif(arg == '-verbose'): 5074 sysvals.verbose = True 5075 elif(arg == '-proc'): 5076 sysvals.useprocmon = True 5077 elif(arg == '-dev'): 5078 sysvals.usedevsrc = True 5079 elif(arg == '-rtcwake'): 5080 sysvals.rtcwake = True 5081 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600) 5082 elif(arg == '-timeprec'): 5083 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6)) 5084 elif(arg == '-mindev'): 5085 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0) 5086 elif(arg == '-mincg'): 5087 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0) 5088 elif(arg == '-cgtest'): 5089 sysvals.cgtest = getArgInt('-cgtest', args, 0, 1) 5090 elif(arg == '-cgphase'): 5091 try: 5092 val = args.next() 5093 except: 5094 doError('No phase name supplied', True) 5095 d = Data(0) 5096 if val not in d.phases: 5097 doError('Invalid phase, valid phaess are %s' % d.phases, True) 5098 sysvals.cgphase = val 5099 elif(arg == '-callloop-maxgap'): 5100 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0) 5101 elif(arg == '-callloop-maxlen'): 5102 sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0) 5103 elif(arg == '-cmd'): 5104 try: 5105 val = args.next() 5106 except: 5107 doError('No command string supplied', True) 5108 sysvals.testcommand = val 5109 sysvals.suspendmode = 'command' 5110 elif(arg == '-expandcg'): 5111 sysvals.cgexp = True 5112 elif(arg == '-srgap'): 5113 sysvals.srgap = 5 5114 elif(arg == '-multi'): 5115 multitest['run'] = True 5116 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000) 5117 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600) 5118 elif(arg == '-o'): 5119 try: 5120 val = args.next() 5121 except: 5122 doError('No subdirectory name supplied', True) 5123 sysvals.setOutputFolder(val) 5124 elif(arg == '-config'): 5125 try: 5126 val = args.next() 5127 except: 5128 doError('No text file supplied', True) 5129 if(os.path.exists(val) == False): 5130 doError('%s does not exist' % val) 5131 configFromFile(val) 5132 elif(arg == '-fadd'): 5133 try: 5134 val = args.next() 5135 except: 5136 doError('No text file supplied', True) 5137 if(os.path.exists(val) == False): 5138 doError('%s does not exist' % val) 5139 sysvals.addFtraceFilterFunctions(val) 5140 elif(arg == '-dmesg'): 5141 try: 5142 val = args.next() 5143 except: 5144 doError('No dmesg file supplied', True) 5145 sysvals.notestrun = True 5146 sysvals.dmesgfile = val 5147 if(os.path.exists(sysvals.dmesgfile) == False): 5148 doError('%s does not exist' % sysvals.dmesgfile) 5149 elif(arg == '-ftrace'): 5150 try: 5151 val = args.next() 5152 except: 5153 doError('No ftrace file supplied', True) 5154 sysvals.notestrun = True 5155 sysvals.ftracefile = val 5156 if(os.path.exists(sysvals.ftracefile) == False): 5157 doError('%s does not exist' % sysvals.ftracefile) 5158 elif(arg == '-summary'): 5159 try: 5160 val = args.next() 5161 except: 5162 doError('No directory supplied', True) 5163 cmd = 'summary' 5164 cmdarg = val 5165 sysvals.notestrun = True 5166 if(os.path.isdir(val) == False): 5167 doError('%s is not accesible' % val) 5168 elif(arg == '-filter'): 5169 try: 5170 val = args.next() 5171 except: 5172 doError('No devnames supplied', True) 5173 sysvals.setDeviceFilter(val) 5174 else: 5175 doError('Invalid argument: '+arg, True) 5176 5177 # compatibility errors 5178 if(sysvals.usecallgraph and sysvals.usedevsrc): 5179 doError('-dev is not compatible with -f') 5180 if(sysvals.usecallgraph and sysvals.useprocmon): 5181 doError('-proc is not compatible with -f') 5182 5183 # callgraph size cannot exceed device size 5184 if sysvals.mincglen < sysvals.mindevlen: 5185 sysvals.mincglen = sysvals.mindevlen 5186 5187 # just run a utility command and exit 5188 if(cmd != ''): 5189 if(cmd == 'status'): 5190 statusCheck(True) 5191 elif(cmd == 'fpdt'): 5192 getFPDT(True) 5193 elif(cmd == 'usbtopo'): 5194 detectUSB() 5195 elif(cmd == 'modes'): 5196 print getModes() 5197 elif(cmd == 'flist'): 5198 sysvals.getFtraceFilterFunctions(True) 5199 elif(cmd == 'flistall'): 5200 sysvals.getFtraceFilterFunctions(False) 5201 elif(cmd == 'usbauto'): 5202 setUSBDevicesAuto() 5203 elif(cmd == 'summary'): 5204 print("Generating a summary of folder \"%s\"" % cmdarg) 5205 runSummary(cmdarg, True) 5206 sys.exit() 5207 5208 # if instructed, re-analyze existing data files 5209 if(sysvals.notestrun): 5210 rerunTest() 5211 sys.exit() 5212 5213 # verify that we can run a test 5214 if(not statusCheck()): 5215 print('Check FAILED, aborting the test run!') 5216 sys.exit() 5217 5218 if multitest['run']: 5219 # run multiple tests in a separate subdirectory 5220 s = 'x%d' % multitest['count'] 5221 if not sysvals.outdir: 5222 sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S') 5223 if not os.path.isdir(sysvals.outdir): 5224 os.mkdir(sysvals.outdir) 5225 for i in range(multitest['count']): 5226 if(i != 0): 5227 print('Waiting %d seconds...' % (multitest['delay'])) 5228 time.sleep(multitest['delay']) 5229 print('TEST (%d/%d) START' % (i+1, multitest['count'])) 5230 runTest(sysvals.outdir) 5231 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count'])) 5232 runSummary(sysvals.outdir, False) 5233 else: 5234 # run the test in the current directory 5235 runTest('.', sysvals.outdir)