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