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