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