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