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 left = zoombox.scrollLeft;\n'\
3850         '               var val = parseFloat(dmesg.style.width);\n'\
3851         '               var newval = 100;\n'\
3852         '               var sh = window.outerWidth / 2;\n'\
3853         '               if(this.id == "zoomin") {\n'\
3854         '                       newval = val * 1.2;\n'\
3855         '                       if(newval > 910034) newval = 910034;\n'\
3856         '                       dmesg.style.width = newval+"%";\n'\
3857         '                       zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
3858         '               } else if (this.id == "zoomout") {\n'\
3859         '                       newval = val / 1.2;\n'\
3860         '                       if(newval < 100) newval = 100;\n'\
3861         '                       dmesg.style.width = newval+"%";\n'\
3862         '                       zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
3863         '               } else {\n'\
3864         '                       zoombox.scrollLeft = 0;\n'\
3865         '                       dmesg.style.width = "100%";\n'\
3866         '               }\n'\
3867         '               var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
3868         '               var t0 = bounds[0];\n'\
3869         '               var tMax = bounds[1];\n'\
3870         '               var tTotal = tMax - t0;\n'\
3871         '               var wTotal = tTotal * 100.0 / newval;\n'\
3872         '               var idx = 7*window.innerWidth/1100;\n'\
3873         '               for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
3874         '               if(i >= tS.length) i = tS.length - 1;\n'\
3875         '               if(tS[i] == resolution) return;\n'\
3876         '               resolution = tS[i];\n'\
3877         '               redrawTimescale(t0, tMax, tS[i]);\n'\
3878         '       }\n'\
3879         '       function deviceName(title) {\n'\
3880         '               var name = title.slice(0, title.indexOf(" ("));\n'\
3881         '               return name;\n'\
3882         '       }\n'\
3883         '       function deviceHover() {\n'\
3884         '               var name = deviceName(this.title);\n'\
3885         '               var dmesg = document.getElementById("dmesg");\n'\
3886         '               var dev = dmesg.getElementsByClassName("thread");\n'\
3887         '               var cpu = -1;\n'\
3888         '               if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3889         '                       cpu = parseInt(name.slice(7));\n'\
3890         '               else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3891         '                       cpu = parseInt(name.slice(8));\n'\
3892         '               for (var i = 0; i < dev.length; i++) {\n'\
3893         '                       dname = deviceName(dev[i].title);\n'\
3894         '                       var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3895         '                       if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3896         '                               (name == dname))\n'\
3897         '                       {\n'\
3898         '                               dev[i].className = "hover "+cname;\n'\
3899         '                       } else {\n'\
3900         '                               dev[i].className = cname;\n'\
3901         '                       }\n'\
3902         '               }\n'\
3903         '       }\n'\
3904         '       function deviceUnhover() {\n'\
3905         '               var dmesg = document.getElementById("dmesg");\n'\
3906         '               var dev = dmesg.getElementsByClassName("thread");\n'\
3907         '               for (var i = 0; i < dev.length; i++) {\n'\
3908         '                       dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3909         '               }\n'\
3910         '       }\n'\
3911         '       function deviceTitle(title, total, cpu) {\n'\
3912         '               var prefix = "Total";\n'\
3913         '               if(total.length > 3) {\n'\
3914         '                       prefix = "Average";\n'\
3915         '                       total[1] = (total[1]+total[3])/2;\n'\
3916         '                       total[2] = (total[2]+total[4])/2;\n'\
3917         '               }\n'\
3918         '               var devtitle = document.getElementById("devicedetailtitle");\n'\
3919         '               var name = deviceName(title);\n'\
3920         '               if(cpu >= 0) name = "CPU"+cpu;\n'\
3921         '               var driver = "";\n'\
3922         '               var tS = "<t2>(</t2>";\n'\
3923         '               var tR = "<t2>)</t2>";\n'\
3924         '               if(total[1] > 0)\n'\
3925         '                       tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
3926         '               if(total[2] > 0)\n'\
3927         '                       tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
3928         '               var s = title.indexOf("{");\n'\
3929         '               var e = title.indexOf("}");\n'\
3930         '               if((s >= 0) && (e >= 0))\n'\
3931         '                       driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
3932         '               if(total[1] > 0 && total[2] > 0)\n'\
3933         '                       devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
3934         '               else\n'\
3935         '                       devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
3936         '               return name;\n'\
3937         '       }\n'\
3938         '       function deviceDetail() {\n'\
3939         '               var devinfo = document.getElementById("devicedetail");\n'\
3940         '               devinfo.style.display = "block";\n'\
3941         '               var name = deviceName(this.title);\n'\
3942         '               var cpu = -1;\n'\
3943         '               if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3944         '                       cpu = parseInt(name.slice(7));\n'\
3945         '               else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3946         '                       cpu = parseInt(name.slice(8));\n'\
3947         '               var dmesg = document.getElementById("dmesg");\n'\
3948         '               var dev = dmesg.getElementsByClassName("thread");\n'\
3949         '               var idlist = [];\n'\
3950         '               var pdata = [[]];\n'\
3951         '               if(document.getElementById("devicedetail1"))\n'\
3952         '                       pdata = [[], []];\n'\
3953         '               var pd = pdata[0];\n'\
3954         '               var total = [0.0, 0.0, 0.0];\n'\
3955         '               for (var i = 0; i < dev.length; i++) {\n'\
3956         '                       dname = deviceName(dev[i].title);\n'\
3957         '                       if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3958         '                               (name == dname))\n'\
3959         '                       {\n'\
3960         '                               idlist[idlist.length] = dev[i].id;\n'\
3961         '                               var tidx = 1;\n'\
3962         '                               if(dev[i].id[0] == "a") {\n'\
3963         '                                       pd = pdata[0];\n'\
3964         '                               } else {\n'\
3965         '                                       if(pdata.length == 1) pdata[1] = [];\n'\
3966         '                                       if(total.length == 3) total[3]=total[4]=0.0;\n'\
3967         '                                       pd = pdata[1];\n'\
3968         '                                       tidx = 3;\n'\
3969         '                               }\n'\
3970         '                               var info = dev[i].title.split(" ");\n'\
3971         '                               var pname = info[info.length-1];\n'\
3972         '                               pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
3973         '                               total[0] += pd[pname];\n'\
3974         '                               if(pname.indexOf("suspend") >= 0)\n'\
3975         '                                       total[tidx] += pd[pname];\n'\
3976         '                               else\n'\
3977         '                                       total[tidx+1] += pd[pname];\n'\
3978         '                       }\n'\
3979         '               }\n'\
3980         '               var devname = deviceTitle(this.title, total, cpu);\n'\
3981         '               var left = 0.0;\n'\
3982         '               for (var t = 0; t < pdata.length; t++) {\n'\
3983         '                       pd = pdata[t];\n'\
3984         '                       devinfo = document.getElementById("devicedetail"+t);\n'\
3985         '                       var phases = devinfo.getElementsByClassName("phaselet");\n'\
3986         '                       for (var i = 0; i < phases.length; i++) {\n'\
3987         '                               if(phases[i].id in pd) {\n'\
3988         '                                       var w = 100.0*pd[phases[i].id]/total[0];\n'\
3989         '                                       var fs = 32;\n'\
3990         '                                       if(w < 8) fs = 4*w | 0;\n'\
3991         '                                       var fs2 = fs*3/4;\n'\
3992         '                                       phases[i].style.width = w+"%";\n'\
3993         '                                       phases[i].style.left = left+"%";\n'\
3994         '                                       phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
3995         '                                       left += w;\n'\
3996         '                                       var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
3997         '                                       var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\
3998         '                                       phases[i].innerHTML = time+pname;\n'\
3999         '                               } else {\n'\
4000         '                                       phases[i].style.width = "0%";\n'\
4001         '                                       phases[i].style.left = left+"%";\n'\
4002         '                               }\n'\
4003         '                       }\n'\
4004         '               }\n'\
4005         '               var cglist = document.getElementById("callgraphs");\n'\
4006         '               if(!cglist) return;\n'\
4007         '               var cg = cglist.getElementsByClassName("atop");\n'\
4008         '               if(cg.length < 10) return;\n'\
4009         '               for (var i = 0; i < cg.length; i++) {\n'\
4010         '                       if(idlist.indexOf(cg[i].id) >= 0) {\n'\
4011         '                               cg[i].style.display = "block";\n'\
4012         '                       } else {\n'\
4013         '                               cg[i].style.display = "none";\n'\
4014         '                       }\n'\
4015         '               }\n'\
4016         '       }\n'\
4017         '       function devListWindow(e) {\n'\
4018         '               var win = window.open();\n'\
4019         '               var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
4020         '                       "<style type=\\"text/css\\">"+\n'\
4021         '                       "   ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
4022         '                       "</style>"\n'\
4023         '               var dt = devtable[0];\n'\
4024         '               if(e.target.id != "devlist1")\n'\
4025         '                       dt = devtable[1];\n'\
4026         '               win.document.write(html+dt);\n'\
4027         '       }\n'\
4028         '       function errWindow() {\n'\
4029         '               var text = this.id;\n'\
4030         '               var win = window.open();\n'\
4031         '               win.document.write("<pre>"+text+"</pre>");\n'\
4032         '               win.document.close();\n'\
4033         '       }\n'\
4034         '       function logWindow(e) {\n'\
4035         '               var name = e.target.id.slice(4);\n'\
4036         '               var win = window.open();\n'\
4037         '               var log = document.getElementById(name+"log");\n'\
4038         '               var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
4039         '               win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
4040         '               win.document.close();\n'\
4041         '       }\n'\
4042         '       function onClickPhase(e) {\n'\
4043         '       }\n'\
4044         '       function onMouseDown(e) {\n'\
4045         '               dragval[0] = e.clientX;\n'\
4046         '               dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\
4047         '               document.onmousemove = onMouseMove;\n'\
4048         '       }\n'\
4049         '       function onMouseMove(e) {\n'\
4050         '               var zoombox = document.getElementById("dmesgzoombox");\n'\
4051         '               zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\
4052         '       }\n'\
4053         '       function onMouseUp(e) {\n'\
4054         '               document.onmousemove = null;\n'\
4055         '       }\n'\
4056         '       function onKeyPress(e) {\n'\
4057         '               var c = e.charCode;\n'\
4058         '               if(c != 42 && c != 43 && c != 45) return;\n'\
4059         '               var click = document.createEvent("Events");\n'\
4060         '               click.initEvent("click", true, false);\n'\
4061         '               if(c == 43)  \n'\
4062         '                       document.getElementById("zoomin").dispatchEvent(click);\n'\
4063         '               else if(c == 45)\n'\
4064         '                       document.getElementById("zoomout").dispatchEvent(click);\n'\
4065         '               else if(c == 42)\n'\
4066         '                       document.getElementById("zoomdef").dispatchEvent(click);\n'\
4067         '       }\n'\
4068         '       window.addEventListener("resize", function () {zoomTimeline();});\n'\
4069         '       window.addEventListener("load", function () {\n'\
4070         '               var dmesg = document.getElementById("dmesg");\n'\
4071         '               dmesg.style.width = "100%"\n'\
4072         '               dmesg.onmousedown = onMouseDown;\n'\
4073         '               document.onmouseup = onMouseUp;\n'\
4074         '               document.onkeypress = onKeyPress;\n'\
4075         '               document.getElementById("zoomin").onclick = zoomTimeline;\n'\
4076         '               document.getElementById("zoomout").onclick = zoomTimeline;\n'\
4077         '               document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
4078         '               var list = document.getElementsByClassName("square");\n'\
4079         '               for (var i = 0; i < list.length; i++)\n'\
4080         '                       list[i].onclick = onClickPhase;\n'\
4081         '               var list = document.getElementsByClassName("err");\n'\
4082         '               for (var i = 0; i < list.length; i++)\n'\
4083         '                       list[i].onclick = errWindow;\n'\
4084         '               var list = document.getElementsByClassName("logbtn");\n'\
4085         '               for (var i = 0; i < list.length; i++)\n'\
4086         '                       list[i].onclick = logWindow;\n'\
4087         '               list = document.getElementsByClassName("devlist");\n'\
4088         '               for (var i = 0; i < list.length; i++)\n'\
4089         '                       list[i].onclick = devListWindow;\n'\
4090         '               var dev = dmesg.getElementsByClassName("thread");\n'\
4091         '               for (var i = 0; i < dev.length; i++) {\n'\
4092         '                       dev[i].onclick = deviceDetail;\n'\
4093         '                       dev[i].onmouseover = deviceHover;\n'\
4094         '                       dev[i].onmouseout = deviceUnhover;\n'\
4095         '               }\n'\
4096         '               zoomTimeline();\n'\
4097         '       });\n'\
4098         '</script>\n'
4099         hf.write(script_code);
4100
4101 # Function: executeSuspend
4102 # Description:
4103 #        Execute system suspend through the sysfs interface, then copy the output
4104 #        dmesg and ftrace files to the test output directory.
4105 def executeSuspend():
4106         pm = ProcessMonitor()
4107         tp = sysvals.tpath
4108         fwdata = []
4109         # mark the start point in the kernel ring buffer just as we start
4110         sysvals.initdmesg()
4111         # start ftrace
4112         if(sysvals.usecallgraph or sysvals.usetraceevents):
4113                 print('START TRACING')
4114                 sysvals.fsetVal('1', 'tracing_on')
4115                 if sysvals.useprocmon:
4116                         pm.start()
4117         # execute however many s/r runs requested
4118         for count in range(1,sysvals.execcount+1):
4119                 # x2delay in between test runs
4120                 if(count > 1 and sysvals.x2delay > 0):
4121                         sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
4122                         time.sleep(sysvals.x2delay/1000.0)
4123                         sysvals.fsetVal('WAIT END', 'trace_marker')
4124                 # start message
4125                 if sysvals.testcommand != '':
4126                         print('COMMAND START')
4127                 else:
4128                         if(sysvals.rtcwake):
4129                                 print('SUSPEND START')
4130                         else:
4131                                 print('SUSPEND START (press a key to resume)')
4132                 # set rtcwake
4133                 if(sysvals.rtcwake):
4134                         print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
4135                         sysvals.rtcWakeAlarmOn()
4136                 # start of suspend trace marker
4137                 if(sysvals.usecallgraph or sysvals.usetraceevents):
4138                         sysvals.fsetVal('SUSPEND START', 'trace_marker')
4139                 # predelay delay
4140                 if(count == 1 and sysvals.predelay > 0):
4141                         sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
4142                         time.sleep(sysvals.predelay/1000.0)
4143                         sysvals.fsetVal('WAIT END', 'trace_marker')
4144                 # initiate suspend or command
4145                 if sysvals.testcommand != '':
4146                         call(sysvals.testcommand+' 2>&1', shell=True);
4147                 else:
4148                         pf = open(sysvals.powerfile, 'w')
4149                         pf.write(sysvals.suspendmode)
4150                         # execution will pause here
4151                         try:
4152                                 pf.close()
4153                         except:
4154                                 pass
4155                 if(sysvals.rtcwake):
4156                         sysvals.rtcWakeAlarmOff()
4157                 # postdelay delay
4158                 if(count == sysvals.execcount and sysvals.postdelay > 0):
4159                         sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
4160                         time.sleep(sysvals.postdelay/1000.0)
4161                         sysvals.fsetVal('WAIT END', 'trace_marker')
4162                 # return from suspend
4163                 print('RESUME COMPLETE')
4164                 if(sysvals.usecallgraph or sysvals.usetraceevents):
4165                         sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
4166                 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4167                         fwdata.append(getFPDT(False))
4168         # stop ftrace
4169         if(sysvals.usecallgraph or sysvals.usetraceevents):
4170                 if sysvals.useprocmon:
4171                         pm.stop()
4172                 sysvals.fsetVal('0', 'tracing_on')
4173                 print('CAPTURING TRACE')
4174                 writeDatafileHeader(sysvals.ftracefile, fwdata)
4175                 call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True)
4176                 sysvals.fsetVal('', 'trace')
4177                 devProps()
4178         # grab a copy of the dmesg output
4179         print('CAPTURING DMESG')
4180         writeDatafileHeader(sysvals.dmesgfile, fwdata)
4181         sysvals.getdmesg()
4182
4183 def writeDatafileHeader(filename, fwdata):
4184         fp = open(filename, 'a')
4185         fp.write(sysvals.teststamp+'\n')
4186         if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4187                 for fw in fwdata:
4188                         if(fw):
4189                                 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
4190         fp.close()
4191
4192 # Function: setUSBDevicesAuto
4193 # Description:
4194 #        Set the autosuspend control parameter of all USB devices to auto
4195 #        This can be dangerous, so use at your own risk, most devices are set
4196 #        to always-on since the kernel cant determine if the device can
4197 #        properly autosuspend
4198 def setUSBDevicesAuto():
4199         rootCheck(True)
4200         for dirname, dirnames, filenames in os.walk('/sys/devices'):
4201                 if(re.match('.*/usb[0-9]*.*', dirname) and
4202                         'idVendor' in filenames and 'idProduct' in filenames):
4203                         call('echo auto > %s/power/control' % dirname, shell=True)
4204                         name = dirname.split('/')[-1]
4205                         desc = Popen(['cat', '%s/product' % dirname],
4206                                 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4207                         ctrl = Popen(['cat', '%s/power/control' % dirname],
4208                                 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4209                         print('control is %s for %6s: %s' % (ctrl, name, desc))
4210
4211 # Function: yesno
4212 # Description:
4213 #        Print out an equivalent Y or N for a set of known parameter values
4214 # Output:
4215 #        'Y', 'N', or ' ' if the value is unknown
4216 def yesno(val):
4217         yesvals = ['auto', 'enabled', 'active', '1']
4218         novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
4219         if val in yesvals:
4220                 return 'Y'
4221         elif val in novals:
4222                 return 'N'
4223         return ' '
4224
4225 # Function: ms2nice
4226 # Description:
4227 #        Print out a very concise time string in minutes and seconds
4228 # Output:
4229 #        The time string, e.g. "1901m16s"
4230 def ms2nice(val):
4231         ms = 0
4232         try:
4233                 ms = int(val)
4234         except:
4235                 return 0.0
4236         m = ms / 60000
4237         s = (ms / 1000) - (m * 60)
4238         return '%3dm%2ds' % (m, s)
4239
4240 # Function: detectUSB
4241 # Description:
4242 #        Detect all the USB hosts and devices currently connected and add
4243 #        a list of USB device names to sysvals for better timeline readability
4244 def detectUSB():
4245         field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
4246         power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
4247                          'control':'', 'persist':'', 'runtime_enabled':'',
4248                          'runtime_status':'', 'runtime_usage':'',
4249                         'runtime_active_time':'',
4250                         'runtime_suspended_time':'',
4251                         'active_duration':'',
4252                         'connected_duration':''}
4253
4254         print('LEGEND')
4255         print('---------------------------------------------------------------------------------------------')
4256         print('  A = async/sync PM queue Y/N                       D = autosuspend delay (seconds)')
4257         print('  S = autosuspend Y/N                         rACTIVE = runtime active (min/sec)')
4258         print('  P = persist across suspend Y/N              rSUSPEN = runtime suspend (min/sec)')
4259         print('  E = runtime suspend enabled/forbidden Y/N    ACTIVE = active duration (min/sec)')
4260         print('  R = runtime status active/suspended Y/N     CONNECT = connected duration (min/sec)')
4261         print('  U = runtime usage count')
4262         print('---------------------------------------------------------------------------------------------')
4263         print('  NAME       ID      DESCRIPTION         SPEED A S P E R U D rACTIVE rSUSPEN  ACTIVE CONNECT')
4264         print('---------------------------------------------------------------------------------------------')
4265
4266         for dirname, dirnames, filenames in os.walk('/sys/devices'):
4267                 if(re.match('.*/usb[0-9]*.*', dirname) and
4268                         'idVendor' in filenames and 'idProduct' in filenames):
4269                         for i in field:
4270                                 field[i] = Popen(['cat', '%s/%s' % (dirname, i)],
4271                                         stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4272                         name = dirname.split('/')[-1]
4273                         for i in power:
4274                                 power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)],
4275                                         stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4276                         if(re.match('usb[0-9]*', name)):
4277                                 first = '%-8s' % name
4278                         else:
4279                                 first = '%8s' % name
4280                         print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
4281                                 (first, field['idVendor'], field['idProduct'], \
4282                                 field['product'][0:20], field['speed'], \
4283                                 yesno(power['async']), \
4284                                 yesno(power['control']), \
4285                                 yesno(power['persist']), \
4286                                 yesno(power['runtime_enabled']), \
4287                                 yesno(power['runtime_status']), \
4288                                 power['runtime_usage'], \
4289                                 power['autosuspend'], \
4290                                 ms2nice(power['runtime_active_time']), \
4291                                 ms2nice(power['runtime_suspended_time']), \
4292                                 ms2nice(power['active_duration']), \
4293                                 ms2nice(power['connected_duration'])))
4294
4295 # Function: devProps
4296 # Description:
4297 #        Retrieve a list of properties for all devices in the trace log
4298 def devProps(data=0):
4299         props = dict()
4300
4301         if data:
4302                 idx = data.index(': ') + 2
4303                 if idx >= len(data):
4304                         return
4305                 devlist = data[idx:].split(';')
4306                 for dev in devlist:
4307                         f = dev.split(',')
4308                         if len(f) < 3:
4309                                 continue
4310                         dev = f[0]
4311                         props[dev] = DevProps()
4312                         props[dev].altname = f[1]
4313                         if int(f[2]):
4314                                 props[dev].async = True
4315                         else:
4316                                 props[dev].async = False
4317                         sysvals.devprops = props
4318                 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4319                         sysvals.testcommand = props['testcommandstring'].altname
4320                 return
4321
4322         if(os.path.exists(sysvals.ftracefile) == False):
4323                 doError('%s does not exist' % sysvals.ftracefile)
4324
4325         # first get the list of devices we need properties for
4326         msghead = 'Additional data added by AnalyzeSuspend'
4327         alreadystamped = False
4328         tp = TestProps()
4329         tf = open(sysvals.ftracefile, 'r')
4330         for line in tf:
4331                 if msghead in line:
4332                         alreadystamped = True
4333                         continue
4334                 # determine the trace data type (required for further parsing)
4335                 m = re.match(sysvals.tracertypefmt, line)
4336                 if(m):
4337                         tp.setTracerType(m.group('t'))
4338                         continue
4339                 # parse only valid lines, if this is not one move on
4340                 m = re.match(tp.ftrace_line_fmt, line)
4341                 if(not m or 'device_pm_callback_start' not in line):
4342                         continue
4343                 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
4344                 if(not m):
4345                         continue
4346                 dev = m.group('d')
4347                 if dev not in props:
4348                         props[dev] = DevProps()
4349         tf.close()
4350
4351         if not alreadystamped and sysvals.suspendmode == 'command':
4352                 out = '#\n# '+msghead+'\n# Device Properties: '
4353                 out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
4354                 with open(sysvals.ftracefile, 'a') as fp:
4355                         fp.write(out+'\n')
4356                 sysvals.devprops = props
4357                 return
4358
4359         # now get the syspath for each of our target devices
4360         for dirname, dirnames, filenames in os.walk('/sys/devices'):
4361                 if(re.match('.*/power', dirname) and 'async' in filenames):
4362                         dev = dirname.split('/')[-2]
4363                         if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
4364                                 props[dev].syspath = dirname[:-6]
4365
4366         # now fill in the properties for our target devices
4367         for dev in props:
4368                 dirname = props[dev].syspath
4369                 if not dirname or not os.path.exists(dirname):
4370                         continue
4371                 with open(dirname+'/power/async') as fp:
4372                         text = fp.read()
4373                         props[dev].async = False
4374                         if 'enabled' in text:
4375                                 props[dev].async = True
4376                 fields = os.listdir(dirname)
4377                 if 'product' in fields:
4378                         with open(dirname+'/product') as fp:
4379                                 props[dev].altname = fp.read()
4380                 elif 'name' in fields:
4381                         with open(dirname+'/name') as fp:
4382                                 props[dev].altname = fp.read()
4383                 elif 'model' in fields:
4384                         with open(dirname+'/model') as fp:
4385                                 props[dev].altname = fp.read()
4386                 elif 'description' in fields:
4387                         with open(dirname+'/description') as fp:
4388                                 props[dev].altname = fp.read()
4389                 elif 'id' in fields:
4390                         with open(dirname+'/id') as fp:
4391                                 props[dev].altname = fp.read()
4392                 elif 'idVendor' in fields and 'idProduct' in fields:
4393                         idv, idp = '', ''
4394                         with open(dirname+'/idVendor') as fp:
4395                                 idv = fp.read().strip()
4396                         with open(dirname+'/idProduct') as fp:
4397                                 idp = fp.read().strip()
4398                         props[dev].altname = '%s:%s' % (idv, idp)
4399
4400                 if props[dev].altname:
4401                         out = props[dev].altname.strip().replace('\n', ' ')
4402                         out = out.replace(',', ' ')
4403                         out = out.replace(';', ' ')
4404                         props[dev].altname = out
4405
4406         # and now write the data to the ftrace file
4407         if not alreadystamped:
4408                 out = '#\n# '+msghead+'\n# Device Properties: '
4409                 for dev in sorted(props):
4410                         out += props[dev].out(dev)
4411                 with open(sysvals.ftracefile, 'a') as fp:
4412                         fp.write(out+'\n')
4413
4414         sysvals.devprops = props
4415
4416 # Function: getModes
4417 # Description:
4418 #        Determine the supported power modes on this system
4419 # Output:
4420 #        A string list of the available modes
4421 def getModes():
4422         modes = ''
4423         if(os.path.exists(sysvals.powerfile)):
4424                 fp = open(sysvals.powerfile, 'r')
4425                 modes = string.split(fp.read())
4426                 fp.close()
4427         return modes
4428
4429 # Function: getFPDT
4430 # Description:
4431 #        Read the acpi bios tables and pull out FPDT, the firmware data
4432 # Arguments:
4433 #        output: True to output the info to stdout, False otherwise
4434 def getFPDT(output):
4435         rectype = {}
4436         rectype[0] = 'Firmware Basic Boot Performance Record'
4437         rectype[1] = 'S3 Performance Table Record'
4438         prectype = {}
4439         prectype[0] = 'Basic S3 Resume Performance Record'
4440         prectype[1] = 'Basic S3 Suspend Performance Record'
4441
4442         rootCheck(True)
4443         if(not os.path.exists(sysvals.fpdtpath)):
4444                 if(output):
4445                         doError('file does not exist: %s' % sysvals.fpdtpath)
4446                 return False
4447         if(not os.access(sysvals.fpdtpath, os.R_OK)):
4448                 if(output):
4449                         doError('file is not readable: %s' % sysvals.fpdtpath)
4450                 return False
4451         if(not os.path.exists(sysvals.mempath)):
4452                 if(output):
4453                         doError('file does not exist: %s' % sysvals.mempath)
4454                 return False
4455         if(not os.access(sysvals.mempath, os.R_OK)):
4456                 if(output):
4457                         doError('file is not readable: %s' % sysvals.mempath)
4458                 return False
4459
4460         fp = open(sysvals.fpdtpath, 'rb')
4461         buf = fp.read()
4462         fp.close()
4463
4464         if(len(buf) < 36):
4465                 if(output):
4466                         doError('Invalid FPDT table data, should '+\
4467                                 'be at least 36 bytes')
4468                 return False
4469
4470         table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
4471         if(output):
4472                 print('')
4473                 print('Firmware Performance Data Table (%s)' % table[0])
4474                 print('                  Signature : %s' % table[0])
4475                 print('               Table Length : %u' % table[1])
4476                 print('                   Revision : %u' % table[2])
4477                 print('                   Checksum : 0x%x' % table[3])
4478                 print('                     OEM ID : %s' % table[4])
4479                 print('               OEM Table ID : %s' % table[5])
4480                 print('               OEM Revision : %u' % table[6])
4481                 print('                 Creator ID : %s' % table[7])
4482                 print('           Creator Revision : 0x%x' % table[8])
4483                 print('')
4484
4485         if(table[0] != 'FPDT'):
4486                 if(output):
4487                         doError('Invalid FPDT table')
4488                 return False
4489         if(len(buf) <= 36):
4490                 return False
4491         i = 0
4492         fwData = [0, 0]
4493         records = buf[36:]
4494         fp = open(sysvals.mempath, 'rb')
4495         while(i < len(records)):
4496                 header = struct.unpack('HBB', records[i:i+4])
4497                 if(header[0] not in rectype):
4498                         i += header[1]
4499                         continue
4500                 if(header[1] != 16):
4501                         i += header[1]
4502                         continue
4503                 addr = struct.unpack('Q', records[i+8:i+16])[0]
4504                 try:
4505                         fp.seek(addr)
4506                         first = fp.read(8)
4507                 except:
4508                         if(output):
4509                                 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
4510                         return [0, 0]
4511                 rechead = struct.unpack('4sI', first)
4512                 recdata = fp.read(rechead[1]-8)
4513                 if(rechead[0] == 'FBPT'):
4514                         record = struct.unpack('HBBIQQQQQ', recdata)
4515                         if(output):
4516                                 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4517                                 print('                  Reset END : %u ns' % record[4])
4518                                 print('  OS Loader LoadImage Start : %u ns' % record[5])
4519                                 print(' OS Loader StartImage Start : %u ns' % record[6])
4520                                 print('     ExitBootServices Entry : %u ns' % record[7])
4521                                 print('      ExitBootServices Exit : %u ns' % record[8])
4522                 elif(rechead[0] == 'S3PT'):
4523                         if(output):
4524                                 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4525                         j = 0
4526                         while(j < len(recdata)):
4527                                 prechead = struct.unpack('HBB', recdata[j:j+4])
4528                                 if(prechead[0] not in prectype):
4529                                         continue
4530                                 if(prechead[0] == 0):
4531                                         record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
4532                                         fwData[1] = record[2]
4533                                         if(output):
4534                                                 print('    %s' % prectype[prechead[0]])
4535                                                 print('               Resume Count : %u' % \
4536                                                         record[1])
4537                                                 print('                 FullResume : %u ns' % \
4538                                                         record[2])
4539                                                 print('              AverageResume : %u ns' % \
4540                                                         record[3])
4541                                 elif(prechead[0] == 1):
4542                                         record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
4543                                         fwData[0] = record[1] - record[0]
4544                                         if(output):
4545                                                 print('    %s' % prectype[prechead[0]])
4546                                                 print('               SuspendStart : %u ns' % \
4547                                                         record[0])
4548                                                 print('                 SuspendEnd : %u ns' % \
4549                                                         record[1])
4550                                                 print('                SuspendTime : %u ns' % \
4551                                                         fwData[0])
4552                                 j += prechead[1]
4553                 if(output):
4554                         print('')
4555                 i += header[1]
4556         fp.close()
4557         return fwData
4558
4559 # Function: statusCheck
4560 # Description:
4561 #        Verify that the requested command and options will work, and
4562 #        print the results to the terminal
4563 # Output:
4564 #        True if the test will work, False if not
4565 def statusCheck(probecheck=False):
4566         status = True
4567
4568         print('Checking this system (%s)...' % platform.node())
4569
4570         # check we have root access
4571         res = sysvals.colorText('NO (No features of this tool will work!)')
4572         if(rootCheck(False)):
4573                 res = 'YES'
4574         print('    have root access: %s' % res)
4575         if(res != 'YES'):
4576                 print('    Try running this script with sudo')
4577                 return False
4578
4579         # check sysfs is mounted
4580         res = sysvals.colorText('NO (No features of this tool will work!)')
4581         if(os.path.exists(sysvals.powerfile)):
4582                 res = 'YES'
4583         print('    is sysfs mounted: %s' % res)
4584         if(res != 'YES'):
4585                 return False
4586
4587         # check target mode is a valid mode
4588         if sysvals.suspendmode != 'command':
4589                 res = sysvals.colorText('NO')
4590                 modes = getModes()
4591                 if(sysvals.suspendmode in modes):
4592                         res = 'YES'
4593                 else:
4594                         status = False
4595                 print('    is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
4596                 if(res == 'NO'):
4597                         print('      valid power modes are: %s' % modes)
4598                         print('      please choose one with -m')
4599
4600         # check if ftrace is available
4601         res = sysvals.colorText('NO')
4602         ftgood = sysvals.verifyFtrace()
4603         if(ftgood):
4604                 res = 'YES'
4605         elif(sysvals.usecallgraph):
4606                 status = False
4607         print('    is ftrace supported: %s' % res)
4608
4609         # check if kprobes are available
4610         res = sysvals.colorText('NO')
4611         sysvals.usekprobes = sysvals.verifyKprobes()
4612         if(sysvals.usekprobes):
4613                 res = 'YES'
4614         else:
4615                 sysvals.usedevsrc = False
4616         print('    are kprobes supported: %s' % res)
4617
4618         # what data source are we using
4619         res = 'DMESG'
4620         if(ftgood):
4621                 sysvals.usetraceeventsonly = True
4622                 sysvals.usetraceevents = False
4623                 for e in sysvals.traceevents:
4624                         check = False
4625                         if(os.path.exists(sysvals.epath+e)):
4626                                 check = True
4627                         if(not check):
4628                                 sysvals.usetraceeventsonly = False
4629                         if(e == 'suspend_resume' and check):
4630                                 sysvals.usetraceevents = True
4631                 if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
4632                         res = 'FTRACE (all trace events found)'
4633                 elif(sysvals.usetraceevents):
4634                         res = 'DMESG and FTRACE (suspend_resume trace event found)'
4635         print('    timeline data source: %s' % res)
4636
4637         # check if rtcwake
4638         res = sysvals.colorText('NO')
4639         if(sysvals.rtcpath != ''):
4640                 res = 'YES'
4641         elif(sysvals.rtcwake):
4642                 status = False
4643         print('    is rtcwake supported: %s' % res)
4644
4645         if not probecheck:
4646                 return status
4647
4648         # verify kprobes
4649         if sysvals.usekprobes:
4650                 for name in sysvals.tracefuncs:
4651                         sysvals.defaultKprobe(name, sysvals.tracefuncs[name])
4652                 if sysvals.usedevsrc:
4653                         for name in sysvals.dev_tracefuncs:
4654                                 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])
4655                 sysvals.addKprobes(True)
4656
4657         return status
4658
4659 # Function: doError
4660 # Description:
4661 #        generic error function for catastrphic failures
4662 # Arguments:
4663 #        msg: the error message to print
4664 #        help: True if printHelp should be called after, False otherwise
4665 def doError(msg, help=False):
4666         if(help == True):
4667                 printHelp()
4668         print('ERROR: %s\n') % msg
4669         sys.exit()
4670
4671 # Function: rootCheck
4672 # Description:
4673 #        quick check to see if we have root access
4674 def rootCheck(fatal):
4675         if(os.access(sysvals.powerfile, os.W_OK)):
4676                 return True
4677         if fatal:
4678                 doError('This command must be run as root')
4679         return False
4680
4681 # Function: getArgInt
4682 # Description:
4683 #        pull out an integer argument from the command line with checks
4684 def getArgInt(name, args, min, max, main=True):
4685         if main:
4686                 try:
4687                         arg = args.next()
4688                 except:
4689                         doError(name+': no argument supplied', True)
4690         else:
4691                 arg = args
4692         try:
4693                 val = int(arg)
4694         except:
4695                 doError(name+': non-integer value given', True)
4696         if(val < min or val > max):
4697                 doError(name+': value should be between %d and %d' % (min, max), True)
4698         return val
4699
4700 # Function: getArgFloat
4701 # Description:
4702 #        pull out a float argument from the command line with checks
4703 def getArgFloat(name, args, min, max, main=True):
4704         if main:
4705                 try:
4706                         arg = args.next()
4707                 except:
4708                         doError(name+': no argument supplied', True)
4709         else:
4710                 arg = args
4711         try:
4712                 val = float(arg)
4713         except:
4714                 doError(name+': non-numerical value given', True)
4715         if(val < min or val > max):
4716                 doError(name+': value should be between %f and %f' % (min, max), True)
4717         return val
4718
4719 def processData():
4720         print('PROCESSING DATA')
4721         if(sysvals.usetraceeventsonly):
4722                 testruns = parseTraceLog()
4723                 if sysvals.dmesgfile:
4724                         dmesgtext = loadKernelLog(True)
4725                         for data in testruns:
4726                                 data.extractErrorInfo(dmesgtext)
4727         else:
4728                 testruns = loadKernelLog()
4729                 for data in testruns:
4730                         parseKernelLog(data)
4731                 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
4732                         appendIncompleteTraceLog(testruns)
4733         createHTML(testruns)
4734
4735 # Function: rerunTest
4736 # Description:
4737 #        generate an output from an existing set of ftrace/dmesg logs
4738 def rerunTest():
4739         if sysvals.ftracefile:
4740                 doesTraceLogHaveTraceEvents()
4741         if not sysvals.dmesgfile and not sysvals.usetraceeventsonly:
4742                 doError('recreating this html output requires a dmesg file')
4743         sysvals.setOutputFile()
4744         vprint('Output file: %s' % sysvals.htmlfile)
4745         if(os.path.exists(sysvals.htmlfile) and not os.access(sysvals.htmlfile, os.W_OK)):
4746                 doError('missing permission to write to %s' % sysvals.htmlfile)
4747         processData()
4748
4749 # Function: runTest
4750 # Description:
4751 #        execute a suspend/resume, gather the logs, and generate the output
4752 def runTest(subdir, testpath=''):
4753         # prepare for the test
4754         sysvals.initFtrace()
4755         sysvals.initTestOutput(subdir, testpath)
4756         vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
4757                 (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
4758
4759         # execute the test
4760         executeSuspend()
4761         sysvals.cleanupFtrace()
4762         processData()
4763
4764         # if running as root, change output dir owner to sudo_user
4765         if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \
4766                 'SUDO_USER' in os.environ:
4767                 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
4768                 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
4769
4770 # Function: runSummary
4771 # Description:
4772 #        create a summary of tests in a sub-directory
4773 def runSummary(subdir, output):
4774         # get a list of ftrace output files
4775         files = []
4776         for dirname, dirnames, filenames in os.walk(subdir):
4777                 for filename in filenames:
4778                         if(re.match('.*_ftrace.txt', filename)):
4779                                 files.append("%s/%s" % (dirname, filename))
4780
4781         # process the files in order and get an array of data objects
4782         testruns = []
4783         for file in sorted(files):
4784                 if output:
4785                         print("Test found in %s" % os.path.dirname(file))
4786                 sysvals.ftracefile = file
4787                 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt')
4788                 doesTraceLogHaveTraceEvents()
4789                 sysvals.usecallgraph = False
4790                 if not sysvals.usetraceeventsonly:
4791                         if(not os.path.exists(sysvals.dmesgfile)):
4792                                 print("Skipping %s: not a valid test input" % file)
4793                                 continue
4794                         else:
4795                                 if output:
4796                                         f = os.path.basename(sysvals.ftracefile)
4797                                         d = os.path.basename(sysvals.dmesgfile)
4798                                         print("\tInput files: %s and %s" % (f, d))
4799                                 testdata = loadKernelLog()
4800                                 data = testdata[0]
4801                                 parseKernelLog(data)
4802                                 testdata = [data]
4803                                 appendIncompleteTraceLog(testdata)
4804                 else:
4805                         if output:
4806                                 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
4807                         testdata = parseTraceLog()
4808                         data = testdata[0]
4809                 data.normalizeTime(data.tSuspended)
4810                 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
4811                 data.outfile = link
4812                 testruns.append(data)
4813
4814         createHTMLSummarySimple(testruns, subdir+'/summary.html')
4815
4816 # Function: checkArgBool
4817 # Description:
4818 #        check if a boolean string value is true or false
4819 def checkArgBool(value):
4820         yes = ['1', 'true', 'yes', 'on']
4821         if value.lower() in yes:
4822                 return True
4823         return False
4824
4825 # Function: configFromFile
4826 # Description:
4827 #        Configure the script via the info in a config file
4828 def configFromFile(file):
4829         Config = ConfigParser.ConfigParser()
4830
4831         Config.read(file)
4832         sections = Config.sections()
4833         overridekprobes = False
4834         overridedevkprobes = False
4835         if 'Settings' in sections:
4836                 for opt in Config.options('Settings'):
4837                         value = Config.get('Settings', opt).lower()
4838                         if(opt.lower() == 'verbose'):
4839                                 sysvals.verbose = checkArgBool(value)
4840                         elif(opt.lower() == 'addlogs'):
4841                                 sysvals.addlogs = checkArgBool(value)
4842                         elif(opt.lower() == 'dev'):
4843                                 sysvals.usedevsrc = checkArgBool(value)
4844                         elif(opt.lower() == 'proc'):
4845                                 sysvals.useprocmon = checkArgBool(value)
4846                         elif(opt.lower() == 'x2'):
4847                                 if checkArgBool(value):
4848                                         sysvals.execcount = 2
4849                         elif(opt.lower() == 'callgraph'):
4850                                 sysvals.usecallgraph = checkArgBool(value)
4851                         elif(opt.lower() == 'override-timeline-functions'):
4852                                 overridekprobes = checkArgBool(value)
4853                         elif(opt.lower() == 'override-dev-timeline-functions'):
4854                                 overridedevkprobes = checkArgBool(value)
4855                         elif(opt.lower() == 'devicefilter'):
4856                                 sysvals.setDeviceFilter(value)
4857                         elif(opt.lower() == 'expandcg'):
4858                                 sysvals.cgexp = checkArgBool(value)
4859                         elif(opt.lower() == 'srgap'):
4860                                 if checkArgBool(value):
4861                                         sysvals.srgap = 5
4862                         elif(opt.lower() == 'mode'):
4863                                 sysvals.suspendmode = value
4864                         elif(opt.lower() == 'command'):
4865                                 sysvals.testcommand = value
4866                         elif(opt.lower() == 'x2delay'):
4867                                 sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
4868                         elif(opt.lower() == 'predelay'):
4869                                 sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False)
4870                         elif(opt.lower() == 'postdelay'):
4871                                 sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False)
4872                         elif(opt.lower() == 'rtcwake'):
4873                                 sysvals.rtcwake = True
4874                                 sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
4875                         elif(opt.lower() == 'timeprec'):
4876                                 sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
4877                         elif(opt.lower() == 'mindev'):
4878                                 sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
4879                         elif(opt.lower() == 'callloop-maxgap'):
4880                                 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False)
4881                         elif(opt.lower() == 'callloop-maxlen'):
4882                                 sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False)
4883                         elif(opt.lower() == 'mincg'):
4884                                 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
4885                         elif(opt.lower() == 'output-dir'):
4886                                 sysvals.setOutputFolder(value)
4887
4888         if sysvals.suspendmode == 'command' and not sysvals.testcommand:
4889                 doError('No command supplied for mode "command"')
4890
4891         # compatibility errors
4892         if sysvals.usedevsrc and sysvals.usecallgraph:
4893                 doError('-dev is not compatible with -f')
4894         if sysvals.usecallgraph and sysvals.useprocmon:
4895                 doError('-proc is not compatible with -f')
4896
4897         if overridekprobes:
4898                 sysvals.tracefuncs = dict()
4899         if overridedevkprobes:
4900                 sysvals.dev_tracefuncs = dict()
4901
4902         kprobes = dict()
4903         kprobesec = 'dev_timeline_functions_'+platform.machine()
4904         if kprobesec in sections:
4905                 for name in Config.options(kprobesec):
4906                         text = Config.get(kprobesec, name)
4907                         kprobes[name] = (text, True)
4908         kprobesec = 'timeline_functions_'+platform.machine()
4909         if kprobesec in sections:
4910                 for name in Config.options(kprobesec):
4911                         if name in kprobes:
4912                                 doError('Duplicate timeline function found "%s"' % (name))
4913                         text = Config.get(kprobesec, name)
4914                         kprobes[name] = (text, False)
4915
4916         for name in kprobes:
4917                 function = name
4918                 format = name
4919                 color = ''
4920                 args = dict()
4921                 text, dev = kprobes[name]
4922                 data = text.split()
4923                 i = 0
4924                 for val in data:
4925                         # bracketted strings are special formatting, read them separately
4926                         if val[0] == '[' and val[-1] == ']':
4927                                 for prop in val[1:-1].split(','):
4928                                         p = prop.split('=')
4929                                         if p[0] == 'color':
4930                                                 try:
4931                                                         color = int(p[1], 16)
4932                                                         color = '#'+p[1]
4933                                                 except:
4934                                                         color = p[1]
4935                                 continue
4936                         # first real arg should be the format string
4937                         if i == 0:
4938                                 format = val
4939                         # all other args are actual function args
4940                         else:
4941                                 d = val.split('=')
4942                                 args[d[0]] = d[1]
4943                         i += 1
4944                 if not function or not format:
4945                         doError('Invalid kprobe: %s' % name)
4946                 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
4947                         if arg not in args:
4948                                 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
4949                 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
4950                         doError('Duplicate timeline function found "%s"' % (name))
4951
4952                 kp = {
4953                         'name': name,
4954                         'func': function,
4955                         'format': format,
4956                         sysvals.archargs: args
4957                 }
4958                 if color:
4959                         kp['color'] = color
4960                 if dev:
4961                         sysvals.dev_tracefuncs[name] = kp
4962                 else:
4963                         sysvals.tracefuncs[name] = kp
4964
4965 # Function: printHelp
4966 # Description:
4967 #        print out the help text
4968 def printHelp():
4969         modes = getModes()
4970
4971         print('')
4972         print('AnalyzeSuspend v%s' % sysvals.version)
4973         print('Usage: sudo analyze_suspend.py <options>')
4974         print('')
4975         print('Description:')
4976         print('  This tool is designed to assist kernel and OS developers in optimizing')
4977         print('  their linux stack\'s suspend/resume time. Using a kernel image built')
4978         print('  with a few extra options enabled, the tool will execute a suspend and')
4979         print('  capture dmesg and ftrace data until resume is complete. This data is')
4980         print('  transformed into a device timeline and an optional callgraph to give')
4981         print('  a detailed view of which devices/subsystems are taking the most')
4982         print('  time in suspend/resume.')
4983         print('')
4984         print('  Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
4985         print('   HTML output:                    <hostname>_<mode>.html')
4986         print('   raw dmesg output:               <hostname>_<mode>_dmesg.txt')
4987         print('   raw ftrace output:              <hostname>_<mode>_ftrace.txt')
4988         print('')
4989         print('Options:')
4990         print('  [general]')
4991         print('   -h           Print this help text')
4992         print('   -v           Print the current tool version')
4993         print('   -config fn   Pull arguments and config options from file fn')
4994         print('   -verbose     Print extra information during execution and analysis')
4995         print('   -status      Test to see if the system is enabled to run this tool')
4996         print('   -modes       List available suspend modes')
4997         print('   -m mode      Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
4998         print('   -o subdir    Override the output subdirectory')
4999         print('   -rtcwake t   Use rtcwake to autoresume after <t> seconds (default: disabled)')
5000         print('   -addlogs     Add the dmesg and ftrace logs to the html output')
5001         print('   -srgap       Add a visible gap in the timeline between sus/res (default: disabled)')
5002         print('  [advanced]')
5003         print('   -cmd {s}     Run the timeline over a custom command, e.g. "sync -d"')
5004         print('   -proc        Add usermode process info into the timeline (default: disabled)')
5005         print('   -dev         Add kernel function calls and threads to the timeline (default: disabled)')
5006         print('   -x2          Run two suspend/resumes back to back (default: disabled)')
5007         print('   -x2delay t   Include t ms delay between multiple test runs (default: 0 ms)')
5008         print('   -predelay t  Include t ms delay before 1st suspend (default: 0 ms)')
5009         print('   -postdelay t Include t ms delay after last resume (default: 0 ms)')
5010         print('   -mindev ms   Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
5011         print('   -multi n d   Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
5012         print('                be created in a new subdirectory with a summary page.')
5013         print('  [debug]')
5014         print('   -f           Use ftrace to create device callgraphs (default: disabled)')
5015         print('   -expandcg    pre-expand the callgraph data in the html output (default: disabled)')
5016         print('   -flist       Print the list of functions currently being captured in ftrace')
5017         print('   -flistall    Print all functions capable of being captured in ftrace')
5018         print('   -fadd file   Add functions to be graphed in the timeline from a list in a text file')
5019         print('   -filter "d1,d2,..." Filter out all but this comma-delimited list of device names')
5020         print('   -mincg  ms   Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
5021         print('   -cgphase P   Only show callgraph data for phase P (e.g. suspend_late)')
5022         print('   -cgtest N    Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
5023         print('   -timeprec N  Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
5024         print('  [utilities]')
5025         print('   -fpdt        Print out the contents of the ACPI Firmware Performance Data Table')
5026         print('   -usbtopo     Print out the current USB topology with power info')
5027         print('   -usbauto     Enable autosuspend for all connected USB devices')
5028         print('  [re-analyze data from previous runs]')
5029         print('   -ftrace ftracefile  Create HTML output using ftrace input')
5030         print('   -dmesg dmesgfile    Create HTML output using dmesg (not needed for kernel >= 3.15)')
5031         print('   -summary directory  Create a summary of all test in this dir')
5032         print('')
5033         return True
5034
5035 # ----------------- MAIN --------------------
5036 # exec start (skipped if script is loaded as library)
5037 if __name__ == '__main__':
5038         cmd = ''
5039         cmdarg = ''
5040         multitest = {'run': False, 'count': 0, 'delay': 0}
5041         simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
5042         # loop through the command line arguments
5043         args = iter(sys.argv[1:])
5044         for arg in args:
5045                 if(arg == '-m'):
5046                         try:
5047                                 val = args.next()
5048                         except:
5049                                 doError('No mode supplied', True)
5050                         if val == 'command' and not sysvals.testcommand:
5051                                 doError('No command supplied for mode "command"', True)
5052                         sysvals.suspendmode = val
5053                 elif(arg in simplecmds):
5054                         cmd = arg[1:]
5055                 elif(arg == '-h'):
5056                         printHelp()
5057                         sys.exit()
5058                 elif(arg == '-v'):
5059                         print("Version %s" % sysvals.version)
5060                         sys.exit()
5061                 elif(arg == '-x2'):
5062                         sysvals.execcount = 2
5063                 elif(arg == '-x2delay'):
5064                         sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
5065                 elif(arg == '-predelay'):
5066                         sysvals.predelay = getArgInt('-predelay', args, 0, 60000)
5067                 elif(arg == '-postdelay'):
5068                         sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
5069                 elif(arg == '-f'):
5070                         sysvals.usecallgraph = True
5071                 elif(arg == '-addlogs'):
5072                         sysvals.addlogs = True
5073                 elif(arg == '-verbose'):
5074                         sysvals.verbose = True
5075                 elif(arg == '-proc'):
5076                         sysvals.useprocmon = True
5077                 elif(arg == '-dev'):
5078                         sysvals.usedevsrc = True
5079                 elif(arg == '-rtcwake'):
5080                         sysvals.rtcwake = True
5081                         sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
5082                 elif(arg == '-timeprec'):
5083                         sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
5084                 elif(arg == '-mindev'):
5085                         sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
5086                 elif(arg == '-mincg'):
5087                         sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
5088                 elif(arg == '-cgtest'):
5089                         sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
5090                 elif(arg == '-cgphase'):
5091                         try:
5092                                 val = args.next()
5093                         except:
5094                                 doError('No phase name supplied', True)
5095                         d = Data(0)
5096                         if val not in d.phases:
5097                                 doError('Invalid phase, valid phaess are %s' % d.phases, True)
5098                         sysvals.cgphase = val
5099                 elif(arg == '-callloop-maxgap'):
5100                         sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
5101                 elif(arg == '-callloop-maxlen'):
5102                         sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)
5103                 elif(arg == '-cmd'):
5104                         try:
5105                                 val = args.next()
5106                         except:
5107                                 doError('No command string supplied', True)
5108                         sysvals.testcommand = val
5109                         sysvals.suspendmode = 'command'
5110                 elif(arg == '-expandcg'):
5111                         sysvals.cgexp = True
5112                 elif(arg == '-srgap'):
5113                         sysvals.srgap = 5
5114                 elif(arg == '-multi'):
5115                         multitest['run'] = True
5116                         multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
5117                         multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
5118                 elif(arg == '-o'):
5119                         try:
5120                                 val = args.next()
5121                         except:
5122                                 doError('No subdirectory name supplied', True)
5123                         sysvals.setOutputFolder(val)
5124                 elif(arg == '-config'):
5125                         try:
5126                                 val = args.next()
5127                         except:
5128                                 doError('No text file supplied', True)
5129                         if(os.path.exists(val) == False):
5130                                 doError('%s does not exist' % val)
5131                         configFromFile(val)
5132                 elif(arg == '-fadd'):
5133                         try:
5134                                 val = args.next()
5135                         except:
5136                                 doError('No text file supplied', True)
5137                         if(os.path.exists(val) == False):
5138                                 doError('%s does not exist' % val)
5139                         sysvals.addFtraceFilterFunctions(val)
5140                 elif(arg == '-dmesg'):
5141                         try:
5142                                 val = args.next()
5143                         except:
5144                                 doError('No dmesg file supplied', True)
5145                         sysvals.notestrun = True
5146                         sysvals.dmesgfile = val
5147                         if(os.path.exists(sysvals.dmesgfile) == False):
5148                                 doError('%s does not exist' % sysvals.dmesgfile)
5149                 elif(arg == '-ftrace'):
5150                         try:
5151                                 val = args.next()
5152                         except:
5153                                 doError('No ftrace file supplied', True)
5154                         sysvals.notestrun = True
5155                         sysvals.ftracefile = val
5156                         if(os.path.exists(sysvals.ftracefile) == False):
5157                                 doError('%s does not exist' % sysvals.ftracefile)
5158                 elif(arg == '-summary'):
5159                         try:
5160                                 val = args.next()
5161                         except:
5162                                 doError('No directory supplied', True)
5163                         cmd = 'summary'
5164                         cmdarg = val
5165                         sysvals.notestrun = True
5166                         if(os.path.isdir(val) == False):
5167                                 doError('%s is not accesible' % val)
5168                 elif(arg == '-filter'):
5169                         try:
5170                                 val = args.next()
5171                         except:
5172                                 doError('No devnames supplied', True)
5173                         sysvals.setDeviceFilter(val)
5174                 else:
5175                         doError('Invalid argument: '+arg, True)
5176
5177         # compatibility errors
5178         if(sysvals.usecallgraph and sysvals.usedevsrc):
5179                 doError('-dev is not compatible with -f')
5180         if(sysvals.usecallgraph and sysvals.useprocmon):
5181                 doError('-proc is not compatible with -f')
5182
5183         # callgraph size cannot exceed device size
5184         if sysvals.mincglen < sysvals.mindevlen:
5185                 sysvals.mincglen = sysvals.mindevlen
5186
5187         # just run a utility command and exit
5188         if(cmd != ''):
5189                 if(cmd == 'status'):
5190                         statusCheck(True)
5191                 elif(cmd == 'fpdt'):
5192                         getFPDT(True)
5193                 elif(cmd == 'usbtopo'):
5194                         detectUSB()
5195                 elif(cmd == 'modes'):
5196                         print getModes()
5197                 elif(cmd == 'flist'):
5198                         sysvals.getFtraceFilterFunctions(True)
5199                 elif(cmd == 'flistall'):
5200                         sysvals.getFtraceFilterFunctions(False)
5201                 elif(cmd == 'usbauto'):
5202                         setUSBDevicesAuto()
5203                 elif(cmd == 'summary'):
5204                         print("Generating a summary of folder \"%s\"" % cmdarg)
5205                         runSummary(cmdarg, True)
5206                 sys.exit()
5207
5208         # if instructed, re-analyze existing data files
5209         if(sysvals.notestrun):
5210                 rerunTest()
5211                 sys.exit()
5212
5213         # verify that we can run a test
5214         if(not statusCheck()):
5215                 print('Check FAILED, aborting the test run!')
5216                 sys.exit()
5217
5218         if multitest['run']:
5219                 # run multiple tests in a separate subdirectory
5220                 s = 'x%d' % multitest['count']
5221                 if not sysvals.outdir:
5222                         sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
5223                 if not os.path.isdir(sysvals.outdir):
5224                         os.mkdir(sysvals.outdir)
5225                 for i in range(multitest['count']):
5226                         if(i != 0):
5227                                 print('Waiting %d seconds...' % (multitest['delay']))
5228                                 time.sleep(multitest['delay'])
5229                         print('TEST (%d/%d) START' % (i+1, multitest['count']))
5230                         runTest(sysvals.outdir)
5231                         print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
5232                 runSummary(sysvals.outdir, False)
5233         else:
5234                 # run the test in the current directory
5235                 runTest('.', sysvals.outdir)