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 #        The following additional kernel parameters are required:
  40 #                (e.g. in file /etc/default/grub)
  41 #                GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
  42 #
  43
  44 import sys
  45 import time
  46 import os
  47 import string
  48 import re
  49 import array
  50 import platform
  51 import datetime
  52 import struct
  53
  54 # -- classes --
  55
  56 class SystemValues:
  57         testdir = "."
  58         tpath = "/sys/kernel/debug/tracing/"
  59         mempath = "/dev/mem"
  60         powerfile = "/sys/power/state"
  61         suspendmode = "mem"
  62         prefix = "test"
  63         teststamp = ""
  64         dmesgfile = ""
  65         ftracefile = ""
  66         htmlfile = ""
  67         rtcwake = False
  68         def setOutputFile(self):
  69                 if((self.htmlfile == "") and (self.dmesgfile != "")):
  70                         m = re.match(r"(?P<name>.*)_dmesg\.txt$", self.dmesgfile)
  71                         if(m):
  72                                 self.htmlfile = m.group("name")+".html"
  73                 if((self.htmlfile == "") and (self.ftracefile != "")):
  74                         m = re.match(r"(?P<name>.*)_ftrace\.txt$", self.ftracefile)
  75                         if(m):
  76                                 self.htmlfile = m.group("name")+".html"
  77                 if(self.htmlfile == ""):
  78                         self.htmlfile = "output.html"
  79         def initTestOutput(self):
  80                 hostname = platform.node()
  81                 if(hostname != ""):
  82                         self.prefix = hostname
  83                 v = os.popen("cat /proc/version").read().strip()
  84                 kver = string.split(v)[2]
  85                 self.testdir = os.popen("date \"+suspend-%m%d%y-%H%M%S\"").read().strip()
  86                 self.teststamp = "# "+self.testdir+" "+self.prefix+" "+self.suspendmode+" "+kver
  87                 self.dmesgfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_dmesg.txt"
  88                 self.ftracefile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+"_ftrace.txt"
  89                 self.htmlfile = self.testdir+"/"+self.prefix+"_"+self.suspendmode+".html"
  90                 os.mkdir(self.testdir)
  91
  92 class Data:
  93         altdevname = dict()
  94         usedmesg = False
  95         useftrace = False
  96         notestrun = False
  97         verbose = False
  98         phases = []
  99         dmesg = {} # root data structure
 100         start = 0.0
 101         end = 0.0
 102         stamp = {'time': "", 'host': "", 'mode': ""}
 103         id = 0
 104         tSuspended = 0.0
 105         fwValid = False
 106         fwSuspend = 0
 107         fwResume = 0
 108         def initialize(self):
 109                 self.dmesg = { # dmesg log data
 110                         'suspend_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
 111                                                                 'row': 0, 'color': "#CCFFCC", 'order': 0},
 112                           'suspend_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
 113                                                                 'row': 0, 'color': "green", 'order': 1},
 114                           'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
 115                                                                 'row': 0, 'color': "#00FFFF", 'order': 2},
 116                                 'suspend_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
 117                                                                 'row': 0, 'color': "blue", 'order': 3},
 118                                  'resume_cpu': {'list': dict(), 'start': -1.0, 'end': -1.0,
 119                                                                 'row': 0, 'color': "red", 'order': 4},
 120                            'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
 121                                                                 'row': 0, 'color': "orange", 'order': 5},
 122                            'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
 123                                                                 'row': 0, 'color': "yellow", 'order': 6},
 124                          'resume_general': {'list': dict(), 'start': -1.0, 'end': -1.0,
 125                                                                 'row': 0, 'color': "#FFFFCC", 'order': 7}
 126                 }
 127                 self.phases = self.sortedPhases()
 128         def normalizeTime(self):
 129                 tSus = tRes = self.tSuspended
 130                 if self.fwValid:
 131                         tSus -= -self.fwSuspend / 1000000000.0
 132                         tRes -= self.fwResume / 1000000000.0
 133                 self.tSuspended = 0.0
 134                 self.start -= tSus
 135                 self.end -= tRes
 136                 for phase in self.phases:
 137                         zero = tRes
 138                         if "suspend" in phase:
 139                                 zero = tSus
 140                         p = self.dmesg[phase]
 141                         p['start'] -= zero
 142                         p['end'] -= zero
 143                         list = p['list']
 144                         for name in list:
 145                                 d = list[name]
 146                                 d['start'] -= zero
 147                                 d['end'] -= zero
 148                                 if('ftrace' in d):
 149                                         cg = d['ftrace']
 150                                         cg.start -= zero
 151                                         cg.end -= zero
 152                                         for line in cg.list:
 153                                                 line.time -= zero
 154                 if self.fwValid:
 155                         fws = -self.fwSuspend / 1000000000.0
 156                         fwr = self.fwResume / 1000000000.0
 157                         list = dict()
 158                         self.id += 1
 159                         devid = "dc%d" % self.id
 160                         list["firmware-suspend"] = \
 161                                 {'start': fws, 'end': 0, 'pid': 0, 'par': "",
 162                                 'length': -fws, 'row': 0, 'id': devid };
 163                         self.id += 1
 164                         devid = "dc%d" % self.id
 165                         list["firmware-resume"] = \
 166                                 {'start': 0, 'end': fwr, 'pid': 0, 'par': "",
 167                                 'length': fwr, 'row': 0, 'id': devid };
 168                         self.dmesg['BIOS'] = \
 169                                 {'list': list, 'start': fws, 'end': fwr,
 170                                 'row': 0, 'color': "purple", 'order': 4}
 171                         self.dmesg['resume_cpu']['order'] += 1
 172                         self.dmesg['resume_noirq']['order'] += 1
 173                         self.dmesg['resume_early']['order'] += 1
 174                         self.dmesg['resume_general']['order'] += 1
 175                         self.phases = self.sortedPhases()
 176         def vprint(self, msg):
 177                 if(self.verbose):
 178                         print(msg)
 179         def dmesgSortVal(self, phase):
 180                 return self.dmesg[phase]['order']
 181         def sortedPhases(self):
 182                 return sorted(self.dmesg, key=self.dmesgSortVal)
 183         def sortedDevices(self, phase):
 184                 list = self.dmesg[phase]['list']
 185                 slist = []
 186                 tmp = dict()
 187                 for devname in list:
 188                         dev = list[devname]
 189                         tmp[dev['start']] = devname
 190                 for t in sorted(tmp):
 191                         slist.append(tmp[t])
 192                 return slist
 193         def fixupInitcalls(self, phase, end):
 194                 # if any calls never returned, clip them at system resume end
 195                 phaselist = self.dmesg[phase]['list']
 196                 for devname in phaselist:
 197                         dev = phaselist[devname]
 198                         if(dev['end'] < 0):
 199                                 dev['end'] = end
 200                                 self.vprint("%s (%s): callback didn't return" % (devname, phase))
 201         def fixupInitcallsThatDidntReturn(self):
 202                 # if any calls never returned, clip them at system resume end
 203                 for phase in self.phases:
 204                         self.fixupInitcalls(phase, self.dmesg['resume_general']['end'])
 205                         if(phase == "resume_general"):
 206                                 break
 207         def newAction(self, phase, name, pid, parent, start, end):
 208                 self.id += 1
 209                 devid = "dc%d" % self.id
 210                 list = self.dmesg[phase]['list']
 211                 length = -1.0
 212                 if(start >= 0 and end >= 0):
 213                         length = end - start
 214                 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
 215                                           'length': length, 'row': 0, 'id': devid }
 216         def deviceIDs(self, devlist, phase):
 217                 idlist = []
 218                 for p in self.phases:
 219                         if(p[0] != phase[0]):
 220                                 continue
 221                         list = data.dmesg[p]['list']
 222                         for devname in list:
 223                                 if devname in devlist:
 224                                         idlist.append(list[devname]['id'])
 225                 return idlist
 226         def deviceParentID(self, devname, phase):
 227                 pdev = ""
 228                 pdevid = ""
 229                 for p in self.phases:
 230                         if(p[0] != phase[0]):
 231                                 continue
 232                         list = data.dmesg[p]['list']
 233                         if devname in list:
 234                                 pdev = list[devname]['par']
 235                 for p in self.phases:
 236                         if(p[0] != phase[0]):
 237                                 continue
 238                         list = data.dmesg[p]['list']
 239                         if pdev in list:
 240                                 return list[pdev]['id']
 241                 return pdev
 242         def deviceChildrenIDs(self, devname, phase):
 243                 devlist = []
 244                 for p in self.phases:
 245                         if(p[0] != phase[0]):
 246                                 continue
 247                         list = data.dmesg[p]['list']
 248                         for child in list:
 249                                 if(list[child]['par'] == devname):
 250                                         devlist.append(child)
 251                 return self.deviceIDs(devlist, phase)
 252
 253 class FTraceLine:
 254         time = 0.0
 255         length = 0.0
 256         fcall = False
 257         freturn = False
 258         fevent = False
 259         depth = 0
 260         name = ""
 261         def __init__(self, t, m, d):
 262                 self.time = float(t)
 263                 # check to see if this is a trace event
 264                 em = re.match(r"^ *\/\* *(?P<msg>.*) \*\/ *$", m)
 265                 if(em):
 266                         self.name = em.group("msg")
 267                         self.fevent = True
 268                         return
 269                 # convert the duration to seconds
 270                 if(d):
 271                         self.length = float(d)/1000000
 272                 # the indentation determines the depth
 273                 match = re.match(r"^(?P<d> *)(?P<o>.*)$", m)
 274                 if(not match):
 275                         return
 276                 self.depth = self.getDepth(match.group('d'))
 277                 m = match.group('o')
 278                 # function return
 279                 if(m[0] == '}'):
 280                         self.freturn = True
 281                         if(len(m) > 1):
 282                                 # includes comment with function name
 283                                 match = re.match(r"^} *\/\* *(?P<n>.*) *\*\/$", m)
 284                                 if(match):
 285                                         self.name = match.group('n')
 286                 # function call
 287                 else:
 288                         self.fcall = True
 289                         # function call with children
 290                         if(m[-1] == '{'):
 291                                 match = re.match(r"^(?P<n>.*) *\(.*", m)
 292                                 if(match):
 293                                         self.name = match.group('n')
 294                         # function call with no children (leaf)
 295                         elif(m[-1] == ';'):
 296                                 self.freturn = True
 297                                 match = re.match(r"^(?P<n>.*) *\(.*", m)
 298                                 if(match):
 299                                         self.name = match.group('n')
 300                         # something else (possibly a trace marker)
 301                         else:
 302                                 self.name = m
 303         def getDepth(self, str):
 304                 return len(str)/2
 305
 306 class FTraceCallGraph:
 307         start = -1.0
 308         end = -1.0
 309         list = []
 310         invalid = False
 311         depth = 0
 312         def __init__(self):
 313                 self.start = -1.0
 314                 self.end = -1.0
 315                 self.list = []
 316                 self.depth = 0
 317         def setDepth(self, line):
 318                 if(line.fcall and not line.freturn):
 319                         line.depth = self.depth
 320                         self.depth += 1
 321                 elif(line.freturn and not line.fcall):
 322                         self.depth -= 1
 323                         line.depth = self.depth
 324                 else:
 325                         line.depth = self.depth
 326         def addLine(self, line, match):
 327                 if(not self.invalid):
 328                         self.setDepth(line)
 329                 if(line.depth == 0 and line.freturn):
 330                         self.end = line.time
 331                         self.list.append(line)
 332                         return True
 333                 if(self.invalid):
 334                         return False
 335                 if(len(self.list) >= 1000000 or self.depth < 0):
 336                    first = self.list[0]
 337                    self.list = []
 338                    self.list.append(first)
 339                    self.invalid = True
 340                    id = "task %s cpu %s" % (match.group("pid"), match.group("cpu"))
 341                    window = "(%f - %f)" % (self.start, line.time)
 342                    data.vprint("Too much data for "+id+" "+window+", ignoring this callback")
 343                    return False
 344                 self.list.append(line)
 345                 if(self.start < 0):
 346                         self.start = line.time
 347                 return False
 348         def sanityCheck(self):
 349                 stack = dict()
 350                 cnt = 0
 351                 for l in self.list:
 352                         if(l.fcall and not l.freturn):
 353                                 stack[l.depth] = l
 354                                 cnt += 1
 355                         elif(l.freturn and not l.fcall):
 356                                 if(not stack[l.depth]):
 357                                         return False
 358                                 stack[l.depth].length = l.length
 359                                 stack[l.depth] = 0
 360                                 l.length = 0
 361                                 cnt -= 1
 362                 if(cnt == 0):
 363                         return True
 364                 return False
 365         def debugPrint(self, filename):
 366                 if(filename == "stdout"):
 367                         print("[%f - %f]") % (self.start, self.end)
 368                         for l in self.list:
 369                                 if(l.freturn and l.fcall):
 370                                         print("%f (%02d): %s(); (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
 371                                 elif(l.freturn):
 372                                         print("%f (%02d): %s} (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
 373                                 else:
 374                                         print("%f (%02d): %s() { (%.3f us)" % (l.time, l.depth, l.name, l.length*1000000))
 375                         print(" ")
 376                 else:
 377                         fp = open(filename, 'w')
 378                         print(filename)
 379                         for l in self.list:
 380                                 if(l.freturn and l.fcall):
 381                                         fp.write("%f (%02d): %s(); (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
 382                                 elif(l.freturn):
 383                                         fp.write("%f (%02d): %s} (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
 384                                 else:
 385                                         fp.write("%f (%02d): %s() { (%.3f us)\n" % (l.time, l.depth, l.name, l.length*1000000))
 386                         fp.close()
 387
 388 class Timeline:
 389         html = {}
 390         scaleH = 0.0 # height of the timescale row as a percent of the timeline height
 391         rowH = 0.0 # height of each row in percent of the timeline height
 392         row_height_pixels = 30
 393         maxrows = 0
 394         height = 0
 395         def __init__(self):
 396                 self.html = {
 397                         'timeline': "",
 398                         'legend': "",
 399                         'scale': ""
 400                 }
 401         def setRows(self, rows):
 402                 self.maxrows = int(rows)
 403                 self.scaleH = 100.0/float(self.maxrows)
 404                 self.height = self.maxrows*self.row_height_pixels
 405                 r = float(self.maxrows - 1)
 406                 if(r < 1.0):
 407                         r = 1.0
 408                 self.rowH = (100.0 - self.scaleH)/r
 409
 410 # -- global objects --
 411
 412 sysvals = SystemValues()
 413 data = Data()
 414
 415 # -- functions --
 416
 417 # Function: initFtrace
 418 # Description:
 419 #        Configure ftrace to capture a function trace during suspend/resume
 420 def initFtrace():
 421         global sysvals
 422
 423         print("INITIALIZING FTRACE...")
 424         # turn trace off
 425         os.system("echo 0 > "+sysvals.tpath+"tracing_on")
 426         # set the trace clock to global
 427         os.system("echo global > "+sysvals.tpath+"trace_clock")
 428         # set trace buffer to a huge value
 429         os.system("echo nop > "+sysvals.tpath+"current_tracer")
 430         os.system("echo 100000 > "+sysvals.tpath+"buffer_size_kb")
 431         # clear the trace buffer
 432         os.system("echo \"\" > "+sysvals.tpath+"trace")
 433         # set trace type
 434         os.system("echo function_graph > "+sysvals.tpath+"current_tracer")
 435         os.system("echo \"\" > "+sysvals.tpath+"set_ftrace_filter")
 436         # set trace format options
 437         os.system("echo funcgraph-abstime > "+sysvals.tpath+"trace_options")
 438         os.system("echo funcgraph-proc > "+sysvals.tpath+"trace_options")
 439         # focus only on device suspend and resume
 440         os.system("cat "+sysvals.tpath+"available_filter_functions | grep dpm_run_callback > "+sysvals.tpath+"set_graph_function")
 441
 442 # Function: verifyFtrace
 443 # Description:
 444 #        Check that ftrace is working on the system
 445 def verifyFtrace():
 446         global sysvals
 447         files = ["available_filter_functions", "buffer_size_kb",
 448                          "current_tracer", "set_ftrace_filter",
 449                          "trace", "trace_marker"]
 450         for f in files:
 451                 if(os.path.exists(sysvals.tpath+f) == False):
 452                         return False
 453         return True
 454
 455 def parseStamp(line):
 456         global data, sysvals
 457         stampfmt = r"# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-"+\
 458                                 "(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})"+\
 459                                 " (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$"
 460         m = re.match(stampfmt, line)
 461         if(m):
 462                 dt = datetime.datetime(int(m.group("y"))+2000, int(m.group("m")),
 463                         int(m.group("d")), int(m.group("H")), int(m.group("M")),
 464                         int(m.group("S")))
 465                 data.stamp['time'] = dt.strftime("%B %d %Y, %I:%M:%S %p")
 466                 data.stamp['host'] = m.group("host")
 467                 data.stamp['mode'] = m.group("mode")
 468                 data.stamp['kernel'] = m.group("kernel")
 469                 sysvals.suspendmode = data.stamp['mode']
 470
 471 # Function: analyzeTraceLog
 472 # Description:
 473 #        Analyse an ftrace log output file generated from this app during
 474 #        the execution phase. Create an "ftrace" structure in memory for
 475 #        subsequent formatting in the html output file
 476 def analyzeTraceLog():
 477         global sysvals, data
 478
 479         # the ftrace data is tied to the dmesg data
 480         if(not data.usedmesg):
 481                 return
 482
 483         # read through the ftrace and parse the data
 484         data.vprint("Analyzing the ftrace data...")
 485         ftrace_line_fmt = r"^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)"+\
 486                                            " *(?P<proc>.*)-(?P<pid>[0-9]*) *\|"+\
 487                                            "[ +!]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)"
 488         ftemp = dict()
 489         inthepipe = False
 490         tf = open(sysvals.ftracefile, 'r')
 491         count = 0
 492         for line in tf:
 493                 count = count + 1
 494                 # grab the time stamp if it's valid
 495                 if(count == 1):
 496                         parseStamp(line)
 497                         continue
 498                 # parse only valid lines
 499                 m = re.match(ftrace_line_fmt, line)
 500                 if(not m):
 501                         continue
 502                 m_time = m.group("time")
 503                 m_pid = m.group("pid")
 504                 m_msg = m.group("msg")
 505                 m_dur = m.group("dur")
 506                 if(m_time and m_pid and m_msg):
 507                         t = FTraceLine(m_time, m_msg, m_dur)
 508                         pid = int(m_pid)
 509                 else:
 510                         continue
 511                 # the line should be a call, return, or event
 512                 if(not t.fcall and not t.freturn and not t.fevent):
 513                         continue
 514                 # only parse the ftrace data during suspend/resume
 515                 if(not inthepipe):
 516                         # look for the suspend start marker
 517                         if(t.fevent):
 518                                 if(t.name == "SUSPEND START"):
 519                                         data.vprint("SUSPEND START %f %s:%d" % (t.time, sysvals.ftracefile, count))
 520                                         inthepipe = True
 521                                 continue
 522                 else:
 523                         # look for the resume end marker
 524                         if(t.fevent):
 525                                 if(t.name == "RESUME COMPLETE"):
 526                                         data.vprint("RESUME COMPLETE %f %s:%d" % (t.time, sysvals.ftracefile, count))
 527                                         inthepipe = False
 528                                         break
 529                                 continue
 530                         # create a callgraph object for the data
 531                         if(pid not in ftemp):
 532                                 ftemp[pid] = FTraceCallGraph()
 533                         # when the call is finished, see which device matches it
 534                         if(ftemp[pid].addLine(t, m)):
 535                                 if(not ftemp[pid].sanityCheck()):
 536                                         id = "task %s cpu %s" % (pid, m.group("cpu"))
 537                                         data.vprint("Sanity check failed for "+id+", ignoring this callback")
 538                                         continue
 539                                 callstart = ftemp[pid].start
 540                                 callend = ftemp[pid].end
 541                                 for p in data.phases:
 542                                         if(data.dmesg[p]['start'] <= callstart and callstart <= data.dmesg[p]['end']):
 543                                                 list = data.dmesg[p]['list']
 544                                                 for devname in list:
 545                                                         dev = list[devname]
 546                                                         if(pid == dev['pid'] and callstart <= dev['start'] and callend >= dev['end']):
 547                                                                 data.vprint("%15s [%f - %f] %s(%d)" % (p, callstart, callend, devname, pid))
 548                                                                 dev['ftrace'] = ftemp[pid]
 549                                                 break
 550                                 ftemp[pid] = FTraceCallGraph()
 551         tf.close()
 552
 553 # Function: sortKernelLog
 554 # Description:
 555 #        The dmesg output log sometimes comes with with lines that have
 556 #        timestamps out of order. This could cause issues since a call
 557 #        could accidentally end up in the wrong phase
 558 def sortKernelLog():
 559         global sysvals, data
 560         lf = open(sysvals.dmesgfile, 'r')
 561         dmesglist = []
 562         count = 0
 563         for line in lf:
 564                 line = line.replace("\r\n", "")
 565                 if(count == 0):
 566                         parseStamp(line)
 567                 elif(count == 1):
 568                         m = re.match(r"# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$", line)
 569                         if(m):
 570                                 data.fwSuspend = int(m.group("s"))
 571                                 data.fwResume = int(m.group("r"))
 572                                 if(data.fwSuspend > 0 or data.fwResume > 0):
 573                                         data.fwValid = True
 574                 if(re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)):
 575                         dmesglist.append(line)
 576                 count += 1
 577         lf.close()
 578         last = ""
 579
 580         # fix lines with the same time stamp and function with the call and return swapped
 581         for line in dmesglist:
 582                 mc = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) calling  (?P<f>.*)\+ @ .*, parent: .*", line)
 583                 mr = re.match(r".*(\[ *)(?P<t>[0-9\.]*)(\]) call (?P<f>.*)\+ returned .* after (?P<dt>.*) usecs", last)
 584                 if(mc and mr and (mc.group("t") == mr.group("t")) and (mc.group("f") == mr.group("f"))):
 585                         i = dmesglist.index(last)
 586                         j = dmesglist.index(line)
 587                         dmesglist[i] = line
 588                         dmesglist[j] = last
 589                 last = line
 590         return dmesglist
 591
 592 # Function: analyzeKernelLog
 593 # Description:
 594 #        Analyse a dmesg log output file generated from this app during
 595 #        the execution phase. Create a set of device structures in memory
 596 #        for subsequent formatting in the html output file
 597 def analyzeKernelLog():
 598         global sysvals, data
 599
 600         print("PROCESSING DATA")
 601         data.vprint("Analyzing the dmesg data...")
 602         if(os.path.exists(sysvals.dmesgfile) == False):
 603                 print("ERROR: %s doesn't exist") % sysvals.dmesgfile
 604                 return False
 605
 606         lf = sortKernelLog()
 607         phase = "suspend_runtime"
 608
 609         dm = {
 610                 'suspend_general': r"PM: Syncing filesystems.*",
 611                   'suspend_early': r"PM: suspend of devices complete after.*",
 612                   'suspend_noirq': r"PM: late suspend of devices complete after.*",
 613                     'suspend_cpu': r"PM: noirq suspend of devices complete after.*",
 614                      'resume_cpu': r"ACPI: Low-level resume complete.*",
 615                    'resume_noirq': r"ACPI: Waking up from system sleep state.*",
 616                    'resume_early': r"PM: noirq resume of devices complete after.*",
 617                  'resume_general': r"PM: early resume of devices complete after.*",
 618                 'resume_complete': r".*Restarting tasks \.\.\..*",
 619         }
 620         if(sysvals.suspendmode == "standby"):
 621                 dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
 622         elif(sysvals.suspendmode == "disk"):
 623                 dm['suspend_early'] = r"PM: freeze of devices complete after.*"
 624                 dm['suspend_noirq'] = r"PM: late freeze of devices complete after.*"
 625                 dm['suspend_cpu'] = r"PM: noirq freeze of devices complete after.*"
 626                 dm['resume_cpu'] = r"PM: Restoring platform NVS memory"
 627                 dm['resume_early'] = r"PM: noirq restore of devices complete after.*"
 628                 dm['resume_general'] = r"PM: early restore of devices complete after.*"
 629
 630         action_start = 0.0
 631         for line in lf:
 632                 # -- preprocessing --
 633                 # parse each dmesg line into the time and message
 634                 m = re.match(r".*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)", line)
 635                 if(m):
 636                         ktime = float(m.group("ktime"))
 637                         msg = m.group("msg")
 638                 else:
 639                         print line
 640                         continue
 641
 642                 # -- phase changes --
 643                 # suspend_general start
 644                 if(re.match(dm['suspend_general'], msg)):
 645                         phase = "suspend_general"
 646                         data.dmesg[phase]['start'] = ktime
 647                         data.start = ktime
 648                         # action start: syncing filesystems
 649                         action_start = ktime
 650                 # suspend_early start
 651                 elif(re.match(dm['suspend_early'], msg)):
 652                         data.dmesg["suspend_general"]['end'] = ktime
 653                         phase = "suspend_early"
 654                         data.dmesg[phase]['start'] = ktime
 655                 # suspend_noirq start
 656                 elif(re.match(dm['suspend_noirq'], msg)):
 657                         data.dmesg["suspend_early"]['end'] = ktime
 658                         phase = "suspend_noirq"
 659                         data.dmesg[phase]['start'] = ktime
 660                 # suspend_cpu start
 661                 elif(re.match(dm['suspend_cpu'], msg)):
 662                         data.dmesg["suspend_noirq"]['end'] = ktime
 663                         phase = "suspend_cpu"
 664                         data.dmesg[phase]['start'] = ktime
 665                 # resume_cpu start
 666                 elif(re.match(dm['resume_cpu'], msg)):
 667                         data.tSuspended = ktime
 668                         data.dmesg["suspend_cpu"]['end'] = ktime
 669                         phase = "resume_cpu"
 670                         data.dmesg[phase]['start'] = ktime
 671                 # resume_noirq start
 672                 elif(re.match(dm['resume_noirq'], msg)):
 673                         data.dmesg["resume_cpu"]['end'] = ktime
 674                         phase = "resume_noirq"
 675                         data.dmesg[phase]['start'] = ktime
 676                         # action end: ACPI resume
 677                         data.newAction("resume_cpu", "ACPI", -1, "", action_start, ktime)
 678                 # resume_early start
 679                 elif(re.match(dm['resume_early'], msg)):
 680                         data.dmesg["resume_noirq"]['end'] = ktime
 681                         phase = "resume_early"
 682                         data.dmesg[phase]['start'] = ktime
 683                 # resume_general start
 684                 elif(re.match(dm['resume_general'], msg)):
 685                         data.dmesg["resume_early"]['end'] = ktime
 686                         phase = "resume_general"
 687                         data.dmesg[phase]['start'] = ktime
 688                 # resume complete start
 689                 elif(re.match(dm['resume_complete'], msg)):
 690                         data.dmesg["resume_general"]['end'] = ktime
 691                         data.end = ktime
 692                         phase = "resume_runtime"
 693                         break
 694
 695                 # -- device callbacks --
 696                 if(phase in data.phases):
 697                         # device init call
 698                         if(re.match(r"calling  (?P<f>.*)\+ @ .*, parent: .*", msg)):
 699                                 sm = re.match(r"calling  (?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)", msg);
 700                                 f = sm.group("f")
 701                                 n = sm.group("n")
 702                                 p = sm.group("p")
 703                                 if(f and n and p):
 704                                         data.newAction(phase, f, int(n), p, ktime, -1)
 705                         # device init return
 706                         elif(re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs", msg)):
 707                                 sm = re.match(r"call (?P<f>.*)\+ returned .* after (?P<t>.*) usecs(?P<a>.*)", msg);
 708                                 f = sm.group("f")
 709                                 t = sm.group("t")
 710                                 list = data.dmesg[phase]['list']
 711                                 if(f in list):
 712                                         dev = list[f]
 713                                         dev['length'] = int(t)
 714                                         dev['end'] = ktime
 715                                         data.vprint("%15s [%f - %f] %s(%d) %s" %
 716                                                 (phase, dev['start'], dev['end'], f, dev['pid'], dev['par']))
 717
 718                 # -- phase specific actions --
 719                 if(phase == "suspend_general"):
 720                         if(re.match(r"PM: Preparing system for mem sleep.*", msg)):
 721                                 data.newAction(phase, "filesystem-sync", -1, "", action_start, ktime)
 722                         elif(re.match(r"Freezing user space processes .*", msg)):
 723                                 action_start = ktime
 724                         elif(re.match(r"Freezing remaining freezable tasks.*", msg)):
 725                                 data.newAction(phase, "freeze-user-processes", -1, "", action_start, ktime)
 726                                 action_start = ktime
 727                         elif(re.match(r"PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*", msg)):
 728                                 data.newAction(phase, "freeze-tasks", -1, "", action_start, ktime)
 729                 elif(phase == "suspend_cpu"):
 730                         m = re.match(r"smpboot: CPU (?P<cpu>[0-9]*) is now offline", msg)
 731                         if(m):
 732                                 cpu = "CPU"+m.group("cpu")
 733                                 data.newAction(phase, cpu, -1, "", action_start, ktime)
 734                                 action_start = ktime
 735                         elif(re.match(r"ACPI: Preparing to enter system sleep state.*", msg)):
 736                                 action_start = ktime
 737                         elif(re.match(r"Disabling non-boot CPUs .*", msg)):
 738                                 data.newAction(phase, "ACPI", -1, "", action_start, ktime)
 739                                 action_start = ktime
 740                 elif(phase == "resume_cpu"):
 741                         m = re.match(r"CPU(?P<cpu>[0-9]*) is up", msg)
 742                         if(m):
 743                                 cpu = "CPU"+m.group("cpu")
 744                                 data.newAction(phase, cpu, -1, "", action_start, ktime)
 745                                 action_start = ktime
 746                         elif(re.match(r"Enabling non-boot CPUs .*", msg)):
 747                                 action_start = ktime
 748
 749         # fill in any missing phases
 750         lp = "suspend_general"
 751         for p in data.phases:
 752                 if(p == "suspend_general"):
 753                         continue
 754                 if(data.dmesg[p]['start'] < 0):
 755                         data.dmesg[p]['start'] = data.dmesg[lp]['end']
 756                         if(p == "resume_cpu"):
 757                                 data.tSuspended = data.dmesg[lp]['end']
 758                 if(data.dmesg[p]['end'] < 0):
 759                         data.dmesg[p]['end'] = data.dmesg[p]['start']
 760                 lp = p
 761
 762         data.fixupInitcallsThatDidntReturn()
 763         return True
 764
 765 # Function: setTimelineRows
 766 # Description:
 767 #        Organize the device or thread lists into the smallest
 768 #        number of rows possible, with no entry overlapping
 769 # Arguments:
 770 #        list: the list to sort (dmesg or ftrace)
 771 #        sortedkeys: sorted key list to use
 772 def setTimelineRows(list, sortedkeys):
 773         global data
 774
 775         # clear all rows and set them to undefined
 776         remaining = len(list)
 777         rowdata = dict()
 778         row = 0
 779         for item in list:
 780                 list[item]['row'] = -1
 781
 782         # try to pack each row with as many ranges as possible
 783         while(remaining > 0):
 784                 if(row not in rowdata):
 785                         rowdata[row] = []
 786                 for item in sortedkeys:
 787                         if(list[item]['row'] < 0):
 788                                 s = list[item]['start']
 789                                 e = list[item]['end']
 790                                 valid = True
 791                                 for ritem in rowdata[row]:
 792                                         rs = ritem['start']
 793                                         re = ritem['end']
 794                                         if(not (((s <= rs) and (e <= rs)) or ((s >= re) and (e >= re)))):
 795                                                 valid = False
 796                                                 break
 797                                 if(valid):
 798                                         rowdata[row].append(list[item])
 799                                         list[item]['row'] = row
 800                                         remaining -= 1
 801                 row += 1
 802         return row
 803
 804 # Function: createTimeScale
 805 # Description:
 806 #        Create timescale lines for the dmesg and ftrace timelines
 807 # Arguments:
 808 #        t0: start time (suspend begin)
 809 #        tMax: end time (resume end)
 810 #        tSuspend: time when suspend occurs
 811 def createTimeScale(t0, tMax, tSuspended):
 812         global data
 813         timescale = "<div class=\"t\" style=\"right:{0}%\">{1}</div>\n"
 814         output = '<div id="timescale">\n'
 815
 816         # set scale for timeline
 817         tTotal = tMax - t0
 818         tS = 0.1
 819         if(tTotal <= 0):
 820                 return output
 821         if(tTotal > 4):
 822                 tS = 1
 823         if(tSuspended < 0):
 824                 for i in range(int(tTotal/tS)+1):
 825                         pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal))
 826                         if(i > 0):
 827                                 val = "%0.f" % (float(i)*tS*1000)
 828                         else:
 829                                 val = ""
 830                         output += timescale.format(pos, val)
 831         else:
 832                 tSuspend = tSuspended - t0
 833                 divTotal = int(tTotal/tS) + 1
 834                 divSuspend = int(tSuspend/tS)
 835                 s0 = (tSuspend - tS*divSuspend)*100/tTotal
 836                 for i in range(divTotal):
 837                         pos = "%0.3f" % (100 - ((float(i)*tS*100)/tTotal) - s0)
 838                         if((i == 0) and (s0 < 3)):
 839                                 val = ""
 840                         elif(i == divSuspend):
 841                                 val = "S/R"
 842                         else:
 843                                 val = "%0.f" % (float(i-divSuspend)*tS*1000)
 844                         output += timescale.format(pos, val)
 845         output += '</div>\n'
 846         return output
 847
 848 # Function: createHTML
 849 # Description:
 850 #        Create the output html file.
 851 def createHTML():
 852         global sysvals, data
 853
 854         data.normalizeTime()
 855
 856         # html function templates
 857         headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
 858         html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n<div id="dmesgzoombox" class="zoombox">\n'
 859         html_timeline = '<div id="{0}" class="timeline" style="height:{1}px">\n'
 860         html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
 861         html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
 862         html_legend = '<div class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
 863         html_timetotal = '<table class="time1">\n<tr>'\
 864                 '<td class="gray">{2} Suspend Time: <b>{0} ms</b></td>'\
 865                 '<td class="gray">{2} Resume Time: <b>{1} ms</b></td>'\
 866                 '</tr>\n</table>\n'
 867         html_timegroups = '<table class="time2">\n<tr>'\
 868                 '<td class="green">Kernel Suspend: {0} ms</td>'\
 869                 '<td class="purple">Firmware Suspend: {1} ms</td>'\
 870                 '<td class="purple">Firmware Resume: {2} ms</td>'\
 871                 '<td class="yellow">Kernel Resume: {3} ms</td>'\
 872                 '</tr>\n</table>\n'
 873
 874         # device timeline (dmesg)
 875         if(data.usedmesg):
 876                 data.vprint("Creating Device Timeline...")
 877                 devtl = Timeline()
 878
 879                 # Generate the header for this timeline
 880                 t0 = data.start
 881                 tMax = data.end
 882                 tTotal = tMax - t0
 883                 if(tTotal == 0):
 884                         print("ERROR: No timeline data")
 885                         sys.exit()
 886                 suspend_time = "%.0f"%(-data.start*1000)
 887                 resume_time = "%.0f"%(data.end*1000)
 888                 if data.fwValid:
 889                         devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Total")
 890                         sktime = "%.3f"%((data.dmesg['suspend_cpu']['end'] - data.dmesg['suspend_general']['start'])*1000)
 891                         sftime = "%.3f"%(data.fwSuspend / 1000000.0)
 892                         rftime = "%.3f"%(data.fwResume / 1000000.0)
 893                         rktime = "%.3f"%((data.dmesg['resume_general']['end'] - data.dmesg['resume_cpu']['start'])*1000)
 894                         devtl.html['timeline'] += html_timegroups.format(sktime, sftime, rftime, rktime)
 895                 else:
 896                         devtl.html['timeline'] = html_timetotal.format(suspend_time, resume_time, "Kernel")
 897
 898                 # determine the maximum number of rows we need to draw
 899                 timelinerows = 0
 900                 for phase in data.dmesg:
 901                         list = data.dmesg[phase]['list']
 902                         rows = setTimelineRows(list, list)
 903                         data.dmesg[phase]['row'] = rows
 904                         if(rows > timelinerows):
 905                                 timelinerows = rows
 906
 907                 # calculate the timeline height and create its bounding box
 908                 devtl.setRows(timelinerows + 1)
 909                 devtl.html['timeline'] += html_zoombox;
 910                 devtl.html['timeline'] += html_timeline.format("dmesg", devtl.height);
 911
 912                 # draw the colored boxes for each of the phases
 913                 for b in data.dmesg:
 914                         phase = data.dmesg[b]
 915                         left = "%.3f" % (((phase['start']-data.start)*100)/tTotal)
 916                         width = "%.3f" % (((phase['end']-phase['start'])*100)/tTotal)
 917                         devtl.html['timeline'] += html_phase.format(left, width, "%.3f"%devtl.scaleH, "%.3f"%(100-devtl.scaleH), data.dmesg[b]['color'], "")
 918
 919                 # draw the time scale, try to make the number of labels readable
 920                 devtl.html['scale'] = createTimeScale(t0, tMax, data.tSuspended)
 921                 devtl.html['timeline'] += devtl.html['scale']
 922                 for b in data.dmesg:
 923                         phaselist = data.dmesg[b]['list']
 924                         for d in phaselist:
 925                                 name = d
 926                                 if(d in data.altdevname):
 927                                         name = data.altdevname[d]
 928                                 dev = phaselist[d]
 929                                 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
 930                                 top = "%.3f" % ((dev['row']*height) + devtl.scaleH)
 931                                 left = "%.3f" % (((dev['start']-data.start)*100)/tTotal)
 932                                 width = "%.3f" % (((dev['end']-dev['start'])*100)/tTotal)
 933                                 len = " (%0.3f ms) " % ((dev['end']-dev['start'])*1000)
 934                                 color = "rgba(204,204,204,0.5)"
 935                                 devtl.html['timeline'] += html_device.format(dev['id'], name+len+b, left, top, "%.3f"%height, width, name)
 936
 937                 # timeline is finished
 938                 devtl.html['timeline'] += "</div>\n</div>\n"
 939
 940                 # draw a legend which describes the phases by color
 941                 devtl.html['legend'] = "<div class=\"legend\">\n"
 942                 pdelta = 100.0/data.phases.__len__()
 943                 pmargin = pdelta / 4.0
 944                 for phase in data.phases:
 945                         order = "%.2f" % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
 946                         name = string.replace(phase, "_", " &nbsp;")
 947                         devtl.html['legend'] += html_legend.format(order, data.dmesg[phase]['color'], name)
 948                 devtl.html['legend'] += "</div>\n"
 949
 950         hf = open(sysvals.htmlfile, 'w')
 951         thread_height = 0
 952
 953         # write the html header first (html head, css code, everything up to the start of body)
 954         html_header = "<!DOCTYPE html>\n<html>\n<head>\n\
 955         <meta http-equiv=\"content-type\" content=\"text/html; charset=UTF-8\">\n\
 956         <title>AnalyzeSuspend</title>\n\
 957         <style type='text/css'>\n\
 958                 body {overflow-y: scroll;}\n\
 959                 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
 960                 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
 961                 .callgraph article * {padding-left: 28px;}\n\
 962                 h1 {color:black;font: bold 30px Times;}\n\
 963                 table {width:100%;}\n\
 964                 .gray {background-color:rgba(80,80,80,0.1);}\n\
 965                 .green {background-color:rgba(204,255,204,0.4);}\n\
 966                 .purple {background-color:rgba(128,0,128,0.2);}\n\
 967                 .yellow {background-color:rgba(255,255,204,0.4);}\n\
 968                 .time1 {font: 22px Arial;border:1px solid;}\n\
 969                 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
 970                 td {text-align: center;}\n\
 971                 .tdhl {color: red;}\n\
 972                 .hide {display: none;}\n\
 973                 .pf {display: none;}\n\
 974                 .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\
 975                 .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\
 976                 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
 977                 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
 978                 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
 979                 .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\
 980                 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
 981                 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
 982                 .t {position: absolute; top: 0%; height: 100%; border-right:1px solid black;}\n\
 983                 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
 984                 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
 985                 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
 986         </style>\n</head>\n<body>\n"
 987         hf.write(html_header)
 988
 989         # write the test title and general info header
 990         if(data.stamp['time'] != ""):
 991                 hf.write(headline_stamp.format(data.stamp['host'],
 992                         data.stamp['kernel'], data.stamp['mode'], data.stamp['time']))
 993
 994         # write the dmesg data (device timeline)
 995         if(data.usedmesg):
 996                 hf.write(devtl.html['timeline'])
 997                 hf.write(devtl.html['legend'])
 998                 hf.write('<div id="devicedetail"></div>\n')
 999                 hf.write('<div id="devicetree"></div>\n')
1000
1001         # write the ftrace data (callgraph)
1002         if(data.useftrace):
1003                 hf.write('<section id="callgraphs" class="callgraph">\n')
1004                 # write out the ftrace data converted to html
1005                 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'
1006                 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
1007                 html_func_end = '</article>\n'
1008                 html_func_leaf = '<article>{0} {1}</article>\n'
1009                 num = 0
1010                 for p in data.phases:
1011                         list = data.dmesg[p]['list']
1012                         for devname in data.sortedDevices(p):
1013                                 if('ftrace' not in list[devname]):
1014                                         continue
1015                                 name = devname
1016                                 if(devname in data.altdevname):
1017                                         name = data.altdevname[devname]
1018                                 devid = list[devname]['id']
1019                                 cg = list[devname]['ftrace']
1020                                 flen = "(%.3f ms)" % ((cg.end - cg.start)*1000)
1021                                 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], num, name+" "+p, flen))
1022                                 num += 1
1023                                 for line in cg.list:
1024                                         if(line.length < 0.000000001):
1025                                                 flen = ""
1026                                         else:
1027                                                 flen = "(%.3f ms)" % (line.length*1000)
1028                                         if(line.freturn and line.fcall):
1029                                                 hf.write(html_func_leaf.format(line.name, flen))
1030                                         elif(line.freturn):
1031                                                 hf.write(html_func_end)
1032                                         else:
1033                                                 hf.write(html_func_start.format(num, line.name, flen))
1034                                                 num += 1
1035                                 hf.write(html_func_end)
1036                 hf.write("\n\n    </section>\n")
1037         # write the footer and close
1038         addScriptCode(hf)
1039         hf.write("</body>\n</html>\n")
1040         hf.close()
1041         return True
1042
1043 def addScriptCode(hf):
1044         global data
1045
1046         t0 = (data.start - data.tSuspended) * 1000
1047         tMax = (data.end - data.tSuspended) * 1000
1048         # create an array in javascript memory with the device details
1049         detail = '      var bounds = [%f,%f];\n' % (t0, tMax)
1050         detail += '     var d = [];\n'
1051         dfmt = '        d["%s"] = { n:"%s", p:"%s", c:[%s] };\n';
1052         for p in data.dmesg:
1053                 list = data.dmesg[p]['list']
1054                 for d in list:
1055                         parent = data.deviceParentID(d, p)
1056                         idlist = data.deviceChildrenIDs(d, p)
1057                         idstr = ""
1058                         for i in idlist:
1059                                 if(idstr == ""):
1060                                         idstr += '"'+i+'"'
1061                                 else:
1062                                         idstr += ', '+'"'+i+'"'
1063                         detail += dfmt % (list[d]['id'], d, parent, idstr)
1064
1065         # add the code which will manipulate the data in the browser
1066         script_code = \
1067         '<script type="text/javascript">\n'+detail+\
1068         '       var filter = [];\n'\
1069         '       var table = [];\n'\
1070         '       function deviceParent(devid) {\n'\
1071         '               var devlist = [];\n'\
1072         '               if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
1073         '               if(d[devid].p in d)\n'\
1074         '                       devlist = deviceParent(d[devid].p);\n'\
1075         '               else if(d[devid].p != "")\n'\
1076         '                       devlist = [d[devid].p];\n'\
1077         '               devlist[devlist.length] = d[devid].n;\n'\
1078         '               return devlist;\n'\
1079         '       }\n'\
1080         '       function deviceChildren(devid, column, row) {\n'\
1081         '               if(!(devid in d)) return;\n'\
1082         '               if(filter.indexOf(devid) < 0) filter[filter.length] = devid;\n'\
1083         '               var cell = {name: d[devid].n, span: 1};\n'\
1084         '               var span = 0;\n'\
1085         '               if(column >= table.length) table[column] = [];\n'\
1086         '               table[column][row] = cell;\n'\
1087         '               for(var i = 0; i < d[devid].c.length; i++) {\n'\
1088         '                       var cid = d[devid].c[i];\n'\
1089         '                       span += deviceChildren(cid, column+1, row+span);\n'\
1090         '               }\n'\
1091         '               if(span == 0) span = 1;\n'\
1092         '               table[column][row].span = span;\n'\
1093         '               return span;\n'\
1094         '       }\n'\
1095         '       function deviceTree(devid, resume) {\n'\
1096         '               var html = "<table border=1>";\n'\
1097         '               filter = [];\n'\
1098         '               table = [];\n'\
1099         '               plist = deviceParent(devid);\n'\
1100         '               var devidx = plist.length - 1;\n'\
1101         '               for(var i = 0; i < devidx; i++)\n'\
1102         '                       table[i] = [{name: plist[i], span: 1}];\n'\
1103         '               deviceChildren(devid, devidx, 0);\n'\
1104         '               for(var i = 0; i < devidx; i++)\n'\
1105         '                       table[i][0].span = table[devidx][0].span;\n'\
1106         '               for(var row = 0; row < table[0][0].span; row++) {\n'\
1107         '                       html += "<tr>";\n'\
1108         '                       for(var col = 0; col < table.length; col++)\n'\
1109         '                               if(row in table[col]) {\n'\
1110         '                                       var cell = table[col][row];\n'\
1111         '                                       var args = "";\n'\
1112         '                                       if(cell.span > 1)\n'\
1113         '                                               args += " rowspan="+cell.span;\n'\
1114         '                                       if((col == devidx) && (row == 0))\n'\
1115         '                                               args += " class=tdhl";\n'\
1116         '                                       if(resume)\n'\
1117         '                                               html += "<td"+args+">"+cell.name+" &rarr;</td>";\n'\
1118         '                                       else\n'\
1119         '                                               html += "<td"+args+">&larr; "+cell.name+"</td>";\n'\
1120         '                               }\n'\
1121         '                       html += "</tr>";\n'\
1122         '               }\n'\
1123         '               html += "</table>";\n'\
1124         '               return html;\n'\
1125         '       }\n'\
1126         '       function zoomTimeline() {\n'\
1127         '               var timescale = document.getElementById("timescale");\n'\
1128         '               var dmesg = document.getElementById("dmesg");\n'\
1129         '               var zoombox = document.getElementById("dmesgzoombox");\n'\
1130         '               var val = parseFloat(dmesg.style.width);\n'\
1131         '               var newval = 100;\n'\
1132         '               var sh = window.outerWidth / 2;\n'\
1133         '               if(this.id == "zoomin") {\n'\
1134         '                       newval = val * 1.2;\n'\
1135         '                       if(newval > 40000) newval = 40000;\n'\
1136         '                       dmesg.style.width = newval+"%";\n'\
1137         '                       zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
1138         '               } else if (this.id == "zoomout") {\n'\
1139         '                       newval = val / 1.2;\n'\
1140         '                       if(newval < 100) newval = 100;\n'\
1141         '                       dmesg.style.width = newval+"%";\n'\
1142         '                       zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
1143         '               } else {\n'\
1144         '                       zoombox.scrollLeft = 0;\n'\
1145         '                       dmesg.style.width = "100%";\n'\
1146         '               }\n'\
1147         '               var html = "";\n'\
1148         '               var t0 = bounds[0];\n'\
1149         '               var tMax = bounds[1];\n'\
1150         '               var tTotal = tMax - t0;\n'\
1151         '               var wTotal = tTotal * 100.0 / newval;\n'\
1152         '               for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\
1153         '               if(tS < 1) tS = 1;\n'\
1154         '               for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
1155         '                       var pos = (tMax - s) * 100.0 / tTotal;\n'\
1156         '                       var name = (s == 0)?"S/R":(s+"ms");\n'\
1157         '                       html += \"<div class=\\\"t\\\" style=\\\"right:\"+pos+\"%\\\">\"+name+\"</div>\";\n'\
1158         '               }\n'\
1159         '               timescale.innerHTML = html;\n'\
1160         '       }\n'\
1161         '       function deviceDetail() {\n'\
1162         '               var devtitle = document.getElementById("devicedetail");\n'\
1163         '               devtitle.innerHTML = "<h1>"+this.title+"</h1>";\n'\
1164         '               var devtree = document.getElementById("devicetree");\n'\
1165         '               devtree.innerHTML = deviceTree(this.id, (this.title.indexOf("resume") >= 0));\n'\
1166         '               var cglist = document.getElementById("callgraphs");\n'\
1167         '               if(!cglist) return;\n'\
1168         '               var cg = cglist.getElementsByClassName("atop");\n'\
1169         '               for (var i = 0; i < cg.length; i++) {\n'\
1170         '                       if(filter.indexOf(cg[i].id) >= 0) {\n'\
1171         '                               cg[i].style.display = "block";\n'\
1172         '                       } else {\n'\
1173         '                               cg[i].style.display = "none";\n'\
1174         '                       }\n'\
1175         '               }\n'\
1176         '       }\n'\
1177         '       window.addEventListener("load", function () {\n'\
1178         '               var dmesg = document.getElementById("dmesg");\n'\
1179         '               dmesg.style.width = "100%"\n'\
1180         '               document.getElementById("zoomin").onclick = zoomTimeline;\n'\
1181         '               document.getElementById("zoomout").onclick = zoomTimeline;\n'\
1182         '               document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
1183         '               var dev = dmesg.getElementsByClassName("thread");\n'\
1184         '               for (var i = 0; i < dev.length; i++) {\n'\
1185         '                       dev[i].onclick = deviceDetail;\n'\
1186         '               }\n'\
1187         '               zoomTimeline();\n'\
1188         '       });\n'\
1189         '</script>\n'
1190         hf.write(script_code);
1191
1192 # Function: executeSuspend
1193 # Description:
1194 #        Execute system suspend through the sysfs interface
1195 def executeSuspend():
1196         global sysvals, data
1197
1198         detectUSB()
1199         pf = open(sysvals.powerfile, 'w')
1200         # clear the kernel ring buffer just as we start
1201         os.system("dmesg -C")
1202         # start ftrace
1203         if(data.useftrace):
1204                 print("START TRACING")
1205                 os.system("echo 1 > "+sysvals.tpath+"tracing_on")
1206                 os.system("echo SUSPEND START > "+sysvals.tpath+"trace_marker")
1207         # initiate suspend
1208         if(sysvals.rtcwake):
1209                 print("SUSPEND START")
1210                 os.system("rtcwake -s 10 -m "+sysvals.suspendmode)
1211         else:
1212                 print("SUSPEND START (press a key to resume)")
1213                 pf.write(sysvals.suspendmode)
1214         # execution will pause here
1215         pf.close()
1216         # return from suspend
1217         print("RESUME COMPLETE")
1218         # stop ftrace
1219         if(data.useftrace):
1220                 os.system("echo RESUME COMPLETE > "+sysvals.tpath+"trace_marker")
1221                 os.system("echo 0 > "+sysvals.tpath+"tracing_on")
1222                 print("CAPTURING FTRACE")
1223                 os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.ftracefile)
1224                 os.system("cat "+sysvals.tpath+"trace >> "+sysvals.ftracefile)
1225         # grab a copy of the dmesg output
1226         print("CAPTURING DMESG")
1227         os.system("echo \""+sysvals.teststamp+"\" > "+sysvals.dmesgfile)
1228         os.system("dmesg -c >> "+sysvals.dmesgfile)
1229
1230 # Function: detectUSB
1231 # Description:
1232 #        Detect all the USB hosts and devices currently connected
1233 def detectUSB():
1234         global sysvals, data
1235
1236         for dirname, dirnames, filenames in os.walk("/sys/devices"):
1237                 if(re.match(r".*/usb[0-9]*.*", dirname) and
1238                         "idVendor" in filenames and "idProduct" in filenames):
1239                         vid = os.popen("cat %s/idVendor 2>/dev/null" % dirname).read().replace('\n', '')
1240                         pid = os.popen("cat %s/idProduct 2>/dev/null" % dirname).read().replace('\n', '')
1241                         product = os.popen("cat %s/product 2>/dev/null" % dirname).read().replace('\n', '')
1242                         name = dirname.split('/')[-1]
1243                         if(len(product) > 0):
1244                                 data.altdevname[name] = "%s [%s]" % (product, name)
1245                         else:
1246                                 data.altdevname[name] = "%s:%s [%s]" % (vid, pid, name)
1247
1248 def getModes():
1249         global sysvals
1250         modes = ""
1251         if(os.path.exists(sysvals.powerfile)):
1252                 fp = open(sysvals.powerfile, 'r')
1253                 modes = string.split(fp.read())
1254                 fp.close()
1255         return modes
1256
1257 # Function: statusCheck
1258 # Description:
1259 #        Verify that the requested command and options will work
1260 def statusCheck(dryrun):
1261         global sysvals, data
1262         res = dict()
1263
1264         if(data.notestrun):
1265                 print("SUCCESS: The command should run!")
1266                 return
1267
1268         # check we have root access
1269         check = "YES"
1270         if(os.environ['USER'] != "root"):
1271                 if(not dryrun):
1272                         doError("root access is required", False)
1273                 check = "NO"
1274         res["    have root access:     "] = check
1275
1276         # check sysfs is mounted
1277         check = "YES"
1278         if(not os.path.exists(sysvals.powerfile)):
1279                 if(not dryrun):
1280                         doError("sysfs must be mounted", False)
1281                 check = "NO"
1282         res["    is sysfs mounted:     "] = check
1283
1284         # check target mode is a valid mode
1285         check = "YES"
1286         modes = getModes()
1287         if(sysvals.suspendmode not in modes):
1288                 if(not dryrun):
1289                         doError("%s is not a value power mode" % sysvals.suspendmode, False)
1290                 check = "NO"
1291         res["    is "+sysvals.suspendmode+" a power mode: "] = check
1292
1293         # check if ftrace is available
1294         if(data.useftrace):
1295                 check = "YES"
1296                 if(not verifyFtrace()):
1297                         if(not dryrun):
1298                                 doError("ftrace is not configured", False)
1299                         check = "NO"
1300                 res["    is ftrace usable:     "] = check
1301
1302         # check if rtcwake
1303         if(sysvals.rtcwake):
1304                 check = "YES"
1305                 version = os.popen("rtcwake -V 2>/dev/null").read()
1306                 if(not version.startswith("rtcwake")):
1307                         if(not dryrun):
1308                                 doError("rtcwake is not installed", False)
1309                         check = "NO"
1310                 res["    is rtcwake usable:    "] = check
1311
1312         if(dryrun):
1313                 status = True
1314                 print("Checking if system can run the current command:")
1315                 for r in res:
1316                         print("%s\t%s" % (r, res[r]))
1317                         if(res[r] != "YES"):
1318                                 status = False
1319                 if(status):
1320                         print("SUCCESS: The command should run!")
1321                 else:
1322                         print("FAILURE: The command won't run!")
1323
1324 def printHelp():
1325         global sysvals
1326         modes = getModes()
1327
1328         print("")
1329         print("AnalyzeSuspend")
1330         print("Usage: sudo analyze_suspend.py <options>")
1331         print("")
1332         print("Description:")
1333         print("  Initiates a system suspend/resume while capturing dmesg")
1334         print("  and (optionally) ftrace data to analyze device timing")
1335         print("")
1336         print("  Generates output files in subdirectory: suspend-mmddyy-HHMMSS")
1337         print("   HTML output:                    <hostname>_<mode>.html")
1338         print("   raw dmesg output:               <hostname>_<mode>_dmesg.txt")
1339         print("   raw ftrace output (with -f):    <hostname>_<mode>_ftrace.txt")
1340         print("")
1341         print("Options:")
1342         print("  [general]")
1343         print("    -h        Print this help text")
1344         print("    -verbose  Print extra information during execution and analysis")
1345         print("    -status   Test to see if the system is enabled to run this tool")
1346         print("    -modes    List available suspend modes")
1347         print("    -m mode   Mode to initiate for suspend %s (default: %s)") % (modes, sysvals.suspendmode)
1348         print("    -rtcwake  Use rtcwake to autoresume after 10 seconds (default: disabled)")
1349         print("    -f        Use ftrace to create device callgraphs (default: disabled)")
1350         print("  [re-analyze data from previous runs]")
1351         print("    -dmesg dmesgfile      Create HTML timeline from dmesg file")
1352         print("    -ftrace ftracefile    Create HTML callgraph from ftrace file")
1353         print("")
1354         return True
1355
1356 def doError(msg, help):
1357         print("ERROR: %s") % msg
1358         if(help == True):
1359                 printHelp()
1360         sys.exit()
1361
1362 # -- script main --
1363 # loop through the command line arguments
1364 cmd = ""
1365 args = iter(sys.argv[1:])
1366 for arg in args:
1367         if(arg == "-m"):
1368                 try:
1369                         val = args.next()
1370                 except:
1371                         doError("No mode supplied", True)
1372                 sysvals.suspendmode = val
1373         elif(arg == "-f"):
1374                 data.useftrace = True
1375         elif(arg == "-modes"):
1376                 cmd = "modes"
1377         elif(arg == "-status"):
1378                 cmd = "status"
1379         elif(arg == "-verbose"):
1380                 data.verbose = True
1381         elif(arg == "-rtcwake"):
1382                 sysvals.rtcwake = True
1383         elif(arg == "-dmesg"):
1384                 try:
1385                         val = args.next()
1386                 except:
1387                         doError("No dmesg file supplied", True)
1388                 data.notestrun = True
1389                 data.usedmesg = True
1390                 sysvals.dmesgfile = val
1391         elif(arg == "-ftrace"):
1392                 try:
1393                         val = args.next()
1394                 except:
1395                         doError("No ftrace file supplied", True)
1396                 data.notestrun = True
1397                 data.useftrace = True
1398                 sysvals.ftracefile = val
1399         elif(arg == "-h"):
1400                 printHelp()
1401                 sys.exit()
1402         else:
1403                 doError("Invalid argument: "+arg, True)
1404
1405 # just run a utility command and exit
1406 if(cmd != ""):
1407         if(cmd == "status"):
1408                 statusCheck(True)
1409         elif(cmd == "modes"):
1410                 modes = getModes()
1411                 print modes
1412         sys.exit()
1413
1414 data.initialize()
1415
1416 # if instructed, re-analyze existing data files
1417 if(data.notestrun):
1418         sysvals.setOutputFile()
1419         data.vprint("Output file: %s" % sysvals.htmlfile)
1420         if(sysvals.dmesgfile != ""):
1421                 analyzeKernelLog()
1422         if(sysvals.ftracefile != ""):
1423                 analyzeTraceLog()
1424         createHTML()
1425         sys.exit()
1426
1427 # verify that we can run a test
1428 data.usedmesg = True
1429 statusCheck(False)
1430
1431 # prepare for the test
1432 if(data.useftrace):
1433         initFtrace()
1434 sysvals.initTestOutput()
1435
1436 data.vprint("Output files:\n    %s" % sysvals.dmesgfile)
1437 if(data.useftrace):
1438         data.vprint("    %s" % sysvals.ftracefile)
1439 data.vprint("    %s" % sysvals.htmlfile)
1440
1441 # execute the test
1442 executeSuspend()
1443 analyzeKernelLog()
1444 if(data.useftrace):
1445         analyzeTraceLog()
1446 createHTML()