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