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