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