scripts/analyze_suspend.py

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