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