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