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 # Description:
  23 #        This tool is designed to assist kernel and OS developers in optimizing
  24 #        their linux stack's suspend/resume time. Using a kernel image built
  25 #        with a few extra options enabled, the tool will execute a suspend and
  26 #        will capture dmesg and ftrace data until resume is complete. This data
  27 #        is transformed into a device timeline and a callgraph to give a quick
  28 #        and detailed view of which devices and callbacks are taking the most
  29 #        time in suspend/resume. The output is a single html file which can be
  30 #        viewed in firefox or chrome.
  31 #
  32 #        The following kernel build options are required:
  33 #                CONFIG_PM_DEBUG=y
  34 #                CONFIG_PM_SLEEP_DEBUG=y
  35 #                CONFIG_FTRACE=y
  36 #                CONFIG_FUNCTION_TRACER=y
  37 #                CONFIG_FUNCTION_GRAPH_TRACER=y
  38 #
  39 #        For kernel versions older than 3.15:
  40 #        The following additional kernel parameters are required:
  41 #                (e.g. in file /etc/default/grub)
  42 #                GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
  43 #
  44
  45 # ----------------- LIBRARIES --------------------
  46
  47 import sys
  48 import time
  49 import os
  50 import string
  51 import re
  52 import platform
  53 from datetime import datetime
  54 import struct
  55
  56 # ----------------- CLASSES --------------------
  57
  58 # Class: SystemValues
  59 # Description:
  60 #        A global, single-instance container used to
  61 #        store system values and test parameters
  62 class SystemValues:
  63         version = 3.0
  64         verbose = False
  65         testdir = '.'
  66         tpath = '/sys/kernel/debug/tracing/'
  67         fpdtpath = '/sys/firmware/acpi/tables/FPDT'
  68         epath = '/sys/kernel/debug/tracing/events/power/'
  69         traceevents = [
  70                 'suspend_resume',
  71                 'device_pm_callback_end',
  72                 'device_pm_callback_start'
  73         ]
  74         modename = {
  75                 'freeze': 'Suspend-To-Idle (S0)',
  76                 'standby': 'Power-On Suspend (S1)',
  77                 'mem': 'Suspend-to-RAM (S3)',
  78                 'disk': 'Suspend-to-disk (S4)'
  79         }
  80         mempath = '/dev/mem'
  81         powerfile = '/sys/power/state'
  82         suspendmode = 'mem'
  83         hostname = 'localhost'
  84         prefix = 'test'
  85         teststamp = ''
  86         dmesgfile = ''
  87         ftracefile = ''
  88         htmlfile = ''
  89         rtcwake = False
  90         rtcwaketime = 10
  91         rtcpath = ''
  92         android = False
  93         adb = 'adb'
  94         devicefilter = []
  95         stamp = 0
  96         execcount = 1
  97         x2delay = 0
  98         usecallgraph = False
  99         usetraceevents = False
 100         usetraceeventsonly = False
 101         notestrun = False
 102         altdevname = dict()
 103         postresumetime = 0
 104         tracertypefmt = '# tracer: (?P<t>.*)'
 105         firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
 106         postresumefmt = '# post resume time (?P<t>[0-9]*)$'
 107         stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
 108                                 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
 109                                 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
 110         def __init__(self):
 111                 self.hostname = platform.node()
 112                 if(self.hostname == ''):
 113                         self.hostname = 'localhost'
 114                 rtc = "rtc0"
 115                 if os.path.exists('/dev/rtc'):
 116                         rtc = os.readlink('/dev/rtc')
 117                 rtc = '/sys/class/rtc/'+rtc
 118                 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
 119                         os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
 120                         self.rtcpath = rtc
 121         def setOutputFile(self):
 122                 if((self.htmlfile == '') and (self.dmesgfile != '')):
 123                         m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
 124                         if(m):
 125                                 self.htmlfile = m.group('name')+'.html'
 126                 if((self.htmlfile == '') and (self.ftracefile != '')):
 127                         m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
 128                         if(m):
 129                                 self.htmlfile = m.group('name')+'.html'
 130                 if(self.htmlfile == ''):
 131                         self.htmlfile = 'output.html'
 132         def initTestOutput(self, subdir):
 133                 if(not self.android):
 134                         self.prefix = self.hostname
 135                         v = open('/proc/version', 'r').read().strip()
 136                         kver = string.split(v)[2]
 137                 else:
 138                         self.prefix = 'android'
 139                         v = os.popen(self.adb+' shell cat /proc/version').read().strip()
 140                         kver = string.split(v)[2]
 141                 testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S')
 142                 if(subdir != "."):
 143                         self.testdir = subdir+"/"+testtime
 144                 else:
 145                         self.testdir = testtime
 146                 self.teststamp = \
 147                         '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
 148                 self.dmesgfile = \
 149                         self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
 150                 self.ftracefile = \
 151                         self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
 152                 self.htmlfile = \
 153                         self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
 154                 os.mkdir(self.testdir)
 155         def setDeviceFilter(self, devnames):
 156                 self.devicefilter = string.split(devnames)
 157         def rtcWakeAlarm(self):
 158                 os.system('echo 0 > '+self.rtcpath+'/wakealarm')
 159                 outD = open(self.rtcpath+'/date', 'r').read().strip()
 160                 outT = open(self.rtcpath+'/time', 'r').read().strip()
 161                 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
 162                 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
 163                 if(mD and mT):
 164                         # get the current time from hardware
 165                         utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
 166                         dt = datetime(\
 167                                 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
 168                                 int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
 169                         nowtime = int(dt.strftime('%s')) + utcoffset
 170                 else:
 171                         # if hardware time fails, use the software time
 172                         nowtime = int(datetime.now().strftime('%s'))
 173                 alarm = nowtime + self.rtcwaketime
 174                 os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
 175
 176 sysvals = SystemValues()
 177
 178 # Class: DeviceNode
 179 # Description:
 180 #        A container used to create a device hierachy, with a single root node
 181 #        and a tree of child nodes. Used by Data.deviceTopology()
 182 class DeviceNode:
 183         name = ''
 184         children = 0
 185         depth = 0
 186         def __init__(self, nodename, nodedepth):
 187                 self.name = nodename
 188                 self.children = []
 189                 self.depth = nodedepth
 190
 191 # Class: Data
 192 # Description:
 193 #        The primary container for suspend/resume test data. There is one for
 194 #        each test run. The data is organized into a cronological hierarchy:
 195 #        Data.dmesg {
 196 #               root structure, started as dmesg & ftrace, but now only ftrace
 197 #               contents: times for suspend start/end, resume start/end, fwdata
 198 #               phases {
 199 #                       10 sequential, non-overlapping phases of S/R
 200 #                       contents: times for phase start/end, order/color data for html
 201 #                       devlist {
 202 #                               device callback or action list for this phase
 203 #                               device {
 204 #                                       a single device callback or generic action
 205 #                                       contents: start/stop times, pid/cpu/driver info
 206 #                                               parents/children, html id for timeline/callgraph
 207 #                                               optionally includes an ftrace callgraph
 208 #                                               optionally includes intradev trace events
 209 #                               }
 210 #                       }
 211 #               }
 212 #       }
 213 #
 214 class Data:
 215         dmesg = {}  # root data structure
 216         phases = [] # ordered list of phases
 217         start = 0.0 # test start
 218         end = 0.0   # test end
 219         tSuspended = 0.0 # low-level suspend start
 220         tResumed = 0.0   # low-level resume start
 221         tLow = 0.0       # time spent in low-level suspend (standby/freeze)
 222         fwValid = False  # is firmware data available
 223         fwSuspend = 0    # time spent in firmware suspend
 224         fwResume = 0     # time spent in firmware resume
 225         dmesgtext = []   # dmesg text file in memory
 226         testnumber = 0
 227         idstr = ''
 228         html_device_id = 0
 229         stamp = 0
 230         outfile = ''
 231         def __init__(self, num):
 232                 idchar = 'abcdefghijklmnopqrstuvwxyz'
 233                 self.testnumber = num
 234                 self.idstr = idchar[num]
 235                 self.dmesgtext = []
 236                 self.phases = []
 237                 self.dmesg = { # fixed list of 10 phases
 238                         'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
 239                                                                 'row': 0, 'color': '#CCFFCC', 'order': 0},
 240                                 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
 241                                                                 'row': 0, 'color': '#88FF88', 'order': 1},
 242                            'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
 243                                                                 'row': 0, 'color': '#00AA00', 'order': 2},
 244                           'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
 245                                                                 'row': 0, 'color': '#008888', 'order': 3},
 246                     'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
 247                                                                 'row': 0, 'color': '#0000FF', 'order': 4},
 248                          'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
 249                                                                 'row': 0, 'color': '#FF0000', 'order': 5},
 250                            'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
 251                                                                 'row': 0, 'color': '#FF9900', 'order': 6},
 252                            'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
 253                                                                 'row': 0, 'color': '#FFCC00', 'order': 7},
 254                                  'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
 255                                                                 'row': 0, 'color': '#FFFF88', 'order': 8},
 256                         'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
 257                                                                 'row': 0, 'color': '#FFFFCC', 'order': 9}
 258                 }
 259                 self.phases = self.sortedPhases()
 260         def getStart(self):
 261                 return self.dmesg[self.phases[0]]['start']
 262         def setStart(self, time):
 263                 self.start = time
 264                 self.dmesg[self.phases[0]]['start'] = time
 265         def getEnd(self):
 266                 return self.dmesg[self.phases[-1]]['end']
 267         def setEnd(self, time):
 268                 self.end = time
 269                 self.dmesg[self.phases[-1]]['end'] = time
 270         def isTraceEventOutsideDeviceCalls(self, pid, time):
 271                 for phase in self.phases:
 272                         list = self.dmesg[phase]['list']
 273                         for dev in list:
 274                                 d = list[dev]
 275                                 if(d['pid'] == pid and time >= d['start'] and
 276                                         time <= d['end']):
 277                                         return False
 278                 return True
 279         def addIntraDevTraceEvent(self, action, name, pid, time):
 280                 if(action == 'mutex_lock_try'):
 281                         color = 'red'
 282                 elif(action == 'mutex_lock_pass'):
 283                         color = 'green'
 284                 elif(action == 'mutex_unlock'):
 285                         color = 'blue'
 286                 else:
 287                         # create separate colors based on the name
 288                         v1 = len(name)*10 % 256
 289                         v2 = string.count(name, 'e')*100 % 256
 290                         v3 = ord(name[0])*20 % 256
 291                         color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3)
 292                 for phase in self.phases:
 293                         list = self.dmesg[phase]['list']
 294                         for dev in list:
 295                                 d = list[dev]
 296                                 if(d['pid'] == pid and time >= d['start'] and
 297                                         time <= d['end']):
 298                                         e = TraceEvent(action, name, color, time)
 299                                         if('traceevents' not in d):
 300                                                 d['traceevents'] = []
 301                                         d['traceevents'].append(e)
 302                                         return d
 303                                         break
 304                 return 0
 305         def capIntraDevTraceEvent(self, action, name, pid, time):
 306                 for phase in self.phases:
 307                         list = self.dmesg[phase]['list']
 308                         for dev in list:
 309                                 d = list[dev]
 310                                 if(d['pid'] == pid and time >= d['start'] and
 311                                         time <= d['end']):
 312                                         if('traceevents' not in d):
 313                                                 return
 314                                         for e in d['traceevents']:
 315                                                 if(e.action == action and
 316                                                         e.name == name and not e.ready):
 317                                                         e.length = time - e.time
 318                                                         e.ready = True
 319                                                         break
 320                                         return
 321         def trimTimeVal(self, t, t0, dT, left):
 322                 if left:
 323                         if(t > t0):
 324                                 if(t - dT < t0):
 325                                         return t0
 326                                 return t - dT
 327                         else:
 328                                 return t
 329                 else:
 330                         if(t < t0 + dT):
 331                                 if(t > t0):
 332                                         return t0 + dT
 333                                 return t + dT
 334                         else:
 335                                 return t
 336         def trimTime(self, t0, dT, left):
 337                 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
 338                 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
 339                 self.start = self.trimTimeVal(self.start, t0, dT, left)
 340                 self.end = self.trimTimeVal(self.end, t0, dT, left)
 341                 for phase in self.phases:
 342                         p = self.dmesg[phase]
 343                         p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
 344                         p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
 345                         list = p['list']
 346                         for name in list:
 347                                 d = list[name]
 348                                 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
 349                                 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
 350                                 if('ftrace' in d):
 351                                         cg = d['ftrace']
 352                                         cg.start = self.trimTimeVal(cg.start, t0, dT, left)
 353                                         cg.end = self.trimTimeVal(cg.end, t0, dT, left)
 354                                         for line in cg.list:
 355                                                 line.time = self.trimTimeVal(line.time, t0, dT, left)
 356                                 if('traceevents' in d):
 357                                         for e in d['traceevents']:
 358                                                 e.time = self.trimTimeVal(e.time, t0, dT, left)
 359         def normalizeTime(self, tZero):
 360                 # first trim out any standby or freeze clock time
 361                 if(self.tSuspended != self.tResumed):
 362                         if(self.tResumed > tZero):
 363                                 self.trimTime(self.tSuspended, \
 364                                         self.tResumed-self.tSuspended, True)
 365                         else:
 366                                 self.trimTime(self.tSuspended, \
 367                                         self.tResumed-self.tSuspended, False)
 368                 # shift the timeline so that tZero is the new 0
 369                 self.tSuspended -= tZero
 370                 self.tResumed -= tZero
 371                 self.start -= tZero
 372                 self.end -= tZero
 373                 for phase in self.phases:
 374                         p = self.dmesg[phase]
 375                         p['start'] -= tZero
 376                         p['end'] -= tZero
 377                         list = p['list']
 378                         for name in list:
 379                                 d = list[name]
 380                                 d['start'] -= tZero
 381                                 d['end'] -= tZero
 382                                 if('ftrace' in d):
 383                                         cg = d['ftrace']
 384                                         cg.start -= tZero
 385                                         cg.end -= tZero
 386                                         for line in cg.list:
 387                                                 line.time -= tZero
 388                                 if('traceevents' in d):
 389                                         for e in d['traceevents']:
 390                                                 e.time -= tZero
 391         def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
 392                 for phase in self.phases:
 393                         self.dmesg[phase]['order'] += 1
 394                 self.html_device_id += 1
 395                 devid = '%s%d' % (self.idstr, self.html_device_id)
 396                 list = dict()
 397                 list[devname] = \
 398                         {'start': start, 'end': end, 'pid': 0, 'par': '',
 399                         'length': (end-start), 'row': 0, 'id': devid, 'drv': '' };
 400                 self.dmesg[phasename] = \
 401                         {'list': list, 'start': start, 'end': end,
 402                         'row': 0, 'color': color, 'order': 0}
 403                 self.phases = self.sortedPhases()
 404         def newPhase(self, phasename, start, end, color, order):
 405                 if(order < 0):
 406                         order = len(self.phases)
 407                 for phase in self.phases[order:]:
 408                         self.dmesg[phase]['order'] += 1
 409                 if(order > 0):
 410                         p = self.phases[order-1]
 411                         self.dmesg[p]['end'] = start
 412                 if(order < len(self.phases)):
 413                         p = self.phases[order]
 414                         self.dmesg[p]['start'] = end
 415                 list = dict()
 416                 self.dmesg[phasename] = \
 417                         {'list': list, 'start': start, 'end': end,
 418                         'row': 0, 'color': color, 'order': order}
 419                 self.phases = self.sortedPhases()
 420         def setPhase(self, phase, ktime, isbegin):
 421                 if(isbegin):
 422                         self.dmesg[phase]['start'] = ktime
 423                 else:
 424                         self.dmesg[phase]['end'] = ktime
 425         def dmesgSortVal(self, phase):
 426                 return self.dmesg[phase]['order']
 427         def sortedPhases(self):
 428                 return sorted(self.dmesg, key=self.dmesgSortVal)
 429         def sortedDevices(self, phase):
 430                 list = self.dmesg[phase]['list']
 431                 slist = []
 432                 tmp = dict()
 433                 for devname in list:
 434                         dev = list[devname]
 435                         tmp[dev['start']] = devname
 436                 for t in sorted(tmp):
 437                         slist.append(tmp[t])
 438                 return slist
 439         def fixupInitcalls(self, phase, end):
 440                 # if any calls never returned, clip them at system resume end
 441                 phaselist = self.dmesg[phase]['list']
 442                 for devname in phaselist:
 443                         dev = phaselist[devname]
 444                         if(dev['end'] < 0):
 445                                 dev['end'] = end
 446                                 vprint('%s (%s): callback didnt return' % (devname, phase))
 447         def deviceFilter(self, devicefilter):
 448                 # remove all by the relatives of the filter devnames
 449                 filter = []
 450                 for phase in self.phases:
 451                         list = self.dmesg[phase]['list']
 452                         for name in devicefilter:
 453                                 dev = name
 454                                 while(dev in list):
 455                                         if(dev not in filter):
 456                                                 filter.append(dev)
 457                                         dev = list[dev]['par']
 458                                 children = self.deviceDescendants(name, phase)
 459                                 for dev in children:
 460                                         if(dev not in filter):
 461                                                 filter.append(dev)
 462                 for phase in self.phases:
 463                         list = self.dmesg[phase]['list']
 464                         rmlist = []
 465                         for name in list:
 466                                 pid = list[name]['pid']
 467                                 if(name not in filter and pid >= 0):
 468                                         rmlist.append(name)
 469                         for name in rmlist:
 470                                 del list[name]
 471         def fixupInitcallsThatDidntReturn(self):
 472                 # if any calls never returned, clip them at system resume end
 473                 for phase in self.phases:
 474                         self.fixupInitcalls(phase, self.getEnd())
 475         def newActionGlobal(self, name, start, end):
 476                 # which phase is this device callback or action "in"
 477                 targetphase = "none"
 478                 overlap = 0.0
 479                 for phase in self.phases:
 480                         pstart = self.dmesg[phase]['start']
 481                         pend = self.dmesg[phase]['end']
 482                         o = max(0, min(end, pend) - max(start, pstart))
 483                         if(o > overlap):
 484                                 targetphase = phase
 485                                 overlap = o
 486                 if targetphase in self.phases:
 487                         self.newAction(targetphase, name, -1, '', start, end, '')
 488                         return True
 489                 return False
 490         def newAction(self, phase, name, pid, parent, start, end, drv):
 491                 # new device callback for a specific phase
 492                 self.html_device_id += 1
 493                 devid = '%s%d' % (self.idstr, self.html_device_id)
 494                 list = self.dmesg[phase]['list']
 495                 length = -1.0
 496                 if(start >= 0 and end >= 0):
 497                         length = end - start
 498                 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
 499                                           'length': length, 'row': 0, 'id': devid, 'drv': drv }
 500         def deviceIDs(self, devlist, phase):
 501                 idlist = []
 502                 list = self.dmesg[phase]['list']
 503                 for devname in list:
 504                         if devname in devlist:
 505                                 idlist.append(list[devname]['id'])
 506                 return idlist
 507         def deviceParentID(self, devname, phase):
 508                 pdev = ''
 509                 pdevid = ''
 510                 list = self.dmesg[phase]['list']
 511                 if devname in list:
 512                         pdev = list[devname]['par']
 513                 if pdev in list:
 514                         return list[pdev]['id']
 515                 return pdev
 516         def deviceChildren(self, devname, phase):
 517                 devlist = []
 518                 list = self.dmesg[phase]['list']
 519                 for child in list:
 520                         if(list[child]['par'] == devname):
 521                                 devlist.append(child)
 522                 return devlist
 523         def deviceDescendants(self, devname, phase):
 524                 children = self.deviceChildren(devname, phase)
 525                 family = children
 526                 for child in children:
 527                         family += self.deviceDescendants(child, phase)
 528                 return family
 529         def deviceChildrenIDs(self, devname, phase):
 530                 devlist = self.deviceChildren(devname, phase)
 531                 return self.deviceIDs(devlist, phase)
 532         def printDetails(self):
 533                 vprint('          test start: %f' % self.start)
 534                 for phase in self.phases:
 535                         dc = len(self.dmesg[phase]['list'])
 536                         vprint('    %16s: %f - %f (%d devices)' % (phase, \
 537                                 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
 538                 vprint('            test end: %f' % self.end)
 539         def masterTopology(self, name, list, depth):
 540                 node = DeviceNode(name, depth)
 541                 for cname in list:
 542                         clist = self.deviceChildren(cname, 'resume')
 543                         cnode = self.masterTopology(cname, clist, depth+1)
 544                         node.children.append(cnode)
 545                 return node
 546         def printTopology(self, node):
 547                 html = ''
 548                 if node.name:
 549                         info = ''
 550                         drv = ''
 551                         for phase in self.phases:
 552                                 list = self.dmesg[phase]['list']
 553                                 if node.name in list:
 554                                         s = list[node.name]['start']
 555                                         e = list[node.name]['end']
 556                                         if list[node.name]['drv']:
 557                                                 drv = ' {'+list[node.name]['drv']+'}'
 558                                         info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
 559                         html += '<li><b>'+node.name+drv+'</b>'
 560                         if info:
 561                                 html += '<ul>'+info+'</ul>'
 562                         html += '</li>'
 563                 if len(node.children) > 0:
 564                         html += '<ul>'
 565                         for cnode in node.children:
 566                                 html += self.printTopology(cnode)
 567                         html += '</ul>'
 568                 return html
 569         def rootDeviceList(self):
 570                 # list of devices graphed
 571                 real = []
 572                 for phase in self.dmesg:
 573                         list = self.dmesg[phase]['list']
 574                         for dev in list:
 575                                 if list[dev]['pid'] >= 0 and dev not in real:
 576                                         real.append(dev)
 577                 # list of top-most root devices
 578                 rootlist = []
 579                 for phase in self.dmesg:
 580                         list = self.dmesg[phase]['list']
 581                         for dev in list:
 582                                 pdev = list[dev]['par']
 583                                 if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
 584                                         continue
 585                                 if pdev and pdev not in real and pdev not in rootlist:
 586                                         rootlist.append(pdev)
 587                 return rootlist
 588         def deviceTopology(self):
 589                 rootlist = self.rootDeviceList()
 590                 master = self.masterTopology('', rootlist, 0)
 591                 return self.printTopology(master)
 592
 593 # Class: TraceEvent
 594 # Description:
 595 #        A container for trace event data found in the ftrace file
 596 class TraceEvent:
 597         ready = False
 598         name = ''
 599         time = 0.0
 600         color = '#FFFFFF'
 601         length = 0.0
 602         action = ''
 603         def __init__(self, a, n, c, t):
 604                 self.action = a
 605                 self.name = n
 606                 self.color = c
 607                 self.time = t
 608
 609 # Class: FTraceLine
 610 # Description:
 611 #        A container for a single line of ftrace data. There are six basic types:
 612 #                callgraph line:
 613 #                         call: "  dpm_run_callback() {"
 614 #                       return: "  }"
 615 #                         leaf: " dpm_run_callback();"
 616 #                trace event:
 617 #                        tracing_mark_write: SUSPEND START or RESUME COMPLETE
 618 #                        suspend_resume: phase or custom exec block data
 619 #                        device_pm_callback: device callback info
 620 class FTraceLine:
 621         time = 0.0
 622         length = 0.0
 623         fcall = False
 624         freturn = False
 625         fevent = False
 626         depth = 0
 627         name = ''
 628         type = ''
 629         def __init__(self, t, m, d):
 630                 self.time = float(t)
 631                 # is this a trace event
 632                 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
 633                         if(d == 'traceevent'):
 634                                 # nop format trace event
 635                                 msg = m
 636                         else:
 637                                 # function_graph format trace event
 638                                 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
 639                                 msg = em.group('msg')
 640
 641                         emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
 642                         if(emm):
 643                                 self.name = emm.group('msg')
 644                                 self.type = emm.group('call')
 645                         else:
 646                                 self.name = msg
 647                         self.fevent = True
 648                         return
 649                 # convert the duration to seconds
 650                 if(d):
 651                         self.length = float(d)/1000000
 652                 # the indentation determines the depth
 653                 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
 654                 if(not match):
 655                         return
 656                 self.depth = self.getDepth(match.group('d'))
 657                 m = match.group('o')
 658                 # function return
 659                 if(m[0] == '}'):
 660                         self.freturn = True
 661                         if(len(m) > 1):
 662                                 # includes comment with function name
 663                                 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
 664                                 if(match):
 665                                         self.name = match.group('n')
 666                 # function call
 667                 else:
 668                         self.fcall = True
 669                         # function call with children
 670                         if(m[-1] == '{'):
 671                                 match = re.match('^(?P<n>.*) *\(.*', m)
 672                                 if(match):
 673                                         self.name = match.group('n')
 674                         # function call with no children (leaf)
 675                         elif(m[-1] == ';'):
 676                                 self.freturn = True
 677                                 match = re.match('^(?P<n>.*) *\(.*', m)
 678                                 if(match):
 679                                         self.name = match.group('n')
 680                         # something else (possibly a trace marker)
 681                         else:
 682                                 self.name = m
 683         def getDepth(self, str):
 684                 return len(str)/2
 685         def debugPrint(self, dev):
 686                 if(self.freturn and self.fcall):
 687                         print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
 688                                 self.depth, self.name, self.length*1000000))
 689                 elif(self.freturn):
 690                         print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
 691                                 self.depth, self.name, self.length*1000000))
 692                 else:
 693                         print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
 694                                 self.depth, self.name, self.length*1000000))
 695
 696 # Class: FTraceCallGraph
 697 # Description:
 698 #        A container for the ftrace callgraph of a single recursive function.
 699 #        This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
 700 #        Each instance is tied to a single device in a single phase, and is
 701 #        comprised of an ordered list of FTraceLine objects
 702 class FTraceCallGraph:
 703         start = -1.0
 704         end = -1.0
 705         list = []
 706         invalid = False
 707         depth = 0
 708         def __init__(self):
 709                 self.start = -1.0
 710                 self.end = -1.0
 711                 self.list = []
 712                 self.depth = 0
 713         def setDepth(self, line):
 714                 if(line.fcall and not line.freturn):
 715                         line.depth = self.depth
 716                         self.depth += 1
 717                 elif(line.freturn and not line.fcall):
 718                         self.depth -= 1
 719                         line.depth = self.depth
 720                 else:
 721                         line.depth = self.depth
 722         def addLine(self, line, match):
 723                 if(not self.invalid):
 724                         self.setDepth(line)
 725                 if(line.depth == 0 and line.freturn):
 726                         if(self.start < 0):
 727                                 self.start = line.time
 728                         self.end = line.time
 729                         self.list.append(line)
 730                         return True
 731                 if(self.invalid):
 732                         return False
 733                 if(len(self.list) >= 1000000 or self.depth < 0):
 734                         if(len(self.list) > 0):
 735                                 first = self.list[0]
 736                                 self.list = []
 737                                 self.list.append(first)
 738                         self.invalid = True
 739                         if(not match):
 740                                 return False
 741                         id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
 742                         window = '(%f - %f)' % (self.start, line.time)
 743                         if(self.depth < 0):
 744                                 print('Too much data for '+id+\
 745                                         ' (buffer overflow), ignoring this callback')
 746                         else:
 747                                 print('Too much data for '+id+\
 748                                         ' '+window+', ignoring this callback')
 749                         return False
 750                 self.list.append(line)
 751                 if(self.start < 0):
 752                         self.start = line.time
 753                 return False
 754         def slice(self, t0, tN):
 755                 minicg = FTraceCallGraph()
 756                 count = -1
 757                 firstdepth = 0
 758                 for l in self.list:
 759                         if(l.time < t0 or l.time > tN):
 760                                 continue
 761                         if(count < 0):
 762                                 if(not l.fcall or l.name == 'dev_driver_string'):
 763                                         continue
 764                                 firstdepth = l.depth
 765                                 count = 0
 766                         l.depth -= firstdepth
 767                         minicg.addLine(l, 0)
 768                         if((count == 0 and l.freturn and l.fcall) or
 769                                 (count > 0 and l.depth <= 0)):
 770                                 break
 771                         count += 1
 772                 return minicg
 773         def sanityCheck(self):
 774                 stack = dict()
 775                 cnt = 0
 776                 for l in self.list:
 777                         if(l.fcall and not l.freturn):
 778                                 stack[l.depth] = l
 779                                 cnt += 1
 780                         elif(l.freturn and not l.fcall):
 781                                 if(l.depth not in stack):
 782                                         return False
 783                                 stack[l.depth].length = l.length
 784                                 stack[l.depth] = 0
 785                                 l.length = 0
 786                                 cnt -= 1
 787                 if(cnt == 0):
 788                         return True
 789                 return False
 790         def debugPrint(self, filename):
 791                 if(filename == 'stdout'):
 792                         print('[%f - %f]') % (self.start, self.end)
 793                         for l in self.list:
 794                                 if(l.freturn and l.fcall):
 795                                         print('%f (%02d): %s(); (%.3f us)' % (l.time, \
 796                                                 l.depth, l.name, l.length*1000000))
 797                                 elif(l.freturn):
 798                                         print('%f (%02d): %s} (%.3f us)' % (l.time, \
 799                                                 l.depth, l.name, l.length*1000000))
 800                                 else:
 801                                         print('%f (%02d): %s() { (%.3f us)' % (l.time, \
 802                                                 l.depth, l.name, l.length*1000000))
 803                         print(' ')
 804                 else:
 805                         fp = open(filename, 'w')
 806                         print(filename)
 807                         for l in self.list:
 808                                 if(l.freturn and l.fcall):
 809                                         fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \
 810                                                 l.depth, l.name, l.length*1000000))
 811                                 elif(l.freturn):
 812                                         fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \
 813                                                 l.depth, l.name, l.length*1000000))
 814                                 else:
 815                                         fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \
 816                                                 l.depth, l.name, l.length*1000000))
 817                         fp.close()
 818
 819 # Class: Timeline
 820 # Description:
 821 #        A container for a suspend/resume html timeline. In older versions
 822 #        of the script there were multiple timelines, but in the latest
 823 #        there is only one.
 824 class Timeline:
 825         html = {}
 826         scaleH = 0.0 # height of the row as a percent of the timeline height
 827         rowH = 0.0 # height of each row in percent of the timeline height
 828         row_height_pixels = 30
 829         maxrows = 0
 830         height = 0
 831         def __init__(self):
 832                 self.html = {
 833                         'timeline': '',
 834                         'legend': '',
 835                         'scale': ''
 836                 }
 837         def setRows(self, rows):
 838                 self.maxrows = int(rows)
 839                 self.scaleH = 100.0/float(self.maxrows)
 840                 self.height = self.maxrows*self.row_height_pixels
 841                 r = float(self.maxrows - 1)
 842                 if(r < 1.0):
 843                         r = 1.0
 844                 self.rowH = (100.0 - self.scaleH)/r
 845
 846 # Class: TestRun
 847 # Description:
 848 #        A container for a suspend/resume test run. This is necessary as
 849 #        there could be more than one, and they need to be separate.
 850 class TestRun:
 851         ftrace_line_fmt_fg = \
 852                 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
 853                 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
 854                 '[ +!]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)'
 855         ftrace_line_fmt_nop = \
 856                 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
 857                 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
 858                 '(?P<msg>.*)'
 859         ftrace_line_fmt = ftrace_line_fmt_nop
 860         cgformat = False
 861         ftemp = dict()
 862         ttemp = dict()
 863         inthepipe = False
 864         tracertype = ''
 865         data = 0
 866         def __init__(self, dataobj):
 867                 self.data = dataobj
 868                 self.ftemp = dict()
 869                 self.ttemp = dict()
 870         def isReady(self):
 871                 if(tracertype == '' or not data):
 872                         return False
 873                 return True
 874         def setTracerType(self, tracer):
 875                 self.tracertype = tracer
 876                 if(tracer == 'function_graph'):
 877                         self.cgformat = True
 878                         self.ftrace_line_fmt = self.ftrace_line_fmt_fg
 879                 elif(tracer == 'nop'):
 880                         self.ftrace_line_fmt = self.ftrace_line_fmt_nop
 881                 else:
 882                         doError('Invalid tracer format: [%s]' % tracer, False)
 883
 884 # ----------------- FUNCTIONS --------------------
 885
 886 # Function: vprint
 887 # Description:
 888 #        verbose print (prints only with -verbose option)
 889 # Arguments:
 890 #        msg: the debug/log message to print
 891 def vprint(msg):
 892         global sysvals
 893         if(sysvals.verbose):
 894                 print(msg)
 895
 896 # Function: initFtrace
 897 # Description:
 898 #        Configure ftrace to use trace events and/or a callgraph
 899 def initFtrace():
 900         global sysvals
 901
 902         tp = sysvals.tpath
 903         cf = 'dpm_run_callback'
 904         if(sysvals.usetraceeventsonly):
 905                 cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback'
 906         if(sysvals.usecallgraph or sysvals.usetraceevents):
 907                 print('INITIALIZING FTRACE...')
 908                 # turn trace off
 909                 os.system('echo 0 > '+tp+'tracing_on')
 910                 # set the trace clock to global
 911                 os.system('echo global > '+tp+'trace_clock')
 912                 # set trace buffer to a huge value
 913                 os.system('echo nop > '+tp+'current_tracer')
 914                 os.system('echo 100000 > '+tp+'buffer_size_kb')
 915                 # initialize the callgraph trace, unless this is an x2 run
 916                 if(sysvals.usecallgraph and sysvals.execcount == 1):
 917                         # set trace type
 918                         os.system('echo function_graph > '+tp+'current_tracer')
 919                         os.system('echo "" > '+tp+'set_ftrace_filter')
 920                         # set trace format options
 921                         os.system('echo funcgraph-abstime > '+tp+'trace_options')
 922                         os.system('echo funcgraph-proc > '+tp+'trace_options')
 923                         # focus only on device suspend and resume
 924                         os.system('cat '+tp+'available_filter_functions | grep '+\
 925                                 cf+' > '+tp+'set_graph_function')
 926                 if(sysvals.usetraceevents):
 927                         # turn trace events on
 928                         events = iter(sysvals.traceevents)
 929                         for e in events:
 930                                 os.system('echo 1 > '+sysvals.epath+e+'/enable')
 931                 # clear the trace buffer
 932                 os.system('echo "" > '+tp+'trace')
 933
 934 # Function: initFtraceAndroid
 935 # Description:
 936 #        Configure ftrace to capture trace events
 937 def initFtraceAndroid():
 938         global sysvals
 939
 940         tp = sysvals.tpath
 941         if(sysvals.usetraceevents):
 942                 print('INITIALIZING FTRACE...')
 943                 # turn trace off
 944                 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
 945                 # set the trace clock to global
 946                 os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'")
 947                 # set trace buffer to a huge value
 948                 os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'")
 949                 os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'")
 950                 # turn trace events on
 951                 events = iter(sysvals.traceevents)
 952                 for e in events:
 953                         os.system(sysvals.adb+" shell 'echo 1 > "+\
 954                                 sysvals.epath+e+"/enable'")
 955                 # clear the trace buffer
 956                 os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'")
 957
 958 # Function: verifyFtrace
 959 # Description:
 960 #        Check that ftrace is working on the system
 961 # Output:
 962 #        True or False
 963 def verifyFtrace():
 964         global sysvals
 965         # files needed for any trace data
 966         files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
 967                          'trace_marker', 'trace_options', 'tracing_on']
 968         # files needed for callgraph trace data
 969         tp = sysvals.tpath
 970         if(sysvals.usecallgraph):
 971                 files += [
 972                         'available_filter_functions',
 973                         'set_ftrace_filter',
 974                         'set_graph_function'
 975                 ]
 976         for f in files:
 977                 if(sysvals.android):
 978                         out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip()
 979                         if(out != tp+f):
 980                                 return False
 981                 else:
 982                         if(os.path.exists(tp+f) == False):
 983                                 return False
 984         return True
 985
 986 # Function: parseStamp
 987 # Description:
 988 #        Pull in the stamp comment line from the data file(s),
 989 #        create the stamp, and add it to the global sysvals object
 990 # Arguments:
 991 #        m: the valid re.match output for the stamp line
 992 def parseStamp(m, data):
 993         global sysvals
 994         data.stamp = {'time': '', 'host': '', 'mode': ''}
 995         dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
 996                 int(m.group('d')), int(m.group('H')), int(m.group('M')),
 997                 int(m.group('S')))
 998         data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
 999         data.stamp['host'] = m.group('host')
1000         data.stamp['mode'] = m.group('mode')
1001         data.stamp['kernel'] = m.group('kernel')
1002         sysvals.suspendmode = data.stamp['mode']
1003         if not sysvals.stamp:
1004                 sysvals.stamp = data.stamp
1005
1006 # Function: diffStamp
1007 # Description:
1008 #       compare the host, kernel, and mode fields in 3 stamps
1009 # Arguments:
1010 #        stamp1: string array with mode, kernel, and host
1011 #        stamp2: string array with mode, kernel, and host
1012 # Return:
1013 #       True if stamps differ, False if they're the same
1014 def diffStamp(stamp1, stamp2):
1015         if 'host' in stamp1 and 'host' in stamp2:
1016                 if stamp1['host'] != stamp2['host']:
1017                         return True
1018         if 'kernel' in stamp1 and 'kernel' in stamp2:
1019                 if stamp1['kernel'] != stamp2['kernel']:
1020                         return True
1021         if 'mode' in stamp1 and 'mode' in stamp2:
1022                 if stamp1['mode'] != stamp2['mode']:
1023                         return True
1024         return False
1025
1026 # Function: doesTraceLogHaveTraceEvents
1027 # Description:
1028 #        Quickly determine if the ftrace log has some or all of the trace events
1029 #        required for primary parsing. Set the usetraceevents and/or
1030 #        usetraceeventsonly flags in the global sysvals object
1031 def doesTraceLogHaveTraceEvents():
1032         global sysvals
1033
1034         sysvals.usetraceeventsonly = True
1035         sysvals.usetraceevents = False
1036         for e in sysvals.traceevents:
1037                 out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read()
1038                 if(not out):
1039                         sysvals.usetraceeventsonly = False
1040                 if(e == 'suspend_resume' and out):
1041                         sysvals.usetraceevents = True
1042
1043 # Function: appendIncompleteTraceLog
1044 # Description:
1045 #        [deprecated for kernel 3.15 or newer]
1046 #        Legacy support of ftrace outputs that lack the device_pm_callback
1047 #        and/or suspend_resume trace events. The primary data should be
1048 #        taken from dmesg, and this ftrace is used only for callgraph data
1049 #        or custom actions in the timeline. The data is appended to the Data
1050 #        objects provided.
1051 # Arguments:
1052 #        testruns: the array of Data objects obtained from parseKernelLog
1053 def appendIncompleteTraceLog(testruns):
1054         global sysvals
1055
1056         # create TestRun vessels for ftrace parsing
1057         testcnt = len(testruns)
1058         testidx = -1
1059         testrun = []
1060         for data in testruns:
1061                 testrun.append(TestRun(data))
1062
1063         # extract the callgraph and traceevent data
1064         vprint('Analyzing the ftrace data...')
1065         tf = open(sysvals.ftracefile, 'r')
1066         for line in tf:
1067                 # remove any latent carriage returns
1068                 line = line.replace('\r\n', '')
1069                 # grab the time stamp first (signifies the start of the test run)
1070                 m = re.match(sysvals.stampfmt, line)
1071                 if(m):
1072                         testidx += 1
1073                         parseStamp(m, testrun[testidx].data)
1074                         continue
1075                 # pull out any firmware data
1076                 if(re.match(sysvals.firmwarefmt, line)):
1077                         continue
1078                 # if we havent found a test time stamp yet keep spinning til we do
1079                 if(testidx < 0):
1080                         continue
1081                 # determine the trace data type (required for further parsing)
1082                 m = re.match(sysvals.tracertypefmt, line)
1083                 if(m):
1084                         tracer = m.group('t')
1085                         testrun[testidx].setTracerType(tracer)
1086                         continue
1087                 # parse only valid lines, if this isnt one move on
1088                 m = re.match(testrun[testidx].ftrace_line_fmt, line)
1089                 if(not m):
1090                         continue
1091                 # gather the basic message data from the line
1092                 m_time = m.group('time')
1093                 m_pid = m.group('pid')
1094                 m_msg = m.group('msg')
1095                 if(testrun[testidx].cgformat):
1096                         m_param3 = m.group('dur')
1097                 else:
1098                         m_param3 = 'traceevent'
1099                 if(m_time and m_pid and m_msg):
1100                         t = FTraceLine(m_time, m_msg, m_param3)
1101                         pid = int(m_pid)
1102                 else:
1103                         continue
1104                 # the line should be a call, return, or event
1105                 if(not t.fcall and not t.freturn and not t.fevent):
1106                         continue
1107                 # only parse the ftrace data during suspend/resume
1108                 data = testrun[testidx].data
1109                 if(not testrun[testidx].inthepipe):
1110                         # look for the suspend start marker
1111                         if(t.fevent):
1112                                 if(t.name == 'SUSPEND START'):
1113                                         testrun[testidx].inthepipe = True
1114                                         data.setStart(t.time)
1115                                 continue
1116                 else:
1117                         # trace event processing
1118                         if(t.fevent):
1119                                 if(t.name == 'RESUME COMPLETE'):
1120                                         testrun[testidx].inthepipe = False
1121                                         data.setEnd(t.time)
1122                                         if(testidx == testcnt - 1):
1123                                                 break
1124                                         continue
1125                                 # general trace events have two types, begin and end
1126                                 if(re.match('(?P<name>.*) begin$', t.name)):
1127                                         isbegin = True
1128                                 elif(re.match('(?P<name>.*) end$', t.name)):
1129                                         isbegin = False
1130                                 else:
1131                                         continue
1132                                 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1133                                 if(m):
1134                                         val = m.group('val')
1135                                         if val == '0':
1136                                                 name = m.group('name')
1137                                         else:
1138                                                 name = m.group('name')+'['+val+']'
1139                                 else:
1140                                         m = re.match('(?P<name>.*) .*', t.name)
1141                                         name = m.group('name')
1142                                 # special processing for trace events
1143                                 if re.match('dpm_prepare\[.*', name):
1144                                         continue
1145                                 elif re.match('machine_suspend.*', name):
1146                                         continue
1147                                 elif re.match('suspend_enter\[.*', name):
1148                                         if(not isbegin):
1149                                                 data.dmesg['suspend_prepare']['end'] = t.time
1150                                         continue
1151                                 elif re.match('dpm_suspend\[.*', name):
1152                                         if(not isbegin):
1153                                                 data.dmesg['suspend']['end'] = t.time
1154                                         continue
1155                                 elif re.match('dpm_suspend_late\[.*', name):
1156                                         if(isbegin):
1157                                                 data.dmesg['suspend_late']['start'] = t.time
1158                                         else:
1159                                                 data.dmesg['suspend_late']['end'] = t.time
1160                                         continue
1161                                 elif re.match('dpm_suspend_noirq\[.*', name):
1162                                         if(isbegin):
1163                                                 data.dmesg['suspend_noirq']['start'] = t.time
1164                                         else:
1165                                                 data.dmesg['suspend_noirq']['end'] = t.time
1166                                         continue
1167                                 elif re.match('dpm_resume_noirq\[.*', name):
1168                                         if(isbegin):
1169                                                 data.dmesg['resume_machine']['end'] = t.time
1170                                                 data.dmesg['resume_noirq']['start'] = t.time
1171                                         else:
1172                                                 data.dmesg['resume_noirq']['end'] = t.time
1173                                         continue
1174                                 elif re.match('dpm_resume_early\[.*', name):
1175                                         if(isbegin):
1176                                                 data.dmesg['resume_early']['start'] = t.time
1177                                         else:
1178                                                 data.dmesg['resume_early']['end'] = t.time
1179                                         continue
1180                                 elif re.match('dpm_resume\[.*', name):
1181                                         if(isbegin):
1182                                                 data.dmesg['resume']['start'] = t.time
1183                                         else:
1184                                                 data.dmesg['resume']['end'] = t.time
1185                                         continue
1186                                 elif re.match('dpm_complete\[.*', name):
1187                                         if(isbegin):
1188                                                 data.dmesg['resume_complete']['start'] = t.time
1189                                         else:
1190                                                 data.dmesg['resume_complete']['end'] = t.time
1191                                         continue
1192                                 # is this trace event outside of the devices calls
1193                                 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1194                                         # global events (outside device calls) are simply graphed
1195                                         if(isbegin):
1196                                                 # store each trace event in ttemp
1197                                                 if(name not in testrun[testidx].ttemp):
1198                                                         testrun[testidx].ttemp[name] = []
1199                                                 testrun[testidx].ttemp[name].append(\
1200                                                         {'begin': t.time, 'end': t.time})
1201                                         else:
1202                                                 # finish off matching trace event in ttemp
1203                                                 if(name in testrun[testidx].ttemp):
1204                                                         testrun[testidx].ttemp[name][-1]['end'] = t.time
1205                                 else:
1206                                         if(isbegin):
1207                                                 data.addIntraDevTraceEvent('', name, pid, t.time)
1208                                         else:
1209                                                 data.capIntraDevTraceEvent('', name, pid, t.time)
1210                         # call/return processing
1211                         elif sysvals.usecallgraph:
1212                                 # create a callgraph object for the data
1213                                 if(pid not in testrun[testidx].ftemp):
1214                                         testrun[testidx].ftemp[pid] = []
1215                                         testrun[testidx].ftemp[pid].append(FTraceCallGraph())
1216                                 # when the call is finished, see which device matches it
1217                                 cg = testrun[testidx].ftemp[pid][-1]
1218                                 if(cg.addLine(t, m)):
1219                                         testrun[testidx].ftemp[pid].append(FTraceCallGraph())
1220         tf.close()
1221
1222         for test in testrun:
1223                 # add the traceevent data to the device hierarchy
1224                 if(sysvals.usetraceevents):
1225                         for name in test.ttemp:
1226                                 for event in test.ttemp[name]:
1227                                         begin = event['begin']
1228                                         end = event['end']
1229                                         # if event starts before timeline start, expand timeline
1230                                         if(begin < test.data.start):
1231                                                 test.data.setStart(begin)
1232                                         # if event ends after timeline end, expand the timeline
1233                                         if(end > test.data.end):
1234                                                 test.data.setEnd(end)
1235                                         test.data.newActionGlobal(name, begin, end)
1236
1237                 # add the callgraph data to the device hierarchy
1238                 for pid in test.ftemp:
1239                         for cg in test.ftemp[pid]:
1240                                 if(not cg.sanityCheck()):
1241                                         id = 'task %s cpu %s' % (pid, m.group('cpu'))
1242                                         vprint('Sanity check failed for '+\
1243                                                 id+', ignoring this callback')
1244                                         continue
1245                                 callstart = cg.start
1246                                 callend = cg.end
1247                                 for p in test.data.phases:
1248                                         if(test.data.dmesg[p]['start'] <= callstart and
1249                                                 callstart <= test.data.dmesg[p]['end']):
1250                                                 list = test.data.dmesg[p]['list']
1251                                                 for devname in list:
1252                                                         dev = list[devname]
1253                                                         if(pid == dev['pid'] and
1254                                                                 callstart <= dev['start'] and
1255                                                                 callend >= dev['end']):
1256                                                                 dev['ftrace'] = cg
1257                                                 break
1258
1259                 if(sysvals.verbose):
1260                         test.data.printDetails()
1261
1262
1263         # add the time in between the tests as a new phase so we can see it
1264         if(len(testruns) > 1):
1265                 t1e = testruns[0].getEnd()
1266                 t2s = testruns[-1].getStart()
1267                 testruns[-1].newPhaseWithSingleAction('user mode', \
1268                         'user mode', t1e, t2s, '#FF9966')
1269
1270 # Function: parseTraceLog
1271 # Description:
1272 #        Analyze an ftrace log output file generated from this app during
1273 #        the execution phase. Used when the ftrace log is the primary data source
1274 #        and includes the suspend_resume and device_pm_callback trace events
1275 #        The ftrace filename is taken from sysvals
1276 # Output:
1277 #        An array of Data objects
1278 def parseTraceLog():
1279         global sysvals
1280
1281         vprint('Analyzing the ftrace data...')
1282         if(os.path.exists(sysvals.ftracefile) == False):
1283                 doError('%s doesnt exist' % sysvals.ftracefile, False)
1284
1285         # extract the callgraph and traceevent data
1286         testruns = []
1287         testdata = []
1288         testrun = 0
1289         data = 0
1290         tf = open(sysvals.ftracefile, 'r')
1291         phase = 'suspend_prepare'
1292         for line in tf:
1293                 # remove any latent carriage returns
1294                 line = line.replace('\r\n', '')
1295                 # stamp line: each stamp means a new test run
1296                 m = re.match(sysvals.stampfmt, line)
1297                 if(m):
1298                         data = Data(len(testdata))
1299                         testdata.append(data)
1300                         testrun = TestRun(data)
1301                         testruns.append(testrun)
1302                         parseStamp(m, data)
1303                         continue
1304                 if(not data):
1305                         continue
1306                 # firmware line: pull out any firmware data
1307                 m = re.match(sysvals.firmwarefmt, line)
1308                 if(m):
1309                         data.fwSuspend = int(m.group('s'))
1310                         data.fwResume = int(m.group('r'))
1311                         if(data.fwSuspend > 0 or data.fwResume > 0):
1312                                 data.fwValid = True
1313                         continue
1314                 # tracer type line: determine the trace data type
1315                 m = re.match(sysvals.tracertypefmt, line)
1316                 if(m):
1317                         tracer = m.group('t')
1318                         testrun.setTracerType(tracer)
1319                         continue
1320                 # post resume time line: did this test run include post-resume data
1321                 m = re.match(sysvals.postresumefmt, line)
1322                 if(m):
1323                         t = int(m.group('t'))
1324                         if(t > 0):
1325                                 sysvals.postresumetime = t
1326                         continue
1327                 # ftrace line: parse only valid lines
1328                 m = re.match(testrun.ftrace_line_fmt, line)
1329                 if(not m):
1330                         continue
1331                 # gather the basic message data from the line
1332                 m_time = m.group('time')
1333                 m_pid = m.group('pid')
1334                 m_msg = m.group('msg')
1335                 if(testrun.cgformat):
1336                         m_param3 = m.group('dur')
1337                 else:
1338                         m_param3 = 'traceevent'
1339                 if(m_time and m_pid and m_msg):
1340                         t = FTraceLine(m_time, m_msg, m_param3)
1341                         pid = int(m_pid)
1342                 else:
1343                         continue
1344                 # the line should be a call, return, or event
1345                 if(not t.fcall and not t.freturn and not t.fevent):
1346                         continue
1347                 # only parse the ftrace data during suspend/resume
1348                 if(not testrun.inthepipe):
1349                         # look for the suspend start marker
1350                         if(t.fevent):
1351                                 if(t.name == 'SUSPEND START'):
1352                                         testrun.inthepipe = True
1353                                         data.setStart(t.time)
1354                         continue
1355                 # trace event processing
1356                 if(t.fevent):
1357                         if(t.name == 'RESUME COMPLETE'):
1358                                 if(sysvals.postresumetime > 0):
1359                                         phase = 'post_resume'
1360                                         data.newPhase(phase, t.time, t.time, '#FF9966', -1)
1361                                 else:
1362                                         testrun.inthepipe = False
1363                                 data.setEnd(t.time)
1364                                 continue
1365                         if(phase == 'post_resume'):
1366                                 data.setEnd(t.time)
1367                         if(t.type == 'suspend_resume'):
1368                                 # suspend_resume trace events have two types, begin and end
1369                                 if(re.match('(?P<name>.*) begin$', t.name)):
1370                                         isbegin = True
1371                                 elif(re.match('(?P<name>.*) end$', t.name)):
1372                                         isbegin = False
1373                                 else:
1374                                         continue
1375                                 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1376                                 if(m):
1377                                         val = m.group('val')
1378                                         if val == '0':
1379                                                 name = m.group('name')
1380                                         else:
1381                                                 name = m.group('name')+'['+val+']'
1382                                 else:
1383                                         m = re.match('(?P<name>.*) .*', t.name)
1384                                         name = m.group('name')
1385                                 # ignore these events
1386                                 if(re.match('acpi_suspend\[.*', t.name) or
1387                                         re.match('suspend_enter\[.*', name)):
1388                                         continue
1389                                 # -- phase changes --
1390                                 # suspend_prepare start
1391                                 if(re.match('dpm_prepare\[.*', t.name)):
1392                                         phase = 'suspend_prepare'
1393                                         if(not isbegin):
1394                                                 data.dmesg[phase]['end'] = t.time
1395                                         continue
1396                                 # suspend start
1397                                 elif(re.match('dpm_suspend\[.*', t.name)):
1398                                         phase = 'suspend'
1399                                         data.setPhase(phase, t.time, isbegin)
1400                                         continue
1401                                 # suspend_late start
1402                                 elif(re.match('dpm_suspend_late\[.*', t.name)):
1403                                         phase = 'suspend_late'
1404                                         data.setPhase(phase, t.time, isbegin)
1405                                         continue
1406                                 # suspend_noirq start
1407                                 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
1408                                         phase = 'suspend_noirq'
1409                                         data.setPhase(phase, t.time, isbegin)
1410                                         if(not isbegin):
1411                                                 phase = 'suspend_machine'
1412                                                 data.dmesg[phase]['start'] = t.time
1413                                         continue
1414                                 # suspend_machine/resume_machine
1415                                 elif(re.match('machine_suspend\[.*', t.name)):
1416                                         if(isbegin):
1417                                                 phase = 'suspend_machine'
1418                                                 data.dmesg[phase]['end'] = t.time
1419                                                 data.tSuspended = t.time
1420                                         else:
1421                                                 if(sysvals.suspendmode in ['mem', 'disk']):
1422                                                         data.dmesg['suspend_machine']['end'] = t.time
1423                                                         data.tSuspended = t.time
1424                                                 phase = 'resume_machine'
1425                                                 data.dmesg[phase]['start'] = t.time
1426                                                 data.tResumed = t.time
1427                                                 data.tLow = data.tResumed - data.tSuspended
1428                                         continue
1429                                 # resume_noirq start
1430                                 elif(re.match('dpm_resume_noirq\[.*', t.name)):
1431                                         phase = 'resume_noirq'
1432                                         data.setPhase(phase, t.time, isbegin)
1433                                         if(isbegin):
1434                                                 data.dmesg['resume_machine']['end'] = t.time
1435                                         continue
1436                                 # resume_early start
1437                                 elif(re.match('dpm_resume_early\[.*', t.name)):
1438                                         phase = 'resume_early'
1439                                         data.setPhase(phase, t.time, isbegin)
1440                                         continue
1441                                 # resume start
1442                                 elif(re.match('dpm_resume\[.*', t.name)):
1443                                         phase = 'resume'
1444                                         data.setPhase(phase, t.time, isbegin)
1445                                         continue
1446                                 # resume complete start
1447                                 elif(re.match('dpm_complete\[.*', t.name)):
1448                                         phase = 'resume_complete'
1449                                         if(isbegin):
1450                                                 data.dmesg[phase]['start'] = t.time
1451                                         continue
1452
1453                                 # is this trace event outside of the devices calls
1454                                 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1455                                         # global events (outside device calls) are simply graphed
1456                                         if(name not in testrun.ttemp):
1457                                                 testrun.ttemp[name] = []
1458                                         if(isbegin):
1459                                                 # create a new list entry
1460                                                 testrun.ttemp[name].append(\
1461                                                         {'begin': t.time, 'end': t.time})
1462                                         else:
1463                                                 if(len(testrun.ttemp[name]) > 0):
1464                                                         # if an antry exists, assume this is its end
1465                                                         testrun.ttemp[name][-1]['end'] = t.time
1466                                                 elif(phase == 'post_resume'):
1467                                                         # post resume events can just have ends
1468                                                         testrun.ttemp[name].append({
1469                                                                 'begin': data.dmesg[phase]['start'],
1470                                                                 'end': t.time})
1471                                 else:
1472                                         if(isbegin):
1473                                                 data.addIntraDevTraceEvent('', name, pid, t.time)
1474                                         else:
1475                                                 data.capIntraDevTraceEvent('', name, pid, t.time)
1476                         # device callback start
1477                         elif(t.type == 'device_pm_callback_start'):
1478                                 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
1479                                         t.name);
1480                                 if(not m):
1481                                         continue
1482                                 drv = m.group('drv')
1483                                 n = m.group('d')
1484                                 p = m.group('p')
1485                                 if(n and p):
1486                                         data.newAction(phase, n, pid, p, t.time, -1, drv)
1487                         # device callback finish
1488                         elif(t.type == 'device_pm_callback_end'):
1489                                 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
1490                                 if(not m):
1491                                         continue
1492                                 n = m.group('d')
1493                                 list = data.dmesg[phase]['list']
1494                                 if(n in list):
1495                                         dev = list[n]
1496                                         dev['length'] = t.time - dev['start']
1497                                         dev['end'] = t.time
1498                 # callgraph processing
1499                 elif sysvals.usecallgraph:
1500                         # this shouldn't happen, but JIC, ignore callgraph data post-res
1501                         if(phase == 'post_resume'):
1502                                 continue
1503                         # create a callgraph object for the data
1504                         if(pid not in testrun.ftemp):
1505                                 testrun.ftemp[pid] = []
1506                                 testrun.ftemp[pid].append(FTraceCallGraph())
1507                         # when the call is finished, see which device matches it
1508                         cg = testrun.ftemp[pid][-1]
1509                         if(cg.addLine(t, m)):
1510                                 testrun.ftemp[pid].append(FTraceCallGraph())
1511         tf.close()
1512
1513         for test in testruns:
1514                 # add the traceevent data to the device hierarchy
1515                 if(sysvals.usetraceevents):
1516                         for name in test.ttemp:
1517                                 for event in test.ttemp[name]:
1518                                         begin = event['begin']
1519                                         end = event['end']
1520                                         # if event starts before timeline start, expand timeline
1521                                         if(begin < test.data.start):
1522                                                 test.data.setStart(begin)
1523                                         # if event ends after timeline end, expand the timeline
1524                                         if(end > test.data.end):
1525                                                 test.data.setEnd(end)
1526                                         test.data.newActionGlobal(name, begin, end)
1527
1528                 # add the callgraph data to the device hierarchy
1529                 borderphase = {
1530                         'dpm_prepare': 'suspend_prepare',
1531                         'dpm_complete': 'resume_complete'
1532                 }
1533                 for pid in test.ftemp:
1534                         for cg in test.ftemp[pid]:
1535                                 if len(cg.list) < 2:
1536                                         continue
1537                                 if(not cg.sanityCheck()):
1538                                         id = 'task %s cpu %s' % (pid, m.group('cpu'))
1539                                         vprint('Sanity check failed for '+\
1540                                                 id+', ignoring this callback')
1541                                         continue
1542                                 callstart = cg.start
1543                                 callend = cg.end
1544                                 if(cg.list[0].name in borderphase):
1545                                         p = borderphase[cg.list[0].name]
1546                                         list = test.data.dmesg[p]['list']
1547                                         for devname in list:
1548                                                 dev = list[devname]
1549                                                 if(pid == dev['pid'] and
1550                                                         callstart <= dev['start'] and
1551                                                         callend >= dev['end']):
1552                                                         dev['ftrace'] = cg.slice(dev['start'], dev['end'])
1553                                         continue
1554                                 if(cg.list[0].name != 'dpm_run_callback'):
1555                                         continue
1556                                 for p in test.data.phases:
1557                                         if(test.data.dmesg[p]['start'] <= callstart and
1558                                                 callstart <= test.data.dmesg[p]['end']):
1559                                                 list = test.data.dmesg[p]['list']
1560                                                 for devname in list:
1561                                                         dev = list[devname]
1562                                                         if(pid == dev['pid'] and
1563                                                                 callstart <= dev['start'] and
1564                                                                 callend >= dev['end']):
1565                                                                 dev['ftrace'] = cg
1566                                                 break
1567
1568         # fill in any missing phases
1569         for data in testdata:
1570                 lp = data.phases[0]
1571                 for p in data.phases:
1572                         if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
1573                                 print('WARNING: phase "%s" is missing!' % p)
1574                         if(data.dmesg[p]['start'] < 0):
1575                                 data.dmesg[p]['start'] = data.dmesg[lp]['end']
1576                                 if(p == 'resume_machine'):
1577                                         data.tSuspended = data.dmesg[lp]['end']
1578                                         data.tResumed = data.dmesg[lp]['end']
1579                                         data.tLow = 0
1580                         if(data.dmesg[p]['end'] < 0):
1581                                 data.dmesg[p]['end'] = data.dmesg[p]['start']
1582                         lp = p
1583
1584                 if(len(sysvals.devicefilter) > 0):
1585                         data.deviceFilter(sysvals.devicefilter)
1586                 data.fixupInitcallsThatDidntReturn()
1587                 if(sysvals.verbose):
1588                         data.printDetails()
1589
1590         # add the time in between the tests as a new phase so we can see it
1591         if(len(testdata) > 1):
1592                 t1e = testdata[0].getEnd()
1593                 t2s = testdata[-1].getStart()
1594                 testdata[-1].newPhaseWithSingleAction('user mode', \
1595                         'user mode', t1e, t2s, '#FF9966')
1596         return testdata
1597
1598 # Function: loadKernelLog
1599 # Description:
1600 #        [deprecated for kernel 3.15.0 or newer]
1601 #        load the dmesg file into memory and fix up any ordering issues
1602 #        The dmesg filename is taken from sysvals
1603 # Output:
1604 #        An array of empty Data objects with only their dmesgtext attributes set
1605 def loadKernelLog():
1606         global sysvals
1607
1608         vprint('Analyzing the dmesg data...')
1609         if(os.path.exists(sysvals.dmesgfile) == False):
1610                 doError('%s doesnt exist' % sysvals.dmesgfile, False)
1611
1612         # there can be multiple test runs in a single file delineated by stamps
1613         testruns = []
1614         data = 0
1615         lf = open(sysvals.dmesgfile, 'r')
1616         for line in lf:
1617                 line = line.replace('\r\n', '')
1618                 idx = line.find('[')
1619                 if idx > 1:
1620                         line = line[idx:]
1621                 m = re.match(sysvals.stampfmt, line)
1622                 if(m):
1623                         if(data):
1624                                 testruns.append(data)
1625                         data = Data(len(testruns))
1626                         parseStamp(m, data)
1627                         continue
1628                 if(not data):
1629                         continue
1630                 m = re.match(sysvals.firmwarefmt, line)
1631                 if(m):
1632                         data.fwSuspend = int(m.group('s'))
1633                         data.fwResume = int(m.group('r'))
1634                         if(data.fwSuspend > 0 or data.fwResume > 0):
1635                                 data.fwValid = True
1636                         continue
1637                 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1638                 if(m):
1639                         data.dmesgtext.append(line)
1640                         if(re.match('ACPI: resume from mwait', m.group('msg'))):
1641                                 print('NOTE: This suspend appears to be freeze rather than'+\
1642                                         ' %s, it will be treated as such' % sysvals.suspendmode)
1643                                 sysvals.suspendmode = 'freeze'
1644                 else:
1645                         vprint('ignoring dmesg line: %s' % line.replace('\n', ''))
1646         testruns.append(data)
1647         lf.close()
1648
1649         if(not data):
1650                 print('ERROR: analyze_suspend header missing from dmesg log')
1651                 sys.exit()
1652
1653         # fix lines with same timestamp/function with the call and return swapped
1654         for data in testruns:
1655                 last = ''
1656                 for line in data.dmesgtext:
1657                         mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling  '+\
1658                                 '(?P<f>.*)\+ @ .*, parent: .*', line)
1659                         mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
1660                                 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
1661                         if(mc and mr and (mc.group('t') == mr.group('t')) and
1662                                 (mc.group('f') == mr.group('f'))):
1663                                 i = data.dmesgtext.index(last)
1664                                 j = data.dmesgtext.index(line)
1665                                 data.dmesgtext[i] = line
1666                                 data.dmesgtext[j] = last
1667                         last = line
1668         return testruns
1669
1670 # Function: parseKernelLog
1671 # Description:
1672 #        [deprecated for kernel 3.15.0 or newer]
1673 #        Analyse a dmesg log output file generated from this app during
1674 #        the execution phase. Create a set of device structures in memory
1675 #        for subsequent formatting in the html output file
1676 #        This call is only for legacy support on kernels where the ftrace
1677 #        data lacks the suspend_resume or device_pm_callbacks trace events.
1678 # Arguments:
1679 #        data: an empty Data object (with dmesgtext) obtained from loadKernelLog
1680 # Output:
1681 #        The filled Data object
1682 def parseKernelLog(data):
1683         global sysvals
1684
1685         phase = 'suspend_runtime'
1686
1687         if(data.fwValid):
1688                 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
1689                         (data.fwSuspend, data.fwResume))
1690
1691         # dmesg phase match table
1692         dm = {
1693                 'suspend_prepare': 'PM: Syncing filesystems.*',
1694                         'suspend': 'PM: Entering [a-z]* sleep.*',
1695                    'suspend_late': 'PM: suspend of devices complete after.*',
1696                   'suspend_noirq': 'PM: late suspend of devices complete after.*',
1697                 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
1698                  'resume_machine': 'ACPI: Low-level resume complete.*',
1699                    'resume_noirq': 'ACPI: Waking up from system sleep state.*',
1700                    'resume_early': 'PM: noirq resume of devices complete after.*',
1701                          'resume': 'PM: early resume of devices complete after.*',
1702                 'resume_complete': 'PM: resume of devices complete after.*',
1703                     'post_resume': '.*Restarting tasks \.\.\..*',
1704         }
1705         if(sysvals.suspendmode == 'standby'):
1706                 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
1707         elif(sysvals.suspendmode == 'disk'):
1708                 dm['suspend_late'] = 'PM: freeze of devices complete after.*'
1709                 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
1710                 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
1711                 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
1712                 dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
1713                 dm['resume'] = 'PM: early restore of devices complete after.*'
1714                 dm['resume_complete'] = 'PM: restore of devices complete after.*'
1715         elif(sysvals.suspendmode == 'freeze'):
1716                 dm['resume_machine'] = 'ACPI: resume from mwait'
1717
1718         # action table (expected events that occur and show up in dmesg)
1719         at = {
1720                 'sync_filesystems': {
1721                         'smsg': 'PM: Syncing filesystems.*',
1722                         'emsg': 'PM: Preparing system for mem sleep.*' },
1723                 'freeze_user_processes': {
1724                         'smsg': 'Freezing user space processes .*',
1725                         'emsg': 'Freezing remaining freezable tasks.*' },
1726                 'freeze_tasks': {
1727                         'smsg': 'Freezing remaining freezable tasks.*',
1728                         'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
1729                 'ACPI prepare': {
1730                         'smsg': 'ACPI: Preparing to enter system sleep state.*',
1731                         'emsg': 'PM: Saving platform NVS memory.*' },
1732                 'PM vns': {
1733                         'smsg': 'PM: Saving platform NVS memory.*',
1734                         'emsg': 'Disabling non-boot CPUs .*' },
1735         }
1736
1737         t0 = -1.0
1738         cpu_start = -1.0
1739         prevktime = -1.0
1740         actions = dict()
1741         for line in data.dmesgtext:
1742                 # -- preprocessing --
1743                 # parse each dmesg line into the time and message
1744                 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1745                 if(m):
1746                         val = m.group('ktime')
1747                         try:
1748                                 ktime = float(val)
1749                         except:
1750                                 doWarning('INVALID DMESG LINE: '+\
1751                                         line.replace('\n', ''), 'dmesg')
1752                                 continue
1753                         msg = m.group('msg')
1754                         # initialize data start to first line time
1755                         if t0 < 0:
1756                                 data.setStart(ktime)
1757                                 t0 = ktime
1758                 else:
1759                         continue
1760
1761                 # hack for determining resume_machine end for freeze
1762                 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
1763                         and phase == 'resume_machine' and \
1764                         re.match('calling  (?P<f>.*)\+ @ .*, parent: .*', msg)):
1765                         data.dmesg['resume_machine']['end'] = ktime
1766                         phase = 'resume_noirq'
1767                         data.dmesg[phase]['start'] = ktime
1768
1769                 # -- phase changes --
1770                 # suspend start
1771                 if(re.match(dm['suspend_prepare'], msg)):
1772                         phase = 'suspend_prepare'
1773                         data.dmesg[phase]['start'] = ktime
1774                         data.setStart(ktime)
1775                 # suspend start
1776                 elif(re.match(dm['suspend'], msg)):
1777                         data.dmesg['suspend_prepare']['end'] = ktime
1778                         phase = 'suspend'
1779                         data.dmesg[phase]['start'] = ktime
1780                 # suspend_late start
1781                 elif(re.match(dm['suspend_late'], msg)):
1782                         data.dmesg['suspend']['end'] = ktime
1783                         phase = 'suspend_late'
1784                         data.dmesg[phase]['start'] = ktime
1785                 # suspend_noirq start
1786                 elif(re.match(dm['suspend_noirq'], msg)):
1787                         data.dmesg['suspend_late']['end'] = ktime
1788                         phase = 'suspend_noirq'
1789                         data.dmesg[phase]['start'] = ktime
1790                 # suspend_machine start
1791                 elif(re.match(dm['suspend_machine'], msg)):
1792                         data.dmesg['suspend_noirq']['end'] = ktime
1793                         phase = 'suspend_machine'
1794                         data.dmesg[phase]['start'] = ktime
1795                 # resume_machine start
1796                 elif(re.match(dm['resume_machine'], msg)):
1797                         if(sysvals.suspendmode in ['freeze', 'standby']):
1798                                 data.tSuspended = prevktime
1799                                 data.dmesg['suspend_machine']['end'] = prevktime
1800                         else:
1801                                 data.tSuspended = ktime
1802                                 data.dmesg['suspend_machine']['end'] = ktime
1803                         phase = 'resume_machine'
1804                         data.tResumed = ktime
1805                         data.tLow = data.tResumed - data.tSuspended
1806                         data.dmesg[phase]['start'] = ktime
1807                 # resume_noirq start
1808                 elif(re.match(dm['resume_noirq'], msg)):
1809                         data.dmesg['resume_machine']['end'] = ktime
1810                         phase = 'resume_noirq'
1811                         data.dmesg[phase]['start'] = ktime
1812                 # resume_early start
1813                 elif(re.match(dm['resume_early'], msg)):
1814                         data.dmesg['resume_noirq']['end'] = ktime
1815                         phase = 'resume_early'
1816                         data.dmesg[phase]['start'] = ktime
1817                 # resume start
1818                 elif(re.match(dm['resume'], msg)):
1819                         data.dmesg['resume_early']['end'] = ktime
1820                         phase = 'resume'
1821                         data.dmesg[phase]['start'] = ktime
1822                 # resume complete start
1823                 elif(re.match(dm['resume_complete'], msg)):
1824                         data.dmesg['resume']['end'] = ktime
1825                         phase = 'resume_complete'
1826                         data.dmesg[phase]['start'] = ktime
1827                 # post resume start
1828                 elif(re.match(dm['post_resume'], msg)):
1829                         data.dmesg['resume_complete']['end'] = ktime
1830                         data.setEnd(ktime)
1831                         phase = 'post_resume'
1832                         break
1833
1834                 # -- device callbacks --
1835                 if(phase in data.phases):
1836                         # device init call
1837                         if(re.match('calling  (?P<f>.*)\+ @ .*, parent: .*', msg)):
1838                                 sm = re.match('calling  (?P<f>.*)\+ @ '+\
1839                                         '(?P<n>.*), parent: (?P<p>.*)', msg);
1840                                 f = sm.group('f')
1841                                 n = sm.group('n')
1842                                 p = sm.group('p')
1843                                 if(f and n and p):
1844                                         data.newAction(phase, f, int(n), p, ktime, -1, '')
1845                         # device init return
1846                         elif(re.match('call (?P<f>.*)\+ returned .* after '+\
1847                                 '(?P<t>.*) usecs', msg)):
1848                                 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
1849                                         '(?P<t>.*) usecs(?P<a>.*)', msg);
1850                                 f = sm.group('f')
1851                                 t = sm.group('t')
1852                                 list = data.dmesg[phase]['list']
1853                                 if(f in list):
1854                                         dev = list[f]
1855                                         dev['length'] = int(t)
1856                                         dev['end'] = ktime
1857
1858                 # -- non-devicecallback actions --
1859                 # if trace events are not available, these are better than nothing
1860                 if(not sysvals.usetraceevents):
1861                         # look for known actions
1862                         for a in at:
1863                                 if(re.match(at[a]['smsg'], msg)):
1864                                         if(a not in actions):
1865                                                 actions[a] = []
1866                                         actions[a].append({'begin': ktime, 'end': ktime})
1867                                 if(re.match(at[a]['emsg'], msg)):
1868                                         actions[a][-1]['end'] = ktime
1869                         # now look for CPU on/off events
1870                         if(re.match('Disabling non-boot CPUs .*', msg)):
1871                                 # start of first cpu suspend
1872                                 cpu_start = ktime
1873                         elif(re.match('Enabling non-boot CPUs .*', msg)):
1874                                 # start of first cpu resume
1875                                 cpu_start = ktime
1876                         elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
1877                                 # end of a cpu suspend, start of the next
1878                                 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
1879                                 cpu = 'CPU'+m.group('cpu')
1880                                 if(cpu not in actions):
1881                                         actions[cpu] = []
1882                                 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1883                                 cpu_start = ktime
1884                         elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
1885                                 # end of a cpu resume, start of the next
1886                                 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
1887                                 cpu = 'CPU'+m.group('cpu')
1888                                 if(cpu not in actions):
1889                                         actions[cpu] = []
1890                                 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1891                                 cpu_start = ktime
1892                 prevktime = ktime
1893
1894         # fill in any missing phases
1895         lp = data.phases[0]
1896         for p in data.phases:
1897                 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
1898                         print('WARNING: phase "%s" is missing, something went wrong!' % p)
1899                         print('    In %s, this dmesg line denotes the start of %s:' % \
1900                                 (sysvals.suspendmode, p))
1901                         print('        "%s"' % dm[p])
1902                 if(data.dmesg[p]['start'] < 0):
1903                         data.dmesg[p]['start'] = data.dmesg[lp]['end']
1904                         if(p == 'resume_machine'):
1905                                 data.tSuspended = data.dmesg[lp]['end']
1906                                 data.tResumed = data.dmesg[lp]['end']
1907                                 data.tLow = 0
1908                 if(data.dmesg[p]['end'] < 0):
1909                         data.dmesg[p]['end'] = data.dmesg[p]['start']
1910                 lp = p
1911
1912         # fill in any actions we've found
1913         for name in actions:
1914                 for event in actions[name]:
1915                         begin = event['begin']
1916                         end = event['end']
1917                         # if event starts before timeline start, expand timeline
1918                         if(begin < data.start):
1919                                 data.setStart(begin)
1920                         # if event ends after timeline end, expand the timeline
1921                         if(end > data.end):
1922                                 data.setEnd(end)
1923                         data.newActionGlobal(name, begin, end)
1924
1925         if(sysvals.verbose):
1926                 data.printDetails()
1927         if(len(sysvals.devicefilter) > 0):
1928                 data.deviceFilter(sysvals.devicefilter)
1929         data.fixupInitcallsThatDidntReturn()
1930         return True
1931
1932 # Function: setTimelineRows
1933 # Description:
1934 #        Organize the timeline entries into the smallest
1935 #        number of rows possible, with no entry overlapping
1936 # Arguments:
1937 #        list: the list of devices/actions for a single phase
1938 #        sortedkeys: cronologically sorted key list to use
1939 # Output:
1940 #        The total number of rows needed to display this phase of the timeline
1941 def setTimelineRows(list, sortedkeys):
1942
1943         # clear all rows and set them to undefined
1944         remaining = len(list)
1945         rowdata = dict()
1946         row = 0
1947         for item in list:
1948                 list[item]['row'] = -1
1949
1950         # try to pack each row with as many ranges as possible
1951         while(remaining > 0):
1952                 if(row not in rowdata):
1953                         rowdata[row] = []
1954                 for item in sortedkeys:
1955                         if(list[item]['row'] < 0):
1956                                 s = list[item]['start']
1957                                 e = list[item]['end']
1958                                 valid = True
1959                                 for ritem in rowdata[row]:
1960                                         rs = ritem['start']
1961                                         re = ritem['end']
1962                                         if(not (((s <= rs) and (e <= rs)) or
1963                                                 ((s >= re) and (e >= re)))):
1964                                                 valid = False
1965                                                 break
1966                                 if(valid):
1967                                         rowdata[row].append(list[item])
1968                                         list[item]['row'] = row
1969                                         remaining -= 1
1970                 row += 1
1971         return row
1972
1973 # Function: createTimeScale
1974 # Description:
1975 #        Create the timescale header for the html timeline
1976 # Arguments:
1977 #        t0: start time (suspend begin)
1978 #        tMax: end time (resume end)
1979 #        tSuspend: time when suspend occurs, i.e. the zero time
1980 # Output:
1981 #        The html code needed to display the time scale
1982 def createTimeScale(t0, tMax, tSuspended):
1983         timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1984         output = '<div id="timescale">\n'
1985
1986         # set scale for timeline
1987         tTotal = tMax - t0
1988         tS = 0.1
1989         if(tTotal <= 0):
1990                 return output
1991         if(tTotal > 4):
1992                 tS = 1
1993         if(tSuspended < 0):
1994                 for i in range(int(tTotal/tS)+1):
1995                         pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal))
1996                         if(i > 0):
1997                                 val = '%0.fms' % (float(i)*tS*1000)
1998                         else:
1999                                 val = ''
2000                         output += timescale.format(pos, val)
2001         else:
2002                 tSuspend = tSuspended - t0
2003                 divTotal = int(tTotal/tS) + 1
2004                 divSuspend = int(tSuspend/tS)
2005                 s0 = (tSuspend - tS*divSuspend)*100/tTotal
2006                 for i in range(divTotal):
2007                         pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0)
2008                         if((i == 0) and (s0 < 3)):
2009                                 val = ''
2010                         elif(i == divSuspend):
2011                                 val = 'S/R'
2012                         else:
2013                                 val = '%0.fms' % (float(i-divSuspend)*tS*1000)
2014                         output += timescale.format(pos, val)
2015         output += '</div>\n'
2016         return output
2017
2018 # Function: createHTMLSummarySimple
2019 # Description:
2020 #        Create summary html file for a series of tests
2021 # Arguments:
2022 #        testruns: array of Data objects from parseTraceLog
2023 def createHTMLSummarySimple(testruns, htmlfile):
2024         global sysvals
2025
2026         # print out the basic summary of all the tests
2027         hf = open(htmlfile, 'w')
2028
2029         # write the html header first (html head, css code, up to body start)
2030         html = '<!DOCTYPE html>\n<html>\n<head>\n\
2031         <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2032         <title>AnalyzeSuspend Summary</title>\n\
2033         <style type=\'text/css\'>\n\
2034                 body {overflow-y: scroll;}\n\
2035                 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\
2036                 table {width:100%;border-collapse: collapse;}\n\
2037                 .summary {font: 22px Arial;border:1px solid;}\n\
2038                 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\
2039                 td {text-align: center;}\n\
2040                 tr.alt td {background-color:#EAF2D3;}\n\
2041                 tr.avg td {background-color:#BDE34C;}\n\
2042                 a:link {color: #90B521;}\n\
2043                 a:visited {color: #495E09;}\n\
2044                 a:hover {color: #B1DF28;}\n\
2045                 a:active {color: #FFFFFF;}\n\
2046         </style>\n</head>\n<body>\n'
2047
2048         # group test header
2049         count = len(testruns)
2050         headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n'
2051         html += headline_stamp.format(sysvals.stamp['host'],
2052                 sysvals.stamp['kernel'], sysvals.stamp['mode'],
2053                 sysvals.stamp['time'], count)
2054
2055         # check to see if all the tests have the same value
2056         stampcolumns = False
2057         for data in testruns:
2058                 if diffStamp(sysvals.stamp, data.stamp):
2059                         stampcolumns = True
2060                         break
2061
2062         th = '\t<th>{0}</th>\n'
2063         td = '\t<td>{0}</td>\n'
2064         tdlink = '\t<td><a href="{0}">Click Here</a></td>\n'
2065
2066         # table header
2067         html += '<table class="summary">\n<tr>\n'
2068         html += th.format("Test #")
2069         if stampcolumns:
2070                 html += th.format("Hostname")
2071                 html += th.format("Kernel Version")
2072                 html += th.format("Suspend Mode")
2073         html += th.format("Test Time")
2074         html += th.format("Suspend Time")
2075         html += th.format("Resume Time")
2076         html += th.format("Detail")
2077         html += '</tr>\n'
2078
2079         # test data, 1 row per test
2080         sTimeAvg = 0.0
2081         rTimeAvg = 0.0
2082         num = 1
2083         for data in testruns:
2084                 # data.end is the end of post_resume
2085                 resumeEnd = data.dmesg['resume_complete']['end']
2086                 if num % 2 == 1:
2087                         html += '<tr class="alt">\n'
2088                 else:
2089                         html += '<tr>\n'
2090
2091                 # test num
2092                 html += td.format("test %d" % num)
2093                 num += 1
2094                 if stampcolumns:
2095                         # host name
2096                         val = "unknown"
2097                         if('host' in data.stamp):
2098                                 val = data.stamp['host']
2099                         html += td.format(val)
2100                         # host kernel
2101                         val = "unknown"
2102                         if('kernel' in data.stamp):
2103                                 val = data.stamp['kernel']
2104                         html += td.format(val)
2105                         # suspend mode
2106                         val = "unknown"
2107                         if('mode' in data.stamp):
2108                                 val = data.stamp['mode']
2109                         html += td.format(val)
2110                 # test time
2111                 val = "unknown"
2112                 if('time' in data.stamp):
2113                         val = data.stamp['time']
2114                 html += td.format(val)
2115                 # suspend time
2116                 sTime = (data.tSuspended - data.start)*1000
2117                 sTimeAvg += sTime
2118                 html += td.format("%3.3f ms" % sTime)
2119                 # resume time
2120                 rTime = (resumeEnd - data.tResumed)*1000
2121                 rTimeAvg += rTime
2122                 html += td.format("%3.3f ms" % rTime)
2123                 # link to the output html
2124                 html += tdlink.format(data.outfile)
2125
2126                 html += '</tr>\n'
2127
2128         # last line: test average
2129         if(count > 0):
2130                 sTimeAvg /= count
2131                 rTimeAvg /= count
2132         html += '<tr class="avg">\n'
2133         html += td.format('Average')    # name
2134         if stampcolumns:
2135                 html += td.format('')                   # host
2136                 html += td.format('')                   # kernel
2137                 html += td.format('')                   # mode
2138         html += td.format('')                   # time
2139         html += td.format("%3.3f ms" % sTimeAvg)        # suspend time
2140         html += td.format("%3.3f ms" % rTimeAvg)        # resume time
2141         html += td.format('')                   # output link
2142         html += '</tr>\n'
2143
2144         # flush the data to file
2145         hf.write(html+'</table>\n')
2146         hf.write('</body>\n</html>\n')
2147         hf.close()
2148
2149 # Function: createHTML
2150 # Description:
2151 #        Create the output html file from the resident test data
2152 # Arguments:
2153 #        testruns: array of Data objects from parseKernelLog or parseTraceLog
2154 # Output:
2155 #        True if the html file was created, false if it failed
2156 def createHTML(testruns):
2157         global sysvals
2158
2159         for data in testruns:
2160                 data.normalizeTime(testruns[-1].tSuspended)
2161
2162         x2changes = ['', 'absolute']
2163         if len(testruns) > 1:
2164                 x2changes = ['1', 'relative']
2165         # html function templates
2166         headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
2167         html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
2168         html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
2169         html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
2170         html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
2171         html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
2172         html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n'
2173         html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
2174         html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
2175         html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
2176         html_timetotal = '<table class="time1">\n<tr>'\
2177                 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
2178                 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
2179                 '</tr>\n</table>\n'
2180         html_timetotal2 = '<table class="time1">\n<tr>'\
2181                 '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\
2182                 '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
2183                 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
2184                 '</tr>\n</table>\n'
2185         html_timegroups = '<table class="time2">\n<tr>'\
2186                 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\
2187                 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
2188                 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
2189                 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
2190                 '</tr>\n</table>\n'
2191
2192         # device timeline
2193         vprint('Creating Device Timeline...')
2194         devtl = Timeline()
2195
2196         # Generate the header for this timeline
2197         textnum = ['First', 'Second']
2198         for data in testruns:
2199                 tTotal = data.end - data.start
2200                 tEnd = data.dmesg['resume_complete']['end']
2201                 if(tTotal == 0):
2202                         print('ERROR: No timeline data')
2203                         sys.exit()
2204                 if(data.tLow > 0):
2205                         low_time = '%.0f'%(data.tLow*1000)
2206                 if data.fwValid:
2207                         suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \
2208                                 (data.fwSuspend/1000000.0))
2209                         resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \
2210                                 (data.fwResume/1000000.0))
2211                         testdesc1 = 'Total'
2212                         testdesc2 = ''
2213                         if(len(testruns) > 1):
2214                                 testdesc1 = testdesc2 = textnum[data.testnumber]
2215                                 testdesc2 += ' '
2216                         if(data.tLow == 0):
2217                                 thtml = html_timetotal.format(suspend_time, \
2218                                         resume_time, testdesc1)
2219                         else:
2220                                 thtml = html_timetotal2.format(suspend_time, low_time, \
2221                                         resume_time, testdesc1)
2222                         devtl.html['timeline'] += thtml
2223                         sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \
2224                                 data.getStart())*1000)
2225                         sftime = '%.3f'%(data.fwSuspend / 1000000.0)
2226                         rftime = '%.3f'%(data.fwResume / 1000000.0)
2227                         rktime = '%.3f'%((data.getEnd() - \
2228                                 data.dmesg['resume_machine']['start'])*1000)
2229                         devtl.html['timeline'] += html_timegroups.format(sktime, \
2230                                 sftime, rftime, rktime, testdesc2)
2231                 else:
2232                         suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
2233                         resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
2234                         testdesc = 'Kernel'
2235                         if(len(testruns) > 1):
2236                                 testdesc = textnum[data.testnumber]+' '+testdesc
2237                         if(data.tLow == 0):
2238                                 thtml = html_timetotal.format(suspend_time, \
2239                                         resume_time, testdesc)
2240                         else:
2241                                 thtml = html_timetotal2.format(suspend_time, low_time, \
2242                                         resume_time, testdesc)
2243                         devtl.html['timeline'] += thtml
2244
2245         # time scale for potentially multiple datasets
2246         t0 = testruns[0].start
2247         tMax = testruns[-1].end
2248         tSuspended = testruns[-1].tSuspended
2249         tTotal = tMax - t0
2250
2251         # determine the maximum number of rows we need to draw
2252         timelinerows = 0
2253         for data in testruns:
2254                 for phase in data.dmesg:
2255                         list = data.dmesg[phase]['list']
2256                         rows = setTimelineRows(list, list)
2257                         data.dmesg[phase]['row'] = rows
2258                         if(rows > timelinerows):
2259                                 timelinerows = rows
2260
2261         # calculate the timeline height and create bounding box, add buttons
2262         devtl.setRows(timelinerows + 1)
2263         devtl.html['timeline'] += html_devlist1
2264         if len(testruns) > 1:
2265                 devtl.html['timeline'] += html_devlist2
2266         devtl.html['timeline'] += html_zoombox
2267         devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
2268
2269         # draw the colored boxes for each of the phases
2270         for data in testruns:
2271                 for b in data.dmesg:
2272                         phase = data.dmesg[b]
2273                         length = phase['end']-phase['start']
2274                         left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
2275                         width = '%.3f' % ((length*100.0)/tTotal)
2276                         devtl.html['timeline'] += html_phase.format(left, width, \
2277                                 '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \
2278                                 data.dmesg[b]['color'], '')
2279
2280         # draw the time scale, try to make the number of labels readable
2281         devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended)
2282         devtl.html['timeline'] += devtl.html['scale']
2283         for data in testruns:
2284                 for b in data.dmesg:
2285                         phaselist = data.dmesg[b]['list']
2286                         for d in phaselist:
2287                                 name = d
2288                                 drv = ''
2289                                 dev = phaselist[d]
2290                                 if(d in sysvals.altdevname):
2291                                         name = sysvals.altdevname[d]
2292                                 if('drv' in dev and dev['drv']):
2293                                         drv = ' {%s}' % dev['drv']
2294                                 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
2295                                 top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
2296                                 left = '%.3f' % (((dev['start']-t0)*100)/tTotal)
2297                                 width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal)
2298                                 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
2299                                 color = 'rgba(204,204,204,0.5)'
2300                                 devtl.html['timeline'] += html_device.format(dev['id'], \
2301                                         d+drv+length+b, left, top, '%.3f'%height, width, name+drv)
2302
2303         # draw any trace events found
2304         for data in testruns:
2305                 for b in data.dmesg:
2306                         phaselist = data.dmesg[b]['list']
2307                         for name in phaselist:
2308                                 dev = phaselist[name]
2309                                 if('traceevents' in dev):
2310                                         vprint('Debug trace events found for device %s' % name)
2311                                         vprint('%20s %20s %10s %8s' % ('action', \
2312                                                 'name', 'time(ms)', 'length(ms)'))
2313                                         for e in dev['traceevents']:
2314                                                 vprint('%20s %20s %10.3f %8.3f' % (e.action, \
2315                                                         e.name, e.time*1000, e.length*1000))
2316                                                 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
2317                                                 top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
2318                                                 left = '%.3f' % (((e.time-t0)*100)/tTotal)
2319                                                 width = '%.3f' % (e.length*100/tTotal)
2320                                                 color = 'rgba(204,204,204,0.5)'
2321                                                 devtl.html['timeline'] += \
2322                                                         html_traceevent.format(e.action+' '+e.name, \
2323                                                                 left, top, '%.3f'%height, \
2324                                                                 width, e.color, '')
2325
2326         # timeline is finished
2327         devtl.html['timeline'] += '</div>\n</div>\n'
2328
2329         # draw a legend which describes the phases by color
2330         data = testruns[-1]
2331         devtl.html['legend'] = '<div class="legend">\n'
2332         pdelta = 100.0/len(data.phases)
2333         pmargin = pdelta / 4.0
2334         for phase in data.phases:
2335                 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
2336                 name = string.replace(phase, '_', ' &nbsp;')
2337                 devtl.html['legend'] += html_legend.format(order, \
2338                         data.dmesg[phase]['color'], name)
2339         devtl.html['legend'] += '</div>\n'
2340
2341         hf = open(sysvals.htmlfile, 'w')
2342         thread_height = 0
2343
2344         # write the html header first (html head, css code, up to body start)
2345         html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
2346         <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2347         <title>AnalyzeSuspend</title>\n\
2348         <style type=\'text/css\'>\n\
2349                 body {overflow-y: scroll;}\n\
2350                 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
2351                 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
2352                 .callgraph article * {padding-left: 28px;}\n\
2353                 h1 {color:black;font: bold 30px Times;}\n\
2354                 t0 {color:black;font: bold 30px Times;}\n\
2355                 t1 {color:black;font: 30px Times;}\n\
2356                 t2 {color:black;font: 25px Times;}\n\
2357                 t3 {color:black;font: 20px Times;white-space:nowrap;}\n\
2358                 t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\
2359                 table {width:100%;}\n\
2360                 .gray {background-color:rgba(80,80,80,0.1);}\n\
2361                 .green {background-color:rgba(204,255,204,0.4);}\n\
2362                 .purple {background-color:rgba(128,0,128,0.2);}\n\
2363                 .yellow {background-color:rgba(255,255,204,0.4);}\n\
2364                 .time1 {font: 22px Arial;border:1px solid;}\n\
2365                 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
2366                 td {text-align: center;}\n\
2367                 r {color:#500000;font:15px Tahoma;}\n\
2368                 n {color:#505050;font:15px Tahoma;}\n\
2369                 .tdhl {color: red;}\n\
2370                 .hide {display: none;}\n\
2371                 .pf {display: none;}\n\
2372                 .pf:checked + 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\
2373                 .pf:not(:checked) ~ 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\
2374                 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
2375                 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
2376                 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
2377                 .thread {position: absolute; height: '+'%.3f'%thread_height+'%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
2378                 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
2379                 .hover {background-color:white;border:1px solid red;z-index:10;}\n\
2380                 .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\
2381                 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
2382                 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
2383                 .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\
2384                 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
2385                 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
2386                 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
2387                 .devlist {position:'+x2changes[1]+';width:190px;}\n\
2388                 #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\
2389         </style>\n</head>\n<body>\n'
2390         hf.write(html_header)
2391
2392         # write the test title and general info header
2393         if(sysvals.stamp['time'] != ""):
2394                 hf.write(headline_stamp.format(sysvals.stamp['host'],
2395                         sysvals.stamp['kernel'], sysvals.stamp['mode'], \
2396                                 sysvals.stamp['time']))
2397
2398         # write the device timeline
2399         hf.write(devtl.html['timeline'])
2400         hf.write(devtl.html['legend'])
2401         hf.write('<div id="devicedetailtitle"></div>\n')
2402         hf.write('<div id="devicedetail" style="display:none;">\n')
2403         # draw the colored boxes for the device detail section
2404         for data in testruns:
2405                 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
2406                 for b in data.phases:
2407                         phase = data.dmesg[b]
2408                         length = phase['end']-phase['start']
2409                         left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
2410                         width = '%.3f' % ((length*100.0)/tTotal)
2411                         hf.write(html_phaselet.format(b, left, width, \
2412                                 data.dmesg[b]['color']))
2413                 hf.write('</div>\n')
2414         hf.write('</div>\n')
2415
2416         # write the ftrace data (callgraph)
2417         data = testruns[-1]
2418         if(sysvals.usecallgraph):
2419                 hf.write('<section id="callgraphs" class="callgraph">\n')
2420                 # write out the ftrace data converted to html
2421                 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'
2422                 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
2423                 html_func_end = '</article>\n'
2424                 html_func_leaf = '<article>{0} {1}</article>\n'
2425                 num = 0
2426                 for p in data.phases:
2427                         list = data.dmesg[p]['list']
2428                         for devname in data.sortedDevices(p):
2429                                 if('ftrace' not in list[devname]):
2430                                         continue
2431                                 name = devname
2432                                 if(devname in sysvals.altdevname):
2433                                         name = sysvals.altdevname[devname]
2434                                 devid = list[devname]['id']
2435                                 cg = list[devname]['ftrace']
2436                                 flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \
2437                                         ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000)
2438                                 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
2439                                         num, name+' '+p, flen))
2440                                 num += 1
2441                                 for line in cg.list:
2442                                         if(line.length < 0.000000001):
2443                                                 flen = ''
2444                                         else:
2445                                                 flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \
2446                                                         line.time*1000)
2447                                         if(line.freturn and line.fcall):
2448                                                 hf.write(html_func_leaf.format(line.name, flen))
2449                                         elif(line.freturn):
2450                                                 hf.write(html_func_end)
2451                                         else:
2452                                                 hf.write(html_func_start.format(num, line.name, flen))
2453                                                 num += 1
2454                                 hf.write(html_func_end)
2455                 hf.write('\n\n    </section>\n')
2456         # write the footer and close
2457         addScriptCode(hf, testruns)
2458         hf.write('</body>\n</html>\n')
2459         hf.close()
2460         return True
2461
2462 # Function: addScriptCode
2463 # Description:
2464 #        Adds the javascript code to the output html
2465 # Arguments:
2466 #        hf: the open html file pointer
2467 #        testruns: array of Data objects from parseKernelLog or parseTraceLog
2468 def addScriptCode(hf, testruns):
2469         t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
2470         tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
2471         # create an array in javascript memory with the device details
2472         detail = '      var devtable = [];\n'
2473         for data in testruns:
2474                 topo = data.deviceTopology()
2475                 detail += '     devtable[%d] = "%s";\n' % (data.testnumber, topo)
2476         detail += '     var bounds = [%f,%f];\n' % (t0, tMax)
2477         # add the code which will manipulate the data in the browser
2478         script_code = \
2479         '<script type="text/javascript">\n'+detail+\
2480         '       function zoomTimeline() {\n'\
2481         '               var timescale = document.getElementById("timescale");\n'\
2482         '               var dmesg = document.getElementById("dmesg");\n'\
2483         '               var zoombox = document.getElementById("dmesgzoombox");\n'\
2484         '               var val = parseFloat(dmesg.style.width);\n'\
2485         '               var newval = 100;\n'\
2486         '               var sh = window.outerWidth / 2;\n'\
2487         '               if(this.id == "zoomin") {\n'\
2488         '                       newval = val * 1.2;\n'\
2489         '                       if(newval > 40000) newval = 40000;\n'\
2490         '                       dmesg.style.width = newval+"%";\n'\
2491         '                       zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
2492         '               } else if (this.id == "zoomout") {\n'\
2493         '                       newval = val / 1.2;\n'\
2494         '                       if(newval < 100) newval = 100;\n'\
2495         '                       dmesg.style.width = newval+"%";\n'\
2496         '                       zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
2497         '               } else {\n'\
2498         '                       zoombox.scrollLeft = 0;\n'\
2499         '                       dmesg.style.width = "100%";\n'\
2500         '               }\n'\
2501         '               var html = "";\n'\
2502         '               var t0 = bounds[0];\n'\
2503         '               var tMax = bounds[1];\n'\
2504         '               var tTotal = tMax - t0;\n'\
2505         '               var wTotal = tTotal * 100.0 / newval;\n'\
2506         '               for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\
2507         '               if(tS < 1) tS = 1;\n'\
2508         '               for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
2509         '                       var pos = (tMax - s) * 100.0 / tTotal;\n'\
2510         '                       var name = (s == 0)?"S/R":(s+"ms");\n'\
2511         '                       html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\
2512         '               }\n'\
2513         '               timescale.innerHTML = html;\n'\
2514         '       }\n'\
2515         '       function deviceHover() {\n'\
2516         '               var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
2517         '               var dmesg = document.getElementById("dmesg");\n'\
2518         '               var dev = dmesg.getElementsByClassName("thread");\n'\
2519         '               var cpu = -1;\n'\
2520         '               if(name.match("CPU_ON\[[0-9]*\]"))\n'\
2521         '                       cpu = parseInt(name.slice(7));\n'\
2522         '               else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
2523         '                       cpu = parseInt(name.slice(8));\n'\
2524         '               for (var i = 0; i < dev.length; i++) {\n'\
2525         '                       dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
2526         '                       if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2527         '                               (name == dname))\n'\
2528         '                       {\n'\
2529         '                               dev[i].className = "thread hover";\n'\
2530         '                       } else {\n'\
2531         '                               dev[i].className = "thread";\n'\
2532         '                       }\n'\
2533         '               }\n'\
2534         '       }\n'\
2535         '       function deviceUnhover() {\n'\
2536         '               var dmesg = document.getElementById("dmesg");\n'\
2537         '               var dev = dmesg.getElementsByClassName("thread");\n'\
2538         '               for (var i = 0; i < dev.length; i++) {\n'\
2539         '                       dev[i].className = "thread";\n'\
2540         '               }\n'\
2541         '       }\n'\
2542         '       function deviceTitle(title, total, cpu) {\n'\
2543         '               var prefix = "Total";\n'\
2544         '               if(total.length > 3) {\n'\
2545         '                       prefix = "Average";\n'\
2546         '                       total[1] = (total[1]+total[3])/2;\n'\
2547         '                       total[2] = (total[2]+total[4])/2;\n'\
2548         '               }\n'\
2549         '               var devtitle = document.getElementById("devicedetailtitle");\n'\
2550         '               var name = title.slice(0, title.indexOf(" "));\n'\
2551         '               if(cpu >= 0) name = "CPU"+cpu;\n'\
2552         '               var driver = "";\n'\
2553         '               var tS = "<t2>(</t2>";\n'\
2554         '               var tR = "<t2>)</t2>";\n'\
2555         '               if(total[1] > 0)\n'\
2556         '                       tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
2557         '               if(total[2] > 0)\n'\
2558         '                       tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
2559         '               var s = title.indexOf("{");\n'\
2560         '               var e = title.indexOf("}");\n'\
2561         '               if((s >= 0) && (e >= 0))\n'\
2562         '                       driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
2563         '               if(total[1] > 0 && total[2] > 0)\n'\
2564         '                       devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
2565         '               else\n'\
2566         '                       devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
2567         '               return name;\n'\
2568         '       }\n'\
2569         '       function deviceDetail() {\n'\
2570         '               var devinfo = document.getElementById("devicedetail");\n'\
2571         '               devinfo.style.display = "block";\n'\
2572         '               var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
2573         '               var cpu = -1;\n'\
2574         '               if(name.match("CPU_ON\[[0-9]*\]"))\n'\
2575         '                       cpu = parseInt(name.slice(7));\n'\
2576         '               else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
2577         '                       cpu = parseInt(name.slice(8));\n'\
2578         '               var dmesg = document.getElementById("dmesg");\n'\
2579         '               var dev = dmesg.getElementsByClassName("thread");\n'\
2580         '               var idlist = [];\n'\
2581         '               var pdata = [[]];\n'\
2582         '               var pd = pdata[0];\n'\
2583         '               var total = [0.0, 0.0, 0.0];\n'\
2584         '               for (var i = 0; i < dev.length; i++) {\n'\
2585         '                       dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
2586         '                       if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2587         '                               (name == dname))\n'\
2588         '                       {\n'\
2589         '                               idlist[idlist.length] = dev[i].id;\n'\
2590         '                               var tidx = 1;\n'\
2591         '                               if(dev[i].id[0] == "a") {\n'\
2592         '                                       pd = pdata[0];\n'\
2593         '                               } else {\n'\
2594         '                                       if(pdata.length == 1) pdata[1] = [];\n'\
2595         '                                       if(total.length == 3) total[3]=total[4]=0.0;\n'\
2596         '                                       pd = pdata[1];\n'\
2597         '                                       tidx = 3;\n'\
2598         '                               }\n'\
2599         '                               var info = dev[i].title.split(" ");\n'\
2600         '                               var pname = info[info.length-1];\n'\
2601         '                               pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
2602         '                               total[0] += pd[pname];\n'\
2603         '                               if(pname.indexOf("suspend") >= 0)\n'\
2604         '                                       total[tidx] += pd[pname];\n'\
2605         '                               else\n'\
2606         '                                       total[tidx+1] += pd[pname];\n'\
2607         '                       }\n'\
2608         '               }\n'\
2609         '               var devname = deviceTitle(this.title, total, cpu);\n'\
2610         '               var left = 0.0;\n'\
2611         '               for (var t = 0; t < pdata.length; t++) {\n'\
2612         '                       pd = pdata[t];\n'\
2613         '                       devinfo = document.getElementById("devicedetail"+t);\n'\
2614         '                       var phases = devinfo.getElementsByClassName("phaselet");\n'\
2615         '                       for (var i = 0; i < phases.length; i++) {\n'\
2616         '                               if(phases[i].id in pd) {\n'\
2617         '                                       var w = 100.0*pd[phases[i].id]/total[0];\n'\
2618         '                                       var fs = 32;\n'\
2619         '                                       if(w < 8) fs = 4*w | 0;\n'\
2620         '                                       var fs2 = fs*3/4;\n'\
2621         '                                       phases[i].style.width = w+"%";\n'\
2622         '                                       phases[i].style.left = left+"%";\n'\
2623         '                                       phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
2624         '                                       left += w;\n'\
2625         '                                       var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
2626         '                                       var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\
2627         '                                       phases[i].innerHTML = time+pname;\n'\
2628         '                               } else {\n'\
2629         '                                       phases[i].style.width = "0%";\n'\
2630         '                                       phases[i].style.left = left+"%";\n'\
2631         '                               }\n'\
2632         '                       }\n'\
2633         '               }\n'\
2634         '               var cglist = document.getElementById("callgraphs");\n'\
2635         '               if(!cglist) return;\n'\
2636         '               var cg = cglist.getElementsByClassName("atop");\n'\
2637         '               for (var i = 0; i < cg.length; i++) {\n'\
2638         '                       if(idlist.indexOf(cg[i].id) >= 0) {\n'\
2639         '                               cg[i].style.display = "block";\n'\
2640         '                       } else {\n'\
2641         '                               cg[i].style.display = "none";\n'\
2642         '                       }\n'\
2643         '               }\n'\
2644         '       }\n'\
2645         '       function devListWindow(e) {\n'\
2646         '               var sx = e.clientX;\n'\
2647         '               if(sx > window.innerWidth - 440)\n'\
2648         '                       sx = window.innerWidth - 440;\n'\
2649         '               var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\
2650         '               var win = window.open("", "_blank", cfg);\n'\
2651         '               if(window.chrome) win.moveBy(sx, 0);\n'\
2652         '               var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
2653         '                       "<style type=\\"text/css\\">"+\n'\
2654         '                       "   ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
2655         '                       "</style>"\n'\
2656         '               var dt = devtable[0];\n'\
2657         '               if(e.target.id != "devlist1")\n'\
2658         '                       dt = devtable[1];\n'\
2659         '               win.document.write(html+dt);\n'\
2660         '       }\n'\
2661         '       window.addEventListener("load", function () {\n'\
2662         '               var dmesg = document.getElementById("dmesg");\n'\
2663         '               dmesg.style.width = "100%"\n'\
2664         '               document.getElementById("zoomin").onclick = zoomTimeline;\n'\
2665         '               document.getElementById("zoomout").onclick = zoomTimeline;\n'\
2666         '               document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
2667         '               var devlist = document.getElementsByClassName("devlist");\n'\
2668         '               for (var i = 0; i < devlist.length; i++)\n'\
2669         '                       devlist[i].onclick = devListWindow;\n'\
2670         '               var dev = dmesg.getElementsByClassName("thread");\n'\
2671         '               for (var i = 0; i < dev.length; i++) {\n'\
2672         '                       dev[i].onclick = deviceDetail;\n'\
2673         '                       dev[i].onmouseover = deviceHover;\n'\
2674         '                       dev[i].onmouseout = deviceUnhover;\n'\
2675         '               }\n'\
2676         '               zoomTimeline();\n'\
2677         '       });\n'\
2678         '</script>\n'
2679         hf.write(script_code);
2680
2681 # Function: executeSuspend
2682 # Description:
2683 #        Execute system suspend through the sysfs interface, then copy the output
2684 #        dmesg and ftrace files to the test output directory.
2685 def executeSuspend():
2686         global sysvals
2687
2688         detectUSB(False)
2689         t0 = time.time()*1000
2690         tp = sysvals.tpath
2691         # execute however many s/r runs requested
2692         for count in range(1,sysvals.execcount+1):
2693                 # clear the kernel ring buffer just as we start
2694                 os.system('dmesg -C')
2695                 # enable callgraph ftrace only for the second run
2696                 if(sysvals.usecallgraph and count == 2):
2697                         # set trace type
2698                         os.system('echo function_graph > '+tp+'current_tracer')
2699                         os.system('echo "" > '+tp+'set_ftrace_filter')
2700                         # set trace format options
2701                         os.system('echo funcgraph-abstime > '+tp+'trace_options')
2702                         os.system('echo funcgraph-proc > '+tp+'trace_options')
2703                         # focus only on device suspend and resume
2704                         os.system('cat '+tp+'available_filter_functions | '+\
2705                                 'grep dpm_run_callback > '+tp+'set_graph_function')
2706                 # if this is test2 and there's a delay, start here
2707                 if(count > 1 and sysvals.x2delay > 0):
2708                         tN = time.time()*1000
2709                         while (tN - t0) < sysvals.x2delay:
2710                                 tN = time.time()*1000
2711                                 time.sleep(0.001)
2712                 # start ftrace
2713                 if(sysvals.usecallgraph or sysvals.usetraceevents):
2714                         print('START TRACING')
2715                         os.system('echo 1 > '+tp+'tracing_on')
2716                 # initiate suspend
2717                 if(sysvals.usecallgraph or sysvals.usetraceevents):
2718                         os.system('echo SUSPEND START > '+tp+'trace_marker')
2719                 if(sysvals.rtcwake):
2720                         print('SUSPEND START')
2721                         print('will autoresume in %d seconds' % sysvals.rtcwaketime)
2722                         sysvals.rtcWakeAlarm()
2723                 else:
2724                         print('SUSPEND START (press a key to resume)')
2725                 pf = open(sysvals.powerfile, 'w')
2726                 pf.write(sysvals.suspendmode)
2727                 # execution will pause here
2728                 pf.close()
2729                 t0 = time.time()*1000
2730                 # return from suspend
2731                 print('RESUME COMPLETE')
2732                 if(sysvals.usecallgraph or sysvals.usetraceevents):
2733                         os.system('echo RESUME COMPLETE > '+tp+'trace_marker')
2734                 # see if there's firmware timing data to be had
2735                 t = sysvals.postresumetime
2736                 if(t > 0):
2737                         print('Waiting %d seconds for POST-RESUME trace events...' % t)
2738                         time.sleep(t)
2739                 # stop ftrace
2740                 if(sysvals.usecallgraph or sysvals.usetraceevents):
2741                         os.system('echo 0 > '+tp+'tracing_on')
2742                         print('CAPTURING TRACE')
2743                         writeDatafileHeader(sysvals.ftracefile)
2744                         os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
2745                         os.system('echo "" > '+tp+'trace')
2746                 # grab a copy of the dmesg output
2747                 print('CAPTURING DMESG')
2748                 writeDatafileHeader(sysvals.dmesgfile)
2749                 os.system('dmesg -c >> '+sysvals.dmesgfile)
2750
2751 def writeDatafileHeader(filename):
2752         global sysvals
2753
2754         fw = getFPDT(False)
2755         prt = sysvals.postresumetime
2756         fp = open(filename, 'a')
2757         fp.write(sysvals.teststamp+'\n')
2758         if(fw):
2759                 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
2760         if(prt > 0):
2761                 fp.write('# post resume time %u\n' % prt)
2762         fp.close()
2763
2764 # Function: executeAndroidSuspend
2765 # Description:
2766 #        Execute system suspend through the sysfs interface
2767 #        on a remote android device, then transfer the output
2768 #        dmesg and ftrace files to the local output directory.
2769 def executeAndroidSuspend():
2770         global sysvals
2771
2772         # check to see if the display is currently off
2773         tp = sysvals.tpath
2774         out = os.popen(sysvals.adb+\
2775                 ' shell dumpsys power | grep mScreenOn').read().strip()
2776         # if so we need to turn it on so we can issue a new suspend
2777         if(out.endswith('false')):
2778                 print('Waking the device up for the test...')
2779                 # send the KEYPAD_POWER keyevent to wake it up
2780                 os.system(sysvals.adb+' shell input keyevent 26')
2781                 # wait a few seconds so the user can see the device wake up
2782                 time.sleep(3)
2783         # execute however many s/r runs requested
2784         for count in range(1,sysvals.execcount+1):
2785                 # clear the kernel ring buffer just as we start
2786                 os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1')
2787                 # start ftrace
2788                 if(sysvals.usetraceevents):
2789                         print('START TRACING')
2790                         os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'")
2791                 # initiate suspend
2792                 for count in range(1,sysvals.execcount+1):
2793                         if(sysvals.usetraceevents):
2794                                 os.system(sysvals.adb+\
2795                                         " shell 'echo SUSPEND START > "+tp+"trace_marker'")
2796                         print('SUSPEND START (press a key on the device to resume)')
2797                         os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\
2798                                 " > "+sysvals.powerfile+"'")
2799                         # execution will pause here, then adb will exit
2800                         while(True):
2801                                 check = os.popen(sysvals.adb+\
2802                                         ' shell pwd 2>/dev/null').read().strip()
2803                                 if(len(check) > 0):
2804                                         break
2805                                 time.sleep(1)
2806                         if(sysvals.usetraceevents):
2807                                 os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\
2808                                         "trace_marker'")
2809                 # return from suspend
2810                 print('RESUME COMPLETE')
2811                 # stop ftrace
2812                 if(sysvals.usetraceevents):
2813                         os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
2814                         print('CAPTURING TRACE')
2815                         os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile)
2816                         os.system(sysvals.adb+' shell cat '+tp+\
2817                                 'trace >> '+sysvals.ftracefile)
2818                 # grab a copy of the dmesg output
2819                 print('CAPTURING DMESG')
2820                 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile)
2821                 os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile)
2822
2823 # Function: setUSBDevicesAuto
2824 # Description:
2825 #        Set the autosuspend control parameter of all USB devices to auto
2826 #        This can be dangerous, so use at your own risk, most devices are set
2827 #        to always-on since the kernel cant determine if the device can
2828 #        properly autosuspend
2829 def setUSBDevicesAuto():
2830         global sysvals
2831
2832         rootCheck()
2833         for dirname, dirnames, filenames in os.walk('/sys/devices'):
2834                 if(re.match('.*/usb[0-9]*.*', dirname) and
2835                         'idVendor' in filenames and 'idProduct' in filenames):
2836                         os.system('echo auto > %s/power/control' % dirname)
2837                         name = dirname.split('/')[-1]
2838                         desc = os.popen('cat %s/product 2>/dev/null' % \
2839                                 dirname).read().replace('\n', '')
2840                         ctrl = os.popen('cat %s/power/control 2>/dev/null' % \
2841                                 dirname).read().replace('\n', '')
2842                         print('control is %s for %6s: %s' % (ctrl, name, desc))
2843
2844 # Function: yesno
2845 # Description:
2846 #        Print out an equivalent Y or N for a set of known parameter values
2847 # Output:
2848 #        'Y', 'N', or ' ' if the value is unknown
2849 def yesno(val):
2850         yesvals = ['auto', 'enabled', 'active', '1']
2851         novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
2852         if val in yesvals:
2853                 return 'Y'
2854         elif val in novals:
2855                 return 'N'
2856         return ' '
2857
2858 # Function: ms2nice
2859 # Description:
2860 #        Print out a very concise time string in minutes and seconds
2861 # Output:
2862 #        The time string, e.g. "1901m16s"
2863 def ms2nice(val):
2864         ms = 0
2865         try:
2866                 ms = int(val)
2867         except:
2868                 return 0.0
2869         m = ms / 60000
2870         s = (ms / 1000) - (m * 60)
2871         return '%3dm%2ds' % (m, s)
2872
2873 # Function: detectUSB
2874 # Description:
2875 #        Detect all the USB hosts and devices currently connected and add
2876 #        a list of USB device names to sysvals for better timeline readability
2877 # Arguments:
2878 #        output: True to output the info to stdout, False otherwise
2879 def detectUSB(output):
2880         global sysvals
2881
2882         field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
2883         power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
2884                          'control':'', 'persist':'', 'runtime_enabled':'',
2885                          'runtime_status':'', 'runtime_usage':'',
2886                         'runtime_active_time':'',
2887                         'runtime_suspended_time':'',
2888                         'active_duration':'',
2889                         'connected_duration':''}
2890         if(output):
2891                 print('LEGEND')
2892                 print('---------------------------------------------------------------------------------------------')
2893                 print('  A = async/sync PM queue Y/N                       D = autosuspend delay (seconds)')
2894                 print('  S = autosuspend Y/N                         rACTIVE = runtime active (min/sec)')
2895                 print('  P = persist across suspend Y/N              rSUSPEN = runtime suspend (min/sec)')
2896                 print('  E = runtime suspend enabled/forbidden Y/N    ACTIVE = active duration (min/sec)')
2897                 print('  R = runtime status active/suspended Y/N     CONNECT = connected duration (min/sec)')
2898                 print('  U = runtime usage count')
2899                 print('---------------------------------------------------------------------------------------------')
2900                 print('  NAME       ID      DESCRIPTION         SPEED A S P E R U D rACTIVE rSUSPEN  ACTIVE CONNECT')
2901                 print('---------------------------------------------------------------------------------------------')
2902
2903         for dirname, dirnames, filenames in os.walk('/sys/devices'):
2904                 if(re.match('.*/usb[0-9]*.*', dirname) and
2905                         'idVendor' in filenames and 'idProduct' in filenames):
2906                         for i in field:
2907                                 field[i] = os.popen('cat %s/%s 2>/dev/null' % \
2908                                         (dirname, i)).read().replace('\n', '')
2909                         name = dirname.split('/')[-1]
2910                         if(len(field['product']) > 0):
2911                                 sysvals.altdevname[name] = \
2912                                         '%s [%s]' % (field['product'], name)
2913                         else:
2914                                 sysvals.altdevname[name] = \
2915                                         '%s:%s [%s]' % (field['idVendor'], \
2916                                                 field['idProduct'], name)
2917                         if(output):
2918                                 for i in power:
2919                                         power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
2920                                                 (dirname, i)).read().replace('\n', '')
2921                                 if(re.match('usb[0-9]*', name)):
2922                                         first = '%-8s' % name
2923                                 else:
2924                                         first = '%8s' % name
2925                                 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
2926                                         (first, field['idVendor'], field['idProduct'], \
2927                                         field['product'][0:20], field['speed'], \
2928                                         yesno(power['async']), \
2929                                         yesno(power['control']), \
2930                                         yesno(power['persist']), \
2931                                         yesno(power['runtime_enabled']), \
2932                                         yesno(power['runtime_status']), \
2933                                         power['runtime_usage'], \
2934                                         power['autosuspend'], \
2935                                         ms2nice(power['runtime_active_time']), \
2936                                         ms2nice(power['runtime_suspended_time']), \
2937                                         ms2nice(power['active_duration']), \
2938                                         ms2nice(power['connected_duration'])))
2939
2940 # Function: getModes
2941 # Description:
2942 #        Determine the supported power modes on this system
2943 # Output:
2944 #        A string list of the available modes
2945 def getModes():
2946         global sysvals
2947         modes = ''
2948         if(not sysvals.android):
2949                 if(os.path.exists(sysvals.powerfile)):
2950                         fp = open(sysvals.powerfile, 'r')
2951                         modes = string.split(fp.read())
2952                         fp.close()
2953         else:
2954                 line = os.popen(sysvals.adb+' shell cat '+\
2955                         sysvals.powerfile).read().strip()
2956                 modes = string.split(line)
2957         return modes
2958
2959 # Function: getFPDT
2960 # Description:
2961 #        Read the acpi bios tables and pull out FPDT, the firmware data
2962 # Arguments:
2963 #        output: True to output the info to stdout, False otherwise
2964 def getFPDT(output):
2965         global sysvals
2966
2967         rectype = {}
2968         rectype[0] = 'Firmware Basic Boot Performance Record'
2969         rectype[1] = 'S3 Performance Table Record'
2970         prectype = {}
2971         prectype[0] = 'Basic S3 Resume Performance Record'
2972         prectype[1] = 'Basic S3 Suspend Performance Record'
2973
2974         rootCheck()
2975         if(not os.path.exists(sysvals.fpdtpath)):
2976                 if(output):
2977                         doError('file doesnt exist: %s' % sysvals.fpdtpath, False)
2978                 return False
2979         if(not os.access(sysvals.fpdtpath, os.R_OK)):
2980                 if(output):
2981                         doError('file isnt readable: %s' % sysvals.fpdtpath, False)
2982                 return False
2983         if(not os.path.exists(sysvals.mempath)):
2984                 if(output):
2985                         doError('file doesnt exist: %s' % sysvals.mempath, False)
2986                 return False
2987         if(not os.access(sysvals.mempath, os.R_OK)):
2988                 if(output):
2989                         doError('file isnt readable: %s' % sysvals.mempath, False)
2990                 return False
2991
2992         fp = open(sysvals.fpdtpath, 'rb')
2993         buf = fp.read()
2994         fp.close()
2995
2996         if(len(buf) < 36):
2997                 if(output):
2998                         doError('Invalid FPDT table data, should '+\
2999                                 'be at least 36 bytes', False)
3000                 return False
3001
3002         table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
3003         if(output):
3004                 print('')
3005                 print('Firmware Performance Data Table (%s)' % table[0])
3006                 print('                  Signature : %s' % table[0])
3007                 print('               Table Length : %u' % table[1])
3008                 print('                   Revision : %u' % table[2])
3009                 print('                   Checksum : 0x%x' % table[3])
3010                 print('                     OEM ID : %s' % table[4])
3011                 print('               OEM Table ID : %s' % table[5])
3012                 print('               OEM Revision : %u' % table[6])
3013                 print('                 Creator ID : %s' % table[7])
3014                 print('           Creator Revision : 0x%x' % table[8])
3015                 print('')
3016
3017         if(table[0] != 'FPDT'):
3018                 if(output):
3019                         doError('Invalid FPDT table')
3020                 return False
3021         if(len(buf) <= 36):
3022                 return False
3023         i = 0
3024         fwData = [0, 0]
3025         records = buf[36:]
3026         fp = open(sysvals.mempath, 'rb')
3027         while(i < len(records)):
3028                 header = struct.unpack('HBB', records[i:i+4])
3029                 if(header[0] not in rectype):
3030                         continue
3031                 if(header[1] != 16):
3032                         continue
3033                 addr = struct.unpack('Q', records[i+8:i+16])[0]
3034                 try:
3035                         fp.seek(addr)
3036                         first = fp.read(8)
3037                 except:
3038                         doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False)
3039                 rechead = struct.unpack('4sI', first)
3040                 recdata = fp.read(rechead[1]-8)
3041                 if(rechead[0] == 'FBPT'):
3042                         record = struct.unpack('HBBIQQQQQ', recdata)
3043                         if(output):
3044                                 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3045                                 print('                  Reset END : %u ns' % record[4])
3046                                 print('  OS Loader LoadImage Start : %u ns' % record[5])
3047                                 print(' OS Loader StartImage Start : %u ns' % record[6])
3048                                 print('     ExitBootServices Entry : %u ns' % record[7])
3049                                 print('      ExitBootServices Exit : %u ns' % record[8])
3050                 elif(rechead[0] == 'S3PT'):
3051                         if(output):
3052                                 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3053                         j = 0
3054                         while(j < len(recdata)):
3055                                 prechead = struct.unpack('HBB', recdata[j:j+4])
3056                                 if(prechead[0] not in prectype):
3057                                         continue
3058                                 if(prechead[0] == 0):
3059                                         record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
3060                                         fwData[1] = record[2]
3061                                         if(output):
3062                                                 print('    %s' % prectype[prechead[0]])
3063                                                 print('               Resume Count : %u' % \
3064                                                         record[1])
3065                                                 print('                 FullResume : %u ns' % \
3066                                                         record[2])
3067                                                 print('              AverageResume : %u ns' % \
3068                                                         record[3])
3069                                 elif(prechead[0] == 1):
3070                                         record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
3071                                         fwData[0] = record[1] - record[0]
3072                                         if(output):
3073                                                 print('    %s' % prectype[prechead[0]])
3074                                                 print('               SuspendStart : %u ns' % \
3075                                                         record[0])
3076                                                 print('                 SuspendEnd : %u ns' % \
3077                                                         record[1])
3078                                                 print('                SuspendTime : %u ns' % \
3079                                                         fwData[0])
3080                                 j += prechead[1]
3081                 if(output):
3082                         print('')
3083                 i += header[1]
3084         fp.close()
3085         return fwData
3086
3087 # Function: statusCheck
3088 # Description:
3089 #        Verify that the requested command and options will work, and
3090 #        print the results to the terminal
3091 # Output:
3092 #        True if the test will work, False if not
3093 def statusCheck():
3094         global sysvals
3095         status = True
3096
3097         if(sysvals.android):
3098                 print('Checking the android system ...')
3099         else:
3100                 print('Checking this system (%s)...' % platform.node())
3101
3102         # check if adb is connected to a device
3103         if(sysvals.android):
3104                 res = 'NO'
3105                 out = os.popen(sysvals.adb+' get-state').read().strip()
3106                 if(out == 'device'):
3107                         res = 'YES'
3108                 print('    is android device connected: %s' % res)
3109                 if(res != 'YES'):
3110                         print('    Please connect the device before using this tool')
3111                         return False
3112
3113         # check we have root access
3114         res = 'NO (No features of this tool will work!)'
3115         if(sysvals.android):
3116                 out = os.popen(sysvals.adb+' shell id').read().strip()
3117                 if('root' in out):
3118                         res = 'YES'
3119         else:
3120                 if(os.environ['USER'] == 'root'):
3121                         res = 'YES'
3122         print('    have root access: %s' % res)
3123         if(res != 'YES'):
3124                 if(sysvals.android):
3125                         print('    Try running "adb root" to restart the daemon as root')
3126                 else:
3127                         print('    Try running this script with sudo')
3128                 return False
3129
3130         # check sysfs is mounted
3131         res = 'NO (No features of this tool will work!)'
3132         if(sysvals.android):
3133                 out = os.popen(sysvals.adb+' shell ls '+\
3134                         sysvals.powerfile).read().strip()
3135                 if(out == sysvals.powerfile):
3136                         res = 'YES'
3137         else:
3138                 if(os.path.exists(sysvals.powerfile)):
3139                         res = 'YES'
3140         print('    is sysfs mounted: %s' % res)
3141         if(res != 'YES'):
3142                 return False
3143
3144         # check target mode is a valid mode
3145         res = 'NO'
3146         modes = getModes()
3147         if(sysvals.suspendmode in modes):
3148                 res = 'YES'
3149         else:
3150                 status = False
3151         print('    is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
3152         if(res == 'NO'):
3153                 print('      valid power modes are: %s' % modes)
3154                 print('      please choose one with -m')
3155
3156         # check if the tool can unlock the device
3157         if(sysvals.android):
3158                 res = 'YES'
3159                 out1 = os.popen(sysvals.adb+\
3160                         ' shell dumpsys power | grep mScreenOn').read().strip()
3161                 out2 = os.popen(sysvals.adb+\
3162                         ' shell input').read().strip()
3163                 if(not out1.startswith('mScreenOn') or not out2.startswith('usage')):
3164                         res = 'NO (wake the android device up before running the test)'
3165                 print('    can I unlock the screen: %s' % res)
3166
3167         # check if ftrace is available
3168         res = 'NO'
3169         ftgood = verifyFtrace()
3170         if(ftgood):
3171                 res = 'YES'
3172         elif(sysvals.usecallgraph):
3173                 status = False
3174         print('    is ftrace supported: %s' % res)
3175
3176         # what data source are we using
3177         res = 'DMESG'
3178         if(ftgood):
3179                 sysvals.usetraceeventsonly = True
3180                 sysvals.usetraceevents = False
3181                 for e in sysvals.traceevents:
3182                         check = False
3183                         if(sysvals.android):
3184                                 out = os.popen(sysvals.adb+' shell ls -d '+\
3185                                         sysvals.epath+e).read().strip()
3186                                 if(out == sysvals.epath+e):
3187                                         check = True
3188                         else:
3189                                 if(os.path.exists(sysvals.epath+e)):
3190                                         check = True
3191                         if(not check):
3192                                 sysvals.usetraceeventsonly = False
3193                         if(e == 'suspend_resume' and check):
3194                                 sysvals.usetraceevents = True
3195                 if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
3196                         res = 'FTRACE (all trace events found)'
3197                 elif(sysvals.usetraceevents):
3198                         res = 'DMESG and FTRACE (suspend_resume trace event found)'
3199         print('    timeline data source: %s' % res)
3200
3201         # check if rtcwake
3202         res = 'NO'
3203         if(sysvals.rtcpath != ''):
3204                 res = 'YES'
3205         elif(sysvals.rtcwake):
3206                 status = False
3207         print('    is rtcwake supported: %s' % res)
3208
3209         return status
3210
3211 # Function: doError
3212 # Description:
3213 #        generic error function for catastrphic failures
3214 # Arguments:
3215 #        msg: the error message to print
3216 #        help: True if printHelp should be called after, False otherwise
3217 def doError(msg, help):
3218         if(help == True):
3219                 printHelp()
3220         print('ERROR: %s\n') % msg
3221         sys.exit()
3222
3223 # Function: doWarning
3224 # Description:
3225 #        generic warning function for non-catastrophic anomalies
3226 # Arguments:
3227 #        msg: the warning message to print
3228 #        file: If not empty, a filename to request be sent to the owner for debug
3229 def doWarning(msg, file):
3230         print('/* %s */') % msg
3231         if(file):
3232                 print('/* For a fix, please send this'+\
3233                         ' %s file to <todd.e.brandt@intel.com> */' % file)
3234
3235 # Function: rootCheck
3236 # Description:
3237 #        quick check to see if we have root access
3238 def rootCheck():
3239         if(os.environ['USER'] != 'root'):
3240                 doError('This script must be run as root', False)
3241
3242 # Function: getArgInt
3243 # Description:
3244 #        pull out an integer argument from the command line with checks
3245 def getArgInt(name, args, min, max):
3246         try:
3247                 arg = args.next()
3248         except:
3249                 doError(name+': no argument supplied', True)
3250         try:
3251                 val = int(arg)
3252         except:
3253                 doError(name+': non-integer value given', True)
3254         if(val < min or val > max):
3255                 doError(name+': value should be between %d and %d' % (min, max), True)
3256         return val
3257
3258 # Function: rerunTest
3259 # Description:
3260 #        generate an output from an existing set of ftrace/dmesg logs
3261 def rerunTest():
3262         global sysvals
3263
3264         if(sysvals.ftracefile != ''):
3265                 doesTraceLogHaveTraceEvents()
3266         if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly):
3267                 doError('recreating this html output '+\
3268                         'requires a dmesg file', False)
3269         sysvals.setOutputFile()
3270         vprint('Output file: %s' % sysvals.htmlfile)
3271         print('PROCESSING DATA')
3272         if(sysvals.usetraceeventsonly):
3273                 testruns = parseTraceLog()
3274         else:
3275                 testruns = loadKernelLog()
3276                 for data in testruns:
3277                         parseKernelLog(data)
3278                 if(sysvals.ftracefile != ''):
3279                         appendIncompleteTraceLog(testruns)
3280         createHTML(testruns)
3281
3282 # Function: runTest
3283 # Description:
3284 #        execute a suspend/resume, gather the logs, and generate the output
3285 def runTest(subdir):
3286         global sysvals
3287
3288         # prepare for the test
3289         if(not sysvals.android):
3290                 initFtrace()
3291         else:
3292                 initFtraceAndroid()
3293         sysvals.initTestOutput(subdir)
3294
3295         vprint('Output files:\n    %s' % sysvals.dmesgfile)
3296         if(sysvals.usecallgraph or
3297                 sysvals.usetraceevents or
3298                 sysvals.usetraceeventsonly):
3299                 vprint('    %s' % sysvals.ftracefile)
3300         vprint('    %s' % sysvals.htmlfile)
3301
3302         # execute the test
3303         if(not sysvals.android):
3304                 executeSuspend()
3305         else:
3306                 executeAndroidSuspend()
3307
3308         # analyze the data and create the html output
3309         print('PROCESSING DATA')
3310         if(sysvals.usetraceeventsonly):
3311                 # data for kernels 3.15 or newer is entirely in ftrace
3312                 testruns = parseTraceLog()
3313         else:
3314                 # data for kernels older than 3.15 is primarily in dmesg
3315                 testruns = loadKernelLog()
3316                 for data in testruns:
3317                         parseKernelLog(data)
3318                 if(sysvals.usecallgraph or sysvals.usetraceevents):
3319                         appendIncompleteTraceLog(testruns)
3320         createHTML(testruns)
3321
3322 # Function: runSummary
3323 # Description:
3324 #        create a summary of tests in a sub-directory
3325 def runSummary(subdir, output):
3326         global sysvals
3327
3328         # get a list of ftrace output files
3329         files = []
3330         for dirname, dirnames, filenames in os.walk(subdir):
3331                 for filename in filenames:
3332                         if(re.match('.*_ftrace.txt', filename)):
3333                                 files.append("%s/%s" % (dirname, filename))
3334
3335         # process the files in order and get an array of data objects
3336         testruns = []
3337         for file in sorted(files):
3338                 if output:
3339                         print("Test found in %s" % os.path.dirname(file))
3340                 sysvals.ftracefile = file
3341                 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt')
3342                 doesTraceLogHaveTraceEvents()
3343                 sysvals.usecallgraph = False
3344                 if not sysvals.usetraceeventsonly:
3345                         if(not os.path.exists(sysvals.dmesgfile)):
3346                                 print("Skipping %s: not a valid test input" % file)
3347                                 continue
3348                         else:
3349                                 if output:
3350                                         f = os.path.basename(sysvals.ftracefile)
3351                                         d = os.path.basename(sysvals.dmesgfile)
3352                                         print("\tInput files: %s and %s" % (f, d))
3353                                 testdata = loadKernelLog()
3354                                 data = testdata[0]
3355                                 parseKernelLog(data)
3356                                 testdata = [data]
3357                                 appendIncompleteTraceLog(testdata)
3358                 else:
3359                         if output:
3360                                 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
3361                         testdata = parseTraceLog()
3362                         data = testdata[0]
3363                 data.normalizeTime(data.tSuspended)
3364                 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
3365                 data.outfile = link
3366                 testruns.append(data)
3367
3368         createHTMLSummarySimple(testruns, subdir+'/summary.html')
3369
3370 # Function: printHelp
3371 # Description:
3372 #        print out the help text
3373 def printHelp():
3374         global sysvals
3375         modes = getModes()
3376
3377         print('')
3378         print('AnalyzeSuspend v%.1f' % sysvals.version)
3379         print('Usage: sudo analyze_suspend.py <options>')
3380         print('')
3381         print('Description:')
3382         print('  This tool is designed to assist kernel and OS developers in optimizing')
3383         print('  their linux stack\'s suspend/resume time. Using a kernel image built')
3384         print('  with a few extra options enabled, the tool will execute a suspend and')
3385         print('  capture dmesg and ftrace data until resume is complete. This data is')
3386         print('  transformed into a device timeline and an optional callgraph to give')
3387         print('  a detailed view of which devices/subsystems are taking the most')
3388         print('  time in suspend/resume.')
3389         print('')
3390         print('  Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
3391         print('   HTML output:                    <hostname>_<mode>.html')
3392         print('   raw dmesg output:               <hostname>_<mode>_dmesg.txt')
3393         print('   raw ftrace output:              <hostname>_<mode>_ftrace.txt')
3394         print('')
3395         print('Options:')
3396         print('  [general]')
3397         print('    -h          Print this help text')
3398         print('    -v          Print the current tool version')
3399         print('    -verbose    Print extra information during execution and analysis')
3400         print('    -status     Test to see if the system is enabled to run this tool')
3401         print('    -modes      List available suspend modes')
3402         print('    -m mode     Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
3403         print('    -rtcwake t  Use rtcwake to autoresume after <t> seconds (default: disabled)')
3404         print('  [advanced]')
3405         print('    -f          Use ftrace to create device callgraphs (default: disabled)')
3406         print('    -filter "d1 d2 ..." Filter out all but this list of dev names')
3407         print('    -x2         Run two suspend/resumes back to back (default: disabled)')
3408         print('    -x2delay t  Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
3409         print('    -postres t  Time after resume completion to wait for post-resume events (default: 0 S)')
3410         print('    -multi n d  Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
3411         print('                be created in a new subdirectory with a summary page.')
3412         print('  [utilities]')
3413         print('    -fpdt       Print out the contents of the ACPI Firmware Performance Data Table')
3414         print('    -usbtopo    Print out the current USB topology with power info')
3415         print('    -usbauto    Enable autosuspend for all connected USB devices')
3416         print('  [android testing]')
3417         print('    -adb binary Use the given adb binary to run the test on an android device.')
3418         print('                The device should already be connected and with root access.')
3419         print('                Commands will be executed on the device using "adb shell"')
3420         print('  [re-analyze data from previous runs]')
3421         print('    -ftrace ftracefile  Create HTML output using ftrace input')
3422         print('    -dmesg dmesgfile    Create HTML output using dmesg (not needed for kernel >= 3.15)')
3423         print('    -summary directory  Create a summary of all test in this dir')
3424         print('')
3425         return True
3426
3427 # ----------------- MAIN --------------------
3428 # exec start (skipped if script is loaded as library)
3429 if __name__ == '__main__':
3430         cmd = ''
3431         cmdarg = ''
3432         multitest = {'run': False, 'count': 0, 'delay': 0}
3433         # loop through the command line arguments
3434         args = iter(sys.argv[1:])
3435         for arg in args:
3436                 if(arg == '-m'):
3437                         try:
3438                                 val = args.next()
3439                         except:
3440                                 doError('No mode supplied', True)
3441                         sysvals.suspendmode = val
3442                 elif(arg == '-adb'):
3443                         try:
3444                                 val = args.next()
3445                         except:
3446                                 doError('No adb binary supplied', True)
3447                         if(not os.path.exists(val)):
3448                                 doError('file doesnt exist: %s' % val, False)
3449                         if(not os.access(val, os.X_OK)):
3450                                 doError('file isnt executable: %s' % val, False)
3451                         try:
3452                                 check = os.popen(val+' version').read().strip()
3453                         except:
3454                                 doError('adb version failed to execute', False)
3455                         if(not re.match('Android Debug Bridge .*', check)):
3456                                 doError('adb version failed to execute', False)
3457                         sysvals.adb = val
3458                         sysvals.android = True
3459                 elif(arg == '-x2'):
3460                         if(sysvals.postresumetime > 0):
3461                                 doError('-x2 is not compatible with -postres', False)
3462                         sysvals.execcount = 2
3463                 elif(arg == '-x2delay'):
3464                         sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
3465                 elif(arg == '-postres'):
3466                         if(sysvals.execcount != 1):
3467                                 doError('-x2 is not compatible with -postres', False)
3468                         sysvals.postresumetime = getArgInt('-postres', args, 0, 3600)
3469                 elif(arg == '-f'):
3470                         sysvals.usecallgraph = True
3471                 elif(arg == '-modes'):
3472                         cmd = 'modes'
3473                 elif(arg == '-fpdt'):
3474                         cmd = 'fpdt'
3475                 elif(arg == '-usbtopo'):
3476                         cmd = 'usbtopo'
3477                 elif(arg == '-usbauto'):
3478                         cmd = 'usbauto'
3479                 elif(arg == '-status'):
3480                         cmd = 'status'
3481                 elif(arg == '-verbose'):
3482                         sysvals.verbose = True
3483                 elif(arg == '-v'):
3484                         print("Version %.1f" % sysvals.version)
3485                         sys.exit()
3486                 elif(arg == '-rtcwake'):
3487                         sysvals.rtcwake = True
3488                         sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
3489                 elif(arg == '-multi'):
3490                         multitest['run'] = True
3491                         multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
3492                         multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
3493                 elif(arg == '-dmesg'):
3494                         try:
3495                                 val = args.next()
3496                         except:
3497                                 doError('No dmesg file supplied', True)
3498                         sysvals.notestrun = True
3499                         sysvals.dmesgfile = val
3500                         if(os.path.exists(sysvals.dmesgfile) == False):
3501                                 doError('%s doesnt exist' % sysvals.dmesgfile, False)
3502                 elif(arg == '-ftrace'):
3503                         try:
3504                                 val = args.next()
3505                         except:
3506                                 doError('No ftrace file supplied', True)
3507                         sysvals.notestrun = True
3508                         sysvals.usecallgraph = True
3509                         sysvals.ftracefile = val
3510                         if(os.path.exists(sysvals.ftracefile) == False):
3511                                 doError('%s doesnt exist' % sysvals.ftracefile, False)
3512                 elif(arg == '-summary'):
3513                         try:
3514                                 val = args.next()
3515                         except:
3516                                 doError('No directory supplied', True)
3517                         cmd = 'summary'
3518                         cmdarg = val
3519                         sysvals.notestrun = True
3520                         if(os.path.isdir(val) == False):
3521                                 doError('%s isnt accesible' % val, False)
3522                 elif(arg == '-filter'):
3523                         try:
3524                                 val = args.next()
3525                         except:
3526                                 doError('No devnames supplied', True)
3527                         sysvals.setDeviceFilter(val)
3528                 elif(arg == '-h'):
3529                         printHelp()
3530                         sys.exit()
3531                 else:
3532                         doError('Invalid argument: '+arg, True)
3533
3534         # just run a utility command and exit
3535         if(cmd != ''):
3536                 if(cmd == 'status'):
3537                         statusCheck()
3538                 elif(cmd == 'fpdt'):
3539                         if(sysvals.android):
3540                                 doError('cannot read FPDT on android device', False)
3541                         getFPDT(True)
3542                 elif(cmd == 'usbtopo'):
3543                         if(sysvals.android):
3544                                 doError('cannot read USB topology '+\
3545                                         'on an android device', False)
3546                         detectUSB(True)
3547                 elif(cmd == 'modes'):
3548                         modes = getModes()
3549                         print modes
3550                 elif(cmd == 'usbauto'):
3551                         setUSBDevicesAuto()
3552                 elif(cmd == 'summary'):
3553                         print("Generating a summary of folder \"%s\"" % cmdarg)
3554                         runSummary(cmdarg, True)
3555                 sys.exit()
3556
3557         # run test on android device
3558         if(sysvals.android):
3559                 if(sysvals.usecallgraph):
3560                         doError('ftrace (-f) is not yet supported '+\
3561                                 'in the android kernel', False)
3562                 if(sysvals.notestrun):
3563                         doError('cannot analyze test files on the '+\
3564                                 'android device', False)
3565
3566         # if instructed, re-analyze existing data files
3567         if(sysvals.notestrun):
3568                 rerunTest()
3569                 sys.exit()
3570
3571         # verify that we can run a test
3572         if(not statusCheck()):
3573                 print('Check FAILED, aborting the test run!')
3574                 sys.exit()
3575
3576         if multitest['run']:
3577                 # run multiple tests in a separte subdirectory
3578                 s = 'x%d' % multitest['count']
3579                 subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
3580                 os.mkdir(subdir)
3581                 for i in range(multitest['count']):
3582                         if(i != 0):
3583                                 print('Waiting %d seconds...' % (multitest['delay']))
3584                                 time.sleep(multitest['delay'])
3585                         print('TEST (%d/%d) START' % (i+1, multitest['count']))
3586                         runTest(subdir)
3587                         print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
3588                 runSummary(subdir, False)
3589         else:
3590                 # run the test in the current directory
3591                 runTest(".")