scripts: analyze_suspend.py: Update to upstream v4.5
authorTodd E Brandt <todd.e.brandt@linux.intel.com>
Wed, 14 Dec 2016 18:37:07 +0000 (10:37 -0800)
committerRafael J. Wysocki <rafael.j.wysocki@intel.com>
Fri, 27 Jan 2017 10:25:36 +0000 (11:25 +0100)
- Kernel errors shown in timeline
- Tool log: The tool output log is now available in the html timeline
- Selective ftrace filter: can choose phase and test run (for x2)
- further instrumentation of dev mode to cover wifi

Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
scripts/analyze_suspend.py

index 0126859..383df79 100755 (executable)
 #         https://01.org/suspendresume
 #       Source repo
 #         https://github.com/01org/suspendresume
-#       Documentation
-#         Getting Started
-#           https://01.org/suspendresume/documentation/getting-started
-#         Command List:
-#           https://01.org/suspendresume/documentation/command-list
 #
 # Description:
 #       This tool is designed to assist kernel and OS developers in optimizing
@@ -77,11 +72,13 @@ from subprocess import call, Popen, PIPE
 #       store system values and test parameters
 class SystemValues:
        ansi = False
-       version = '4.4'
+       version = '4.5'
        verbose = False
        addlogs = False
-       mindevlen = 0.001
-       mincglen = 1.0
+       mindevlen = 0.0
+       mincglen = 0.0
+       cgphase = ''
+       cgtest = -1
        callloopmaxgap = 0.0001
        callloopmaxlen = 0.005
        srgap = 0
@@ -96,6 +93,7 @@ class SystemValues:
                'device_pm_callback_end',
                'device_pm_callback_start'
        ]
+       logmsg = ''
        testcommand = ''
        mempath = '/dev/mem'
        powerfile = '/sys/power/state'
@@ -166,18 +164,38 @@ class SystemValues:
        }
        dev_tracefuncs = {
                # general wait/delay/sleep
-               'msleep': { 'args_x86_64': {'time':'%di:s32'} },
-               'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'} },
-               'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'} },
-               'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} },
-               'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'} },
-               'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath' },
-               'acpi_os_stall': dict(),
+               'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
+               'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
+               'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
+               'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
+               'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
+               'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
+               'acpi_os_stall': {'ub': 1},
                # ACPI
                'acpi_resume_power_resources': dict(),
                'acpi_ps_parse_aml': dict(),
                # filesystem
                'ext4_sync_fs': dict(),
+               # 80211
+               'iwlagn_mac_start': dict(),
+               'iwlagn_alloc_bcast_station': dict(),
+               'iwl_trans_pcie_start_hw': dict(),
+               'iwl_trans_pcie_start_fw': dict(),
+               'iwl_run_init_ucode': dict(),
+               'iwl_load_ucode_wait_alive': dict(),
+               'iwl_alive_start': dict(),
+               'iwlagn_mac_stop': dict(),
+               'iwlagn_mac_suspend': dict(),
+               'iwlagn_mac_resume': dict(),
+               'iwlagn_mac_add_interface': dict(),
+               'iwlagn_mac_remove_interface': dict(),
+               'iwlagn_mac_change_interface': dict(),
+               'iwlagn_mac_config': dict(),
+               'iwlagn_configure_filter': dict(),
+               'iwlagn_mac_hw_scan': dict(),
+               'iwlagn_bss_info_changed': dict(),
+               'iwlagn_mac_channel_switch': dict(),
+               'iwlagn_mac_flush': dict(),
                # ATA
                'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
                # i915
@@ -196,14 +214,6 @@ class SystemValues:
                'intel_opregion_init': dict(),
                'intel_fbdev_set_suspend': dict(),
        }
-       kprobes_postresume = [
-               {
-                       'name': 'ataportrst',
-                       'func': 'ata_eh_recover',
-                       'args': {'port':'+36(%di):s32'},
-                       'format': 'ata{port}_port_reset'
-               }
-       ]
        kprobes = dict()
        timeformat = '%.3f'
        def __init__(self):
@@ -429,45 +439,65 @@ class SystemValues:
                if 'args' in kprobe:
                        args = kprobe['args']
                if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
-                       doError('Kprobe "%s" has format info in the function name "%s"' % (name, func), False)
+                       doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
                for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
                        if arg not in args:
-                               doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
+                               doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
                val = 'p:%s_cal %s' % (name, func)
                for i in sorted(args):
                        val += ' %s=%s' % (i, args[i])
                val += '\nr:%s_ret %s $retval\n' % (name, func)
                return val
-       def addKprobes(self):
+       def addKprobes(self, output=False):
+               if len(sysvals.kprobes) < 1:
+                       return
+               if output:
+                       print('    kprobe functions in this kernel:')
                # first test each kprobe
-               print('INITIALIZING KPROBES...')
                rejects = []
+               # sort kprobes: trace, ub-dev, custom, dev
+               kpl = [[], [], [], []]
                for name in sorted(self.kprobes):
+                       res = self.colorText('YES', 32)
                        if not self.testKprobe(name, self.kprobes[name]):
+                               res = self.colorText('NO')
                                rejects.append(name)
+                       else:
+                               if name in self.tracefuncs:
+                                       kpl[0].append(name)
+                               elif name in self.dev_tracefuncs:
+                                       if 'ub' in self.dev_tracefuncs[name]:
+                                               kpl[1].append(name)
+                                       else:
+                                               kpl[3].append(name)
+                               else:
+                                       kpl[2].append(name)
+                       if output:
+                               print('         %s: %s' % (name, res))
+               kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
                # remove all failed ones from the list
                for name in rejects:
-                       vprint('Skipping KPROBE: %s' % name)
                        self.kprobes.pop(name)
+               # set the kprobes all at once
                self.fsetVal('', 'kprobe_events')
                kprobeevents = ''
-               # set the kprobes all at once
-               for kp in self.kprobes:
-                       val = self.kprobeText(kp, self.kprobes[kp])
-                       vprint('Adding KPROBE: %s\n%s' % (kp, val.strip()))
+               for kp in kplist:
                        kprobeevents += self.kprobeText(kp, self.kprobes[kp])
                self.fsetVal(kprobeevents, 'kprobe_events')
                # verify that the kprobes were set as ordered
                check = self.fgetVal('kprobe_events')
-               linesout = len(kprobeevents.split('\n'))
-               linesack = len(check.split('\n'))
-               if linesack < linesout:
-                       # if not, try appending the kprobes 1 by 1
-                       for kp in self.kprobes:
-                               kprobeevents = self.kprobeText(kp, self.kprobes[kp])
-                               self.fsetVal(kprobeevents, 'kprobe_events', 'a')
+               linesout = len(kprobeevents.split('\n')) - 1
+               linesack = len(check.split('\n')) - 1
+               if output:
+                       res = '%d/%d' % (linesack, linesout)
+                       if linesack < linesout:
+                               res = self.colorText(res, 31)
+                       else:
+                               res = self.colorText(res, 32)
+                       print('    working kprobe functions enabled: %s' % res)
                self.fsetVal('1', 'events/kprobes/enable')
        def testKprobe(self, kname, kprobe):
+               self.fsetVal('0', 'events/kprobes/enable')
                kprobeevents = self.kprobeText(kname, kprobe)
                if not kprobeevents:
                        return False
@@ -486,8 +516,9 @@ class SystemValues:
                if not os.path.exists(file):
                        return False
                try:
-                       fp = open(file, mode)
+                       fp = open(file, mode, 0)
                        fp.write(val)
+                       fp.flush()
                        fp.close()
                except:
                        pass
@@ -525,7 +556,6 @@ class SystemValues:
                                return True
                return False
        def initFtrace(self, testing=False):
-               tp = self.tpath
                print('INITIALIZING FTRACE...')
                # turn trace off
                self.fsetVal('0', 'tracing_on')
@@ -570,7 +600,8 @@ class SystemValues:
                        if self.usedevsrc:
                                for name in self.dev_tracefuncs:
                                        self.defaultKprobe(name, self.dev_tracefuncs[name])
-                       self.addKprobes()
+                       print('INITIALIZING KPROBES...')
+                       self.addKprobes(self.verbose)
                if(self.usetraceevents):
                        # turn trace events on
                        events = iter(self.traceevents)
@@ -602,10 +633,10 @@ class SystemValues:
                        if(os.path.exists(tp+f) == False):
                                return False
                return True
-       def colorText(self, str):
+       def colorText(self, str, color=31):
                if not self.ansi:
                        return str
-               return '\x1B[31;40m'+str+'\x1B[m'
+               return '\x1B[%d;40m%s\x1B[m' % (color, str)
 
 sysvals = SystemValues()
 
@@ -658,8 +689,6 @@ class DeviceNode:
 #       The primary container for suspend/resume test data. There is one for
 #       each test run. The data is organized into a cronological hierarchy:
 #       Data.dmesg {
-#              root structure, started as dmesg & ftrace, but now only ftrace
-#              contents: times for suspend start/end, resume start/end, fwdata
 #              phases {
 #                      10 sequential, non-overlapping phases of S/R
 #                      contents: times for phase start/end, order/color data for html
@@ -670,7 +699,7 @@ class DeviceNode:
 #                                      contents: start/stop times, pid/cpu/driver info
 #                                              parents/children, html id for timeline/callgraph
 #                                              optionally includes an ftrace callgraph
-#                                              optionally includes intradev trace events
+#                                              optionally includes dev/ps data
 #                              }
 #                      }
 #              }
@@ -697,16 +726,9 @@ class Data:
        stamp = 0
        outfile = ''
        devpids = []
-       dev_ubiquitous = [
-               'msleep',
-               'schedule_timeout_uninterruptible',
-               'schedule_timeout',
-               'udelay',
-               'usleep_range',
-               'mutex_lock_slowpath'
-       ]
+       kerror = False
        def __init__(self, num):
-               idchar = 'abcdefghijklmnopqrstuvwxyz'
+               idchar = 'abcdefghij'
                self.pstl = dict()
                self.testnumber = num
                self.idstr = idchar[num]
@@ -738,6 +760,35 @@ class Data:
                self.devicegroups = []
                for phase in self.phases:
                        self.devicegroups.append([phase])
+               self.errorinfo = {'suspend':[],'resume':[]}
+       def extractErrorInfo(self, dmesg):
+               error = ''
+               tm = 0.0
+               for i in range(len(dmesg)):
+                       if 'Call Trace:' in dmesg[i]:
+                               m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i])
+                               if not m:
+                                       continue
+                               tm = float(m.group('ktime'))
+                               if tm < self.start or tm > self.end:
+                                       continue
+                               for j in range(i-10, i+1):
+                                       error += dmesg[j]
+                               continue
+                       if error:
+                               m = re.match('[ \t]*\[ *[0-9\.]*\]  \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
+                               if m:
+                                       error += dmesg[i]
+                               else:
+                                       if tm < self.tSuspended:
+                                               dir = 'suspend'
+                                       else:
+                                               dir = 'resume'
+                                       error = error.replace('<', '&lt').replace('>', '&gt')
+                                       vprint('kernel error found in %s at %f' % (dir, tm))
+                                       self.errorinfo[dir].append((tm, error))
+                                       self.kerror = True
+                                       error = ''
        def setStart(self, time):
                self.start = time
        def setEnd(self, time):
@@ -751,9 +802,8 @@ class Data:
                                        time < d['end']):
                                        return False
                return True
-       def sourcePhase(self, start, end):
+       def sourcePhase(self, start):
                for phase in self.phases:
-                       pstart = self.dmesg[phase]['start']
                        pend = self.dmesg[phase]['end']
                        if start <= pend:
                                return phase
@@ -798,7 +848,7 @@ class Data:
                                threadname = 'kthread-%d' % (pid)
                        else:
                                threadname = '%s-%d' % (proc, pid)
-                       tgtphase = self.sourcePhase(start, end)
+                       tgtphase = self.sourcePhase(start)
                        self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
                        return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
                # this should not happen
@@ -809,8 +859,9 @@ class Data:
                # place the call data inside the src element of the tgtdev
                if('src' not in tgtdev):
                        tgtdev['src'] = []
+               dtf = sysvals.dev_tracefuncs
                ubiquitous = False
-               if kprobename in self.dev_ubiquitous:
+               if kprobename in dtf and 'ub' in dtf[kprobename]:
                        ubiquitous = True
                title = cdata+' '+rdata
                mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
@@ -823,7 +874,7 @@ class Data:
                                r = ''
                        else:
                                r = 'ret=%s ' % r
-                       if ubiquitous and c in self.dev_ubiquitous:
+                       if ubiquitous and c in dtf and 'ub' in dtf[c]:
                                return False
                color = sysvals.kprobeColor(kprobename)
                e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
@@ -917,6 +968,8 @@ class Data:
                self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
                self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
                self.start = self.trimTimeVal(self.start, t0, dT, left)
+               self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
+               self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
                self.end = self.trimTimeVal(self.end, t0, dT, left)
                for phase in self.phases:
                        p = self.dmesg[phase]
@@ -964,7 +1017,7 @@ class Data:
                for t in sorted(tmp):
                        slist.append(tmp[t])
                return slist
-       def fixupInitcalls(self, phase, end):
+       def fixupInitcalls(self, phase):
                # if any calls never returned, clip them at system resume end
                phaselist = self.dmesg[phase]['list']
                for devname in phaselist:
@@ -976,8 +1029,6 @@ class Data:
                                                break
                                vprint('%s (%s): callback didnt return' % (devname, phase))
        def deviceFilter(self, devicefilter):
-               # check each device name & driver name
-               # remove it if it does not include one of the filter strings
                for phase in self.phases:
                        list = self.dmesg[phase]['list']
                        rmlist = []
@@ -994,7 +1045,7 @@ class Data:
        def fixupInitcallsThatDidntReturn(self):
                # if any calls never returned, clip them at system resume end
                for phase in self.phases:
-                       self.fixupInitcalls(phase, self.end)
+                       self.fixupInitcalls(phase)
        def phaseOverlap(self, phases):
                rmgroups = []
                newgroup = []
@@ -1068,22 +1119,6 @@ class Data:
                if color:
                        list[name]['color'] = color
                return name
-       def deviceIDs(self, devlist, phase):
-               idlist = []
-               list = self.dmesg[phase]['list']
-               for devname in list:
-                       if devname in devlist:
-                               idlist.append(list[devname]['id'])
-               return idlist
-       def deviceParentID(self, devname, phase):
-               pdev = ''
-               pdevid = ''
-               list = self.dmesg[phase]['list']
-               if devname in list:
-                       pdev = list[devname]['par']
-               if pdev in list:
-                       return list[pdev]['id']
-               return pdev
        def deviceChildren(self, devname, phase):
                devlist = []
                list = self.dmesg[phase]['list']
@@ -1091,15 +1126,6 @@ class Data:
                        if(list[child]['par'] == devname):
                                devlist.append(child)
                return devlist
-       def deviceDescendants(self, devname, phase):
-               children = self.deviceChildren(devname, phase)
-               family = children
-               for child in children:
-                       family += self.deviceDescendants(child, phase)
-               return family
-       def deviceChildrenIDs(self, devname, phase):
-               devlist = self.deviceChildren(devname, phase)
-               return self.deviceIDs(devlist, phase)
        def printDetails(self):
                vprint('Timeline Details:')
                vprint('          test start: %f' % self.start)
@@ -1418,7 +1444,6 @@ class FTraceLine:
                        print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
                                self.depth, self.name, self.length*1000000))
        def startMarker(self):
-               global sysvals
                # Is this the starting line of a suspend?
                if not self.fevent:
                        return False
@@ -1721,8 +1746,9 @@ class Timeline:
        rows = 0        # total timeline rows
        rowlines = dict()
        rowheight = dict()
-       def __init__(self, rowheight):
+       def __init__(self, rowheight, scaleheight):
                self.rowH = rowheight
+               self.scaleH = scaleheight
                self.html = {
                        'header': '',
                        'timeline': '',
@@ -1921,7 +1947,6 @@ class Timeline:
 #       A list of values describing the properties of these test runs
 class TestProps:
        stamp = ''
-       tracertype = ''
        S0i3 = False
        fwdata = []
        ftrace_line_fmt_fg = \
@@ -1939,14 +1964,13 @@ class TestProps:
        def __init__(self):
                self.ktemp = dict()
        def setTracerType(self, tracer):
-               self.tracertype = tracer
                if(tracer == 'function_graph'):
                        self.cgformat = True
                        self.ftrace_line_fmt = self.ftrace_line_fmt_fg
                elif(tracer == 'nop'):
                        self.ftrace_line_fmt = self.ftrace_line_fmt_nop
                else:
-                       doError('Invalid tracer format: [%s]' % tracer, False)
+                       doError('Invalid tracer format: [%s]' % tracer)
 
 # Class: TestRun
 # Description:
@@ -1995,7 +2019,6 @@ class ProcessMonitor:
                        out += '%s-%s %d' % (val['name'], pid, jiffies)
                return 'ps - '+out
        def processMonitor(self, tid):
-               global sysvals
                while self.running:
                        out = self.procstat()
                        if out:
@@ -2015,7 +2038,7 @@ class ProcessMonitor:
 # Arguments:
 #       msg: the debug/log message to print
 def vprint(msg):
-       global sysvals
+       sysvals.logmsg += msg+'\n'
        if(sysvals.verbose):
                print(msg)
 
@@ -2026,8 +2049,6 @@ def vprint(msg):
 # Arguments:
 #       m: the valid re.match output for the stamp line
 def parseStamp(line, data):
-       global sysvals
-
        m = re.match(sysvals.stampfmt, line)
        data.stamp = {'time': '', 'host': '', 'mode': ''}
        dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
@@ -2076,8 +2097,6 @@ def diffStamp(stamp1, stamp2):
 #       required for primary parsing. Set the usetraceevents and/or
 #       usetraceeventsonly flags in the global sysvals object
 def doesTraceLogHaveTraceEvents():
-       global sysvals
-
        # check for kprobes
        sysvals.usekprobes = False
        out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True)
@@ -2120,8 +2139,6 @@ def doesTraceLogHaveTraceEvents():
 # Arguments:
 #       testruns: the array of Data objects obtained from parseKernelLog
 def appendIncompleteTraceLog(testruns):
-       global sysvals
-
        # create TestRun vessels for ftrace parsing
        testcnt = len(testruns)
        testidx = 0
@@ -2312,8 +2329,7 @@ def appendIncompleteTraceLog(testruns):
                                                                dev['ftrace'] = cg
                                                break
 
-               if(sysvals.verbose):
-                       test.data.printDetails()
+               test.data.printDetails()
 
 # Function: parseTraceLog
 # Description:
@@ -2324,11 +2340,9 @@ def appendIncompleteTraceLog(testruns):
 # Output:
 #       An array of Data objects
 def parseTraceLog():
-       global sysvals
-
        vprint('Analyzing the ftrace data...')
        if(os.path.exists(sysvals.ftracefile) == False):
-               doError('%s does not exist' % sysvals.ftracefile, False)
+               doError('%s does not exist' % sysvals.ftracefile)
 
        sysvals.setupAllKprobes()
        tracewatch = []
@@ -2398,10 +2412,6 @@ def parseTraceLog():
                        testrun = TestRun(data)
                        testruns.append(testrun)
                        parseStamp(tp.stamp, data)
-                       if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
-                               data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
-                               if(data.fwSuspend > 0 or data.fwResume > 0):
-                                       data.fwValid = True
                        data.setStart(t.time)
                        data.tKernSus = t.time
                        continue
@@ -2427,6 +2437,11 @@ def parseTraceLog():
                                data.tKernRes = t.time
                        if data.dmesg['resume_complete']['end'] < 0:
                                data.dmesg['resume_complete']['end'] = t.time
+                       if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
+                               data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
+                               if(data.tSuspended != 0 and data.tResumed != 0 and \
+                                       (data.fwSuspend > 0 or data.fwResume > 0)):
+                                       data.fwValid = True
                        if(not sysvals.usetracemarkers):
                                # no trace markers? then quit and be sure to finish recording
                                # the event we used to trigger resume end
@@ -2713,9 +2728,8 @@ def parseTraceLog():
                                        cg.newActionFromFunction(data)
 
        if sysvals.suspendmode == 'command':
-               if(sysvals.verbose):
-                       for data in testdata:
-                               data.printDetails()
+               for data in testdata:
+                       data.printDetails()
                return testdata
 
        # fill in any missing phases
@@ -2723,7 +2737,7 @@ def parseTraceLog():
                lp = data.phases[0]
                for p in data.phases:
                        if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
-                               print('WARNING: phase "%s" is missing!' % p)
+                               vprint('WARNING: phase "%s" is missing!' % p)
                        if(data.dmesg[p]['start'] < 0):
                                data.dmesg[p]['start'] = data.dmesg[lp]['end']
                                if(p == 'resume_machine'):
@@ -2732,6 +2746,8 @@ def parseTraceLog():
                                        data.tLow = 0
                        if(data.dmesg[p]['end'] < 0):
                                data.dmesg[p]['end'] = data.dmesg[p]['start']
+                       if(p != lp and not ('machine' in p and 'machine' in lp)):
+                               data.dmesg[lp]['end'] = data.dmesg[p]['start']
                        lp = p
 
                if(len(sysvals.devicefilter) > 0):
@@ -2739,8 +2755,7 @@ def parseTraceLog():
                data.fixupInitcallsThatDidntReturn()
                if sysvals.usedevsrc:
                        data.optimizeDevSrc()
-               if sysvals.verbose:
-                       data.printDetails()
+               data.printDetails()
 
        # x2: merge any overlapping devices between test runs
        if sysvals.usedevsrc and len(testdata) > 1:
@@ -2752,50 +2767,6 @@ def parseTraceLog():
                testdata[0].stitchTouchingThreads(testdata[1:])
        return testdata
 
-# Function: loadRawKernelLog
-# Description:
-#       Load a raw kernel log that wasn't created by this tool, it might be
-#       possible to extract a valid suspend/resume log
-def loadRawKernelLog(dmesgfile):
-       global sysvals
-
-       stamp = {'time': '', 'host': '', 'mode': 'mem', 'kernel': ''}
-       stamp['time'] = datetime.now().strftime('%B %d %Y, %I:%M:%S %p')
-       stamp['host'] = sysvals.hostname
-
-       testruns = []
-       data = 0
-       lf = open(dmesgfile, 'r')
-       for line in lf:
-               line = line.replace('\r\n', '')
-               idx = line.find('[')
-               if idx > 1:
-                       line = line[idx:]
-               m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
-               if(not m):
-                       continue
-               msg = m.group("msg")
-               m = re.match('PM: Syncing filesystems.*', msg)
-               if(m):
-                       if(data):
-                               testruns.append(data)
-                       data = Data(len(testruns))
-                       data.stamp = stamp
-               if(data):
-                       m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
-                       if(m):
-                               stamp['kernel'] = m.group('k')
-                       m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
-                       if(m):
-                               stamp['mode'] = m.group('m')
-                       data.dmesgtext.append(line)
-       if(data):
-               testruns.append(data)
-               sysvals.stamp = stamp
-               sysvals.suspendmode = stamp['mode']
-       lf.close()
-       return testruns
-
 # Function: loadKernelLog
 # Description:
 #       [deprecated for kernel 3.15.0 or newer]
@@ -2803,15 +2774,16 @@ def loadRawKernelLog(dmesgfile):
 #       The dmesg filename is taken from sysvals
 # Output:
 #       An array of empty Data objects with only their dmesgtext attributes set
-def loadKernelLog():
-       global sysvals
-
+def loadKernelLog(justtext=False):
        vprint('Analyzing the dmesg data...')
        if(os.path.exists(sysvals.dmesgfile) == False):
-               doError('%s does not exist' % sysvals.dmesgfile, False)
+               doError('%s does not exist' % sysvals.dmesgfile)
 
+       if justtext:
+               dmesgtext = []
        # there can be multiple test runs in a single file
        tp = TestProps()
+       tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
        testruns = []
        data = 0
        lf = open(sysvals.dmesgfile, 'r')
@@ -2832,6 +2804,9 @@ def loadKernelLog():
                if(not m):
                        continue
                msg = m.group("msg")
+               if justtext:
+                       dmesgtext.append(line)
+                       continue
                if(re.match('PM: Syncing filesystems.*', msg)):
                        if(data):
                                testruns.append(data)
@@ -2841,24 +2816,24 @@ def loadKernelLog():
                                data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
                                if(data.fwSuspend > 0 or data.fwResume > 0):
                                        data.fwValid = True
-               if(re.match('ACPI: resume from mwait', msg)):
-                       print('NOTE: This suspend appears to be freeze rather than'+\
-                               ' %s, it will be treated as such' % sysvals.suspendmode)
-                       sysvals.suspendmode = 'freeze'
                if(not data):
                        continue
+               m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
+               if(m):
+                       sysvals.stamp['kernel'] = m.group('k')
+               m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
+               if(m):
+                       sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')
                data.dmesgtext.append(line)
-       if(data):
-               testruns.append(data)
        lf.close()
 
-       if(len(testruns) < 1):
-               # bad log, but see if you can extract something meaningful anyway
-               testruns = loadRawKernelLog(sysvals.dmesgfile)
-
-       if(len(testruns) < 1):
-               doError(' dmesg log is completely unreadable: %s' \
-                       % sysvals.dmesgfile, False)
+       if justtext:
+               return dmesgtext
+       if data:
+               testruns.append(data)
+       if len(testruns) < 1:
+               doError(' dmesg log has no suspend/resume data: %s' \
+                       % sysvals.dmesgfile)
 
        # fix lines with same timestamp/function with the call and return swapped
        for data in testruns:
@@ -2890,8 +2865,6 @@ def loadKernelLog():
 # Output:
 #       The filled Data object
 def parseKernelLog(data):
-       global sysvals
-
        phase = 'suspend_runtime'
 
        if(data.fwValid):
@@ -2949,7 +2922,6 @@ def parseKernelLog(data):
        prevktime = -1.0
        actions = dict()
        for line in data.dmesgtext:
-               # -- preprocessing --
                # parse each dmesg line into the time and message
                m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
                if(m):
@@ -2957,8 +2929,6 @@ def parseKernelLog(data):
                        try:
                                ktime = float(val)
                        except:
-                               doWarning('INVALID DMESG LINE: '+\
-                                       line.replace('\n', ''), 'dmesg')
                                continue
                        msg = m.group('msg')
                        # initialize data start to first line time
@@ -2976,12 +2946,12 @@ def parseKernelLog(data):
                        phase = 'resume_noirq'
                        data.dmesg[phase]['start'] = ktime
 
-               # -- phase changes --
                # suspend start
                if(re.match(dm['suspend_prepare'], msg)):
                        phase = 'suspend_prepare'
                        data.dmesg[phase]['start'] = ktime
                        data.setStart(ktime)
+                       data.tKernSus = ktime
                # suspend start
                elif(re.match(dm['suspend'], msg)):
                        data.dmesg['suspend_prepare']['end'] = ktime
@@ -3038,7 +3008,7 @@ def parseKernelLog(data):
                elif(re.match(dm['post_resume'], msg)):
                        data.dmesg['resume_complete']['end'] = ktime
                        data.setEnd(ktime)
-                       phase = 'post_resume'
+                       data.tKernRes = ktime
                        break
 
                # -- device callbacks --
@@ -3065,7 +3035,6 @@ def parseKernelLog(data):
                                        dev['length'] = int(t)
                                        dev['end'] = ktime
 
-               # -- non-devicecallback actions --
                # if trace events are not available, these are better than nothing
                if(not sysvals.usetraceevents):
                        # look for known actions
@@ -3125,8 +3094,7 @@ def parseKernelLog(data):
                for event in actions[name]:
                        data.newActionGlobal(name, event['begin'], event['end'])
 
-       if(sysvals.verbose):
-               data.printDetails()
+       data.printDetails()
        if(len(sysvals.devicefilter) > 0):
                data.deviceFilter(sysvals.devicefilter)
        data.fixupInitcallsThatDidntReturn()
@@ -3138,8 +3106,6 @@ def parseKernelLog(data):
 # Arguments:
 #       testruns: array of Data objects from parseTraceLog
 def createHTMLSummarySimple(testruns, htmlfile):
-       global sysvals
-
        # print out the basic summary of all the tests
        hf = open(htmlfile, 'w')
 
@@ -3264,7 +3230,6 @@ def createHTMLSummarySimple(testruns, htmlfile):
        hf.close()
 
 def htmlTitle():
-       global sysvals
        modename = {
                'freeze': 'Freeze (S0)',
                'standby': 'Standby (S1)',
@@ -3297,13 +3262,14 @@ def ordinal(value):
 # Output:
 #       True if the html file was created, false if it failed
 def createHTML(testruns):
-       global sysvals
-
        if len(testruns) < 1:
                print('ERROR: Not enough test data to build a timeline')
                return
 
+       kerror = False
        for data in testruns:
+               if data.kerror:
+                       kerror = True
                data.normalizeTime(testruns[-1].tSuspended)
 
        x2changes = ['', 'absolute']
@@ -3318,6 +3284,7 @@ def createHTML(testruns):
        html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
        html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
        html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
+       html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR&rarr;</div>\n'
        html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n'
        html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
        html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
@@ -3347,11 +3314,16 @@ def createHTML(testruns):
        hoverZ = 'z-index:8;'
        if sysvals.usedevsrc:
                hoverZ = ''
+       scaleH = 20
+       scaleTH = 20
+       if kerror:
+               scaleH = 40
+               scaleTH = 60
 
        # device timeline
        vprint('Creating Device Timeline...')
 
-       devtl = Timeline(30)
+       devtl = Timeline(30, scaleH)
 
        # Generate the header for this timeline
        for data in testruns:
@@ -3415,7 +3387,6 @@ def createHTML(testruns):
        # time scale for potentially multiple datasets
        t0 = testruns[0].start
        tMax = testruns[-1].end
-       tSuspended = testruns[-1].tSuspended
        tTotal = tMax - t0
 
        # determine the maximum number of rows we need to draw
@@ -3507,6 +3478,11 @@ def createHTML(testruns):
                                devtl.html['timeline'] += html_phase.format(left, width, \
                                        '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
                                        data.dmesg[b]['color'], '')
+                       for e in data.errorinfo[dir]:
+                               # draw red lines for any kernel errors found
+                               t, err = e
+                               right = '%f' % (((mMax-t)*100.0)/mTotal)
+                               devtl.html['timeline'] += html_error.format(right, err)
                        for b in sorted(phases[dir]):
                                # draw the devices for this phase
                                phaselist = data.dmesg[b]['list']
@@ -3623,8 +3599,7 @@ def createHTML(testruns):
                t2 {color:black;font:25px Times;}\n\
                t3 {color:black;font:20px Times;white-space:nowrap;}\n\
                t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
-               cS {color:blue;font:bold 11px Times;}\n\
-               cR {color:red;font:bold 11px Times;}\n\
+               cS {font:bold 13px Times;}\n\
                table {width:100%;}\n\
                .gray {background-color:rgba(80,80,80,0.1);}\n\
                .green {background-color:rgba(204,255,204,0.4);}\n\
@@ -3655,7 +3630,8 @@ def createHTML(testruns):
                .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\
                .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
                .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
-               .t {position:absolute;pointer-events:none;top:0%;height:100%;border-right:1px solid black;z-index:6;}\n\
+               .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\
+               .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\
                .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
                .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
                button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
@@ -3683,6 +3659,8 @@ def createHTML(testruns):
        # write the test title and general info header
        if(sysvals.stamp['time'] != ""):
                hf.write(headline_version)
+               if sysvals.logmsg:
+                       hf.write('<button id="showtest" class="logbtn">log</button>')
                if sysvals.addlogs and sysvals.dmesgfile:
                        hf.write('<button id="showdmesg" class="logbtn">dmesg</button>')
                if sysvals.addlogs and sysvals.ftracefile:
@@ -3718,7 +3696,10 @@ def createHTML(testruns):
        hf.write('</div>\n')
 
        # write the ftrace data (callgraph)
-       data = testruns[-1]
+       if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
+               data = testruns[sysvals.cgtest]
+       else:
+               data = testruns[-1]
        if(sysvals.usecallgraph and not sysvals.embedded):
                hf.write('<section id="callgraphs" class="callgraph">\n')
                # write out the ftrace data converted to html
@@ -3728,6 +3709,8 @@ def createHTML(testruns):
                html_func_leaf = '<article>{0} {1}</article>\n'
                num = 0
                for p in data.phases:
+                       if sysvals.cgphase and p != sysvals.cgphase:
+                               continue
                        list = data.dmesg[p]['list']
                        for devname in data.sortedDevices(p):
                                if('ftrace' not in list[devname]):
@@ -3765,11 +3748,15 @@ def createHTML(testruns):
                                hf.write(html_func_end)
                hf.write('\n\n    </section>\n')
 
+       # add the test log as a hidden div
+       if sysvals.logmsg:
+               hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
        # add the dmesg log as a hidden div
        if sysvals.addlogs and sysvals.dmesgfile:
                hf.write('<div id="dmesglog" style="display:none;">\n')
                lf = open(sysvals.dmesgfile, 'r')
                for line in lf:
+                       line = line.replace('<', '&lt').replace('>', '&gt')
                        hf.write(line)
                lf.close()
                hf.write('</div>\n')
@@ -3822,7 +3809,7 @@ def addScriptCode(hf, testruns):
        '       var resolution = -1;\n'\
        '       var dragval = [0, 0];\n'\
        '       function redrawTimescale(t0, tMax, tS) {\n'\
-       '               var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cR><-R</cR></div>\';\n'\
+       '               var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cS>&larr;R</cS></div>\';\n'\
        '               var tTotal = tMax - t0;\n'\
        '               var list = document.getElementsByClassName("tblock");\n'\
        '               for (var i = 0; i < list.length; i++) {\n'\
@@ -3847,7 +3834,7 @@ def addScriptCode(hf, testruns):
        '                                       pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
        '                                       val = (j-divTotal+1)*tS;\n'\
        '                                       if(j == divTotal - 1)\n'\
-       '                                               htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S-></cS></div>\';\n'\
+       '                                               htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S&rarr;</cS></div>\';\n'\
        '                                       else\n'\
        '                                               htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
        '                               }\n'\
@@ -4027,12 +4014,7 @@ def addScriptCode(hf, testruns):
        '               }\n'\
        '       }\n'\
        '       function devListWindow(e) {\n'\
-       '               var sx = e.clientX;\n'\
-       '               if(sx > window.innerWidth - 440)\n'\
-       '                       sx = window.innerWidth - 440;\n'\
-       '               var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\
-       '               var win = window.open("", "_blank", cfg);\n'\
-       '               if(window.chrome) win.moveBy(sx, 0);\n'\
+       '               var win = window.open();\n'\
        '               var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
        '                       "<style type=\\"text/css\\">"+\n'\
        '                       "   ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
@@ -4042,6 +4024,12 @@ def addScriptCode(hf, testruns):
        '                       dt = devtable[1];\n'\
        '               win.document.write(html+dt);\n'\
        '       }\n'\
+       '       function errWindow() {\n'\
+       '               var text = this.id;\n'\
+       '               var win = window.open();\n'\
+       '               win.document.write("<pre>"+text+"</pre>");\n'\
+       '               win.document.close();\n'\
+       '       }\n'\
        '       function logWindow(e) {\n'\
        '               var name = e.target.id.slice(4);\n'\
        '               var win = window.open();\n'\
@@ -4089,6 +4077,9 @@ def addScriptCode(hf, testruns):
        '               var list = document.getElementsByClassName("square");\n'\
        '               for (var i = 0; i < list.length; i++)\n'\
        '                       list[i].onclick = onClickPhase;\n'\
+       '               var list = document.getElementsByClassName("err");\n'\
+       '               for (var i = 0; i < list.length; i++)\n'\
+       '                       list[i].onclick = errWindow;\n'\
        '               var list = document.getElementsByClassName("logbtn");\n'\
        '               for (var i = 0; i < list.length; i++)\n'\
        '                       list[i].onclick = logWindow;\n'\
@@ -4111,8 +4102,6 @@ def addScriptCode(hf, testruns):
 #       Execute system suspend through the sysfs interface, then copy the output
 #       dmesg and ftrace files to the test output directory.
 def executeSuspend():
-       global sysvals
-
        pm = ProcessMonitor()
        tp = sysvals.tpath
        fwdata = []
@@ -4128,7 +4117,9 @@ def executeSuspend():
        for count in range(1,sysvals.execcount+1):
                # x2delay in between test runs
                if(count > 1 and sysvals.x2delay > 0):
+                       sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
                        time.sleep(sysvals.x2delay/1000.0)
+                       sysvals.fsetVal('WAIT END', 'trace_marker')
                # start message
                if sysvals.testcommand != '':
                        print('COMMAND START')
@@ -4146,7 +4137,9 @@ def executeSuspend():
                        sysvals.fsetVal('SUSPEND START', 'trace_marker')
                # predelay delay
                if(count == 1 and sysvals.predelay > 0):
+                       sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
                        time.sleep(sysvals.predelay/1000.0)
+                       sysvals.fsetVal('WAIT END', 'trace_marker')
                # initiate suspend or command
                if sysvals.testcommand != '':
                        call(sysvals.testcommand+' 2>&1', shell=True);
@@ -4162,7 +4155,9 @@ def executeSuspend():
                        sysvals.rtcWakeAlarmOff()
                # postdelay delay
                if(count == sysvals.execcount and sysvals.postdelay > 0):
+                       sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
                        time.sleep(sysvals.postdelay/1000.0)
+                       sysvals.fsetVal('WAIT END', 'trace_marker')
                # return from suspend
                print('RESUME COMPLETE')
                if(sysvals.usecallgraph or sysvals.usetraceevents):
@@ -4185,8 +4180,6 @@ def executeSuspend():
        sysvals.getdmesg()
 
 def writeDatafileHeader(filename, fwdata):
-       global sysvals
-
        fp = open(filename, 'a')
        fp.write(sysvals.teststamp+'\n')
        if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
@@ -4202,8 +4195,6 @@ def writeDatafileHeader(filename, fwdata):
 #       to always-on since the kernel cant determine if the device can
 #       properly autosuspend
 def setUSBDevicesAuto():
-       global sysvals
-
        rootCheck(True)
        for dirname, dirnames, filenames in os.walk('/sys/devices'):
                if(re.match('.*/usb[0-9]*.*', dirname) and
@@ -4250,8 +4241,6 @@ def ms2nice(val):
 #       Detect all the USB hosts and devices currently connected and add
 #       a list of USB device names to sysvals for better timeline readability
 def detectUSB():
-       global sysvals
-
        field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
        power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
                         'control':'', 'persist':'', 'runtime_enabled':'',
@@ -4306,7 +4295,6 @@ def detectUSB():
 # Description:
 #       Retrieve a list of properties for all devices in the trace log
 def devProps(data=0):
-       global sysvals
        props = dict()
 
        if data:
@@ -4331,7 +4319,7 @@ def devProps(data=0):
                return
 
        if(os.path.exists(sysvals.ftracefile) == False):
-               doError('%s does not exist' % sysvals.ftracefile, False)
+               doError('%s does not exist' % sysvals.ftracefile)
 
        # first get the list of devices we need properties for
        msghead = 'Additional data added by AnalyzeSuspend'
@@ -4354,7 +4342,7 @@ def devProps(data=0):
                m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
                if(not m):
                        continue
-               drv, dev, par = m.group('drv'), m.group('d'), m.group('p')
+               dev = m.group('d')
                if dev not in props:
                        props[dev] = DevProps()
        tf.close()
@@ -4430,7 +4418,6 @@ def devProps(data=0):
 # Output:
 #       A string list of the available modes
 def getModes():
-       global sysvals
        modes = ''
        if(os.path.exists(sysvals.powerfile)):
                fp = open(sysvals.powerfile, 'r')
@@ -4444,8 +4431,6 @@ def getModes():
 # Arguments:
 #       output: True to output the info to stdout, False otherwise
 def getFPDT(output):
-       global sysvals
-
        rectype = {}
        rectype[0] = 'Firmware Basic Boot Performance Record'
        rectype[1] = 'S3 Performance Table Record'
@@ -4456,19 +4441,19 @@ def getFPDT(output):
        rootCheck(True)
        if(not os.path.exists(sysvals.fpdtpath)):
                if(output):
-                       doError('file does not exist: %s' % sysvals.fpdtpath, False)
+                       doError('file does not exist: %s' % sysvals.fpdtpath)
                return False
        if(not os.access(sysvals.fpdtpath, os.R_OK)):
                if(output):
-                       doError('file is not readable: %s' % sysvals.fpdtpath, False)
+                       doError('file is not readable: %s' % sysvals.fpdtpath)
                return False
        if(not os.path.exists(sysvals.mempath)):
                if(output):
-                       doError('file does not exist: %s' % sysvals.mempath, False)
+                       doError('file does not exist: %s' % sysvals.mempath)
                return False
        if(not os.access(sysvals.mempath, os.R_OK)):
                if(output):
-                       doError('file is not readable: %s' % sysvals.mempath, False)
+                       doError('file is not readable: %s' % sysvals.mempath)
                return False
 
        fp = open(sysvals.fpdtpath, 'rb')
@@ -4478,7 +4463,7 @@ def getFPDT(output):
        if(len(buf) < 36):
                if(output):
                        doError('Invalid FPDT table data, should '+\
-                               'be at least 36 bytes', False)
+                               'be at least 36 bytes')
                return False
 
        table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
@@ -4577,7 +4562,6 @@ def getFPDT(output):
 # Output:
 #       True if the test will work, False if not
 def statusCheck(probecheck=False):
-       global sysvals
        status = True
 
        print('Checking this system (%s)...' % platform.node())
@@ -4661,20 +4645,13 @@ def statusCheck(probecheck=False):
                return status
 
        # verify kprobes
-       if sysvals.usekprobes and len(sysvals.tracefuncs) > 0:
-               print('    verifying timeline kprobes work:')
-               for name in sorted(sysvals.tracefuncs):
-                       res = sysvals.colorText('NO')
-                       if sysvals.testKprobe(name, sysvals.tracefuncs[name]):
-                               res = 'YES'
-                       print('         %s: %s' % (name, res))
-       if sysvals.usedevsrc and sysvals.usekprobes and len(sysvals.dev_tracefuncs) > 0:
-               print('    verifying dev kprobes work:')
-               for name in sorted(sysvals.dev_tracefuncs):
-                       res = sysvals.colorText('NO')
-                       if sysvals.testKprobe(name, sysvals.dev_tracefuncs[name]):
-                               res = 'YES'
-                       print('         %s: %s' % (name, res))
+       if sysvals.usekprobes:
+               for name in sysvals.tracefuncs:
+                       sysvals.defaultKprobe(name, sysvals.tracefuncs[name])
+               if sysvals.usedevsrc:
+                       for name in sysvals.dev_tracefuncs:
+                               sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])
+               sysvals.addKprobes(True)
 
        return status
 
@@ -4684,33 +4661,20 @@ def statusCheck(probecheck=False):
 # Arguments:
 #       msg: the error message to print
 #       help: True if printHelp should be called after, False otherwise
-def doError(msg, help):
+def doError(msg, help=False):
        if(help == True):
                printHelp()
        print('ERROR: %s\n') % msg
        sys.exit()
 
-# Function: doWarning
-# Description:
-#       generic warning function for non-catastrophic anomalies
-# Arguments:
-#       msg: the warning message to print
-#       file: If not empty, a filename to request be sent to the owner for debug
-def doWarning(msg, file=''):
-       print('/* %s */') % msg
-       if(file):
-               print('/* For a fix, please send this'+\
-                       ' %s file to <todd.e.brandt@intel.com> */' % file)
-
 # Function: rootCheck
 # Description:
 #       quick check to see if we have root access
 def rootCheck(fatal):
-       global sysvals
        if(os.access(sysvals.powerfile, os.W_OK)):
                return True
        if fatal:
-               doError('This command must be run as root', False)
+               doError('This command must be run as root')
        return False
 
 # Function: getArgInt
@@ -4751,66 +4715,51 @@ def getArgFloat(name, args, min, max, main=True):
                doError(name+': value should be between %f and %f' % (min, max), True)
        return val
 
-# Function: rerunTest
-# Description:
-#       generate an output from an existing set of ftrace/dmesg logs
-def rerunTest():
-       global sysvals
-
-       if(sysvals.ftracefile != ''):
-               doesTraceLogHaveTraceEvents()
-       if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly):
-               doError('recreating this html output '+\
-                       'requires a dmesg file', False)
-       sysvals.setOutputFile()
-       vprint('Output file: %s' % sysvals.htmlfile)
-       if(os.path.exists(sysvals.htmlfile) and not os.access(sysvals.htmlfile, os.W_OK)):
-               doError('missing permission to write to %s' % sysvals.htmlfile, False)
+def processData():
        print('PROCESSING DATA')
        if(sysvals.usetraceeventsonly):
                testruns = parseTraceLog()
+               if sysvals.dmesgfile:
+                       dmesgtext = loadKernelLog(True)
+                       for data in testruns:
+                               data.extractErrorInfo(dmesgtext)
        else:
                testruns = loadKernelLog()
                for data in testruns:
                        parseKernelLog(data)
-               if(sysvals.ftracefile != ''):
+               if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
                        appendIncompleteTraceLog(testruns)
        createHTML(testruns)
 
+# Function: rerunTest
+# Description:
+#       generate an output from an existing set of ftrace/dmesg logs
+def rerunTest():
+       if sysvals.ftracefile:
+               doesTraceLogHaveTraceEvents()
+       if not sysvals.dmesgfile and not sysvals.usetraceeventsonly:
+               doError('recreating this html output requires a dmesg file')
+       sysvals.setOutputFile()
+       vprint('Output file: %s' % sysvals.htmlfile)
+       if(os.path.exists(sysvals.htmlfile) and not os.access(sysvals.htmlfile, os.W_OK)):
+               doError('missing permission to write to %s' % sysvals.htmlfile)
+       processData()
+
 # Function: runTest
 # Description:
 #       execute a suspend/resume, gather the logs, and generate the output
 def runTest(subdir, testpath=''):
-       global sysvals
-
        # prepare for the test
        sysvals.initFtrace()
        sysvals.initTestOutput(subdir, testpath)
-
-       vprint('Output files:\n    %s' % sysvals.dmesgfile)
-       if(sysvals.usecallgraph or
-               sysvals.usetraceevents or
-               sysvals.usetraceeventsonly):
-               vprint('    %s' % sysvals.ftracefile)
-       vprint('    %s' % sysvals.htmlfile)
+       vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
+               (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
 
        # execute the test
        executeSuspend()
        sysvals.cleanupFtrace()
+       processData()
 
-       # analyze the data and create the html output
-       print('PROCESSING DATA')
-       if(sysvals.usetraceeventsonly):
-               # data for kernels 3.15 or newer is entirely in ftrace
-               testruns = parseTraceLog()
-       else:
-               # data for kernels older than 3.15 is primarily in dmesg
-               testruns = loadKernelLog()
-               for data in testruns:
-                       parseKernelLog(data)
-               if(sysvals.usecallgraph or sysvals.usetraceevents):
-                       appendIncompleteTraceLog(testruns)
-       createHTML(testruns)
        # if running as root, change output dir owner to sudo_user
        if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \
                'SUDO_USER' in os.environ:
@@ -4821,8 +4770,6 @@ def runTest(subdir, testpath=''):
 # Description:
 #       create a summary of tests in a sub-directory
 def runSummary(subdir, output):
-       global sysvals
-
        # get a list of ftrace output files
        files = []
        for dirname, dirnames, filenames in os.walk(subdir):
@@ -4878,7 +4825,6 @@ def checkArgBool(value):
 # Description:
 #       Configure the script via the info in a config file
 def configFromFile(file):
-       global sysvals
        Config = ConfigParser.ConfigParser()
 
        Config.read(file)
@@ -4939,15 +4885,13 @@ def configFromFile(file):
                                sysvals.setOutputFolder(value)
 
        if sysvals.suspendmode == 'command' and not sysvals.testcommand:
-               doError('No command supplied for mode "command"', False)
+               doError('No command supplied for mode "command"')
 
        # compatibility errors
        if sysvals.usedevsrc and sysvals.usecallgraph:
-               doError('-dev is not compatible with -f', False)
-       if sysvals.usecallgraph and sysvals.execcount > 1:
-               doError('-x2 is not compatible with -f', False)
+               doError('-dev is not compatible with -f')
        if sysvals.usecallgraph and sysvals.useprocmon:
-               doError('-proc is not compatible with -f', False)
+               doError('-proc is not compatible with -f')
 
        if overridekprobes:
                sysvals.tracefuncs = dict()
@@ -4964,7 +4908,7 @@ def configFromFile(file):
        if kprobesec in sections:
                for name in Config.options(kprobesec):
                        if name in kprobes:
-                               doError('Duplicate timeline function found "%s"' % (name), False)
+                               doError('Duplicate timeline function found "%s"' % (name))
                        text = Config.get(kprobesec, name)
                        kprobes[name] = (text, False)
 
@@ -4997,12 +4941,12 @@ def configFromFile(file):
                                args[d[0]] = d[1]
                        i += 1
                if not function or not format:
-                       doError('Invalid kprobe: %s' % name, False)
+                       doError('Invalid kprobe: %s' % name)
                for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
                        if arg not in args:
-                               doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
+                               doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
                if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
-                       doError('Duplicate timeline function found "%s"' % (name), False)
+                       doError('Duplicate timeline function found "%s"' % (name))
 
                kp = {
                        'name': name,
@@ -5021,7 +4965,6 @@ def configFromFile(file):
 # Description:
 #       print out the help text
 def printHelp():
-       global sysvals
        modes = getModes()
 
        print('')
@@ -5074,6 +5017,8 @@ def printHelp():
        print('   -fadd file   Add functions to be graphed in the timeline from a list in a text file')
        print('   -filter "d1,d2,..." Filter out all but this comma-delimited list of device names')
        print('   -mincg  ms   Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
+       print('   -cgphase P   Only show callgraph data for phase P (e.g. suspend_late)')
+       print('   -cgtest N    Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
        print('   -timeprec N  Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
        print('  [utilities]')
        print('   -fpdt        Print out the contents of the ACPI Firmware Performance Data Table')
@@ -5139,6 +5084,17 @@ if __name__ == '__main__':
                        sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
                elif(arg == '-mincg'):
                        sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
+               elif(arg == '-cgtest'):
+                       sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
+               elif(arg == '-cgphase'):
+                       try:
+                               val = args.next()
+                       except:
+                               doError('No phase name supplied', True)
+                       d = Data(0)
+                       if val not in d.phases:
+                               doError('Invalid phase, valid phaess are %s' % d.phases, True)
+                       sysvals.cgphase = val
                elif(arg == '-callloop-maxgap'):
                        sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
                elif(arg == '-callloop-maxlen'):
@@ -5170,7 +5126,7 @@ if __name__ == '__main__':
                        except:
                                doError('No text file supplied', True)
                        if(os.path.exists(val) == False):
-                               doError('%s does not exist' % val, False)
+                               doError('%s does not exist' % val)
                        configFromFile(val)
                elif(arg == '-fadd'):
                        try:
@@ -5178,7 +5134,7 @@ if __name__ == '__main__':
                        except:
                                doError('No text file supplied', True)
                        if(os.path.exists(val) == False):
-                               doError('%s does not exist' % val, False)
+                               doError('%s does not exist' % val)
                        sysvals.addFtraceFilterFunctions(val)
                elif(arg == '-dmesg'):
                        try:
@@ -5188,7 +5144,7 @@ if __name__ == '__main__':
                        sysvals.notestrun = True
                        sysvals.dmesgfile = val
                        if(os.path.exists(sysvals.dmesgfile) == False):
-                               doError('%s does not exist' % sysvals.dmesgfile, False)
+                               doError('%s does not exist' % sysvals.dmesgfile)
                elif(arg == '-ftrace'):
                        try:
                                val = args.next()
@@ -5197,7 +5153,7 @@ if __name__ == '__main__':
                        sysvals.notestrun = True
                        sysvals.ftracefile = val
                        if(os.path.exists(sysvals.ftracefile) == False):
-                               doError('%s does not exist' % sysvals.ftracefile, False)
+                               doError('%s does not exist' % sysvals.ftracefile)
                elif(arg == '-summary'):
                        try:
                                val = args.next()
@@ -5207,7 +5163,7 @@ if __name__ == '__main__':
                        cmdarg = val
                        sysvals.notestrun = True
                        if(os.path.isdir(val) == False):
-                               doError('%s is not accesible' % val, False)
+                               doError('%s is not accesible' % val)
                elif(arg == '-filter'):
                        try:
                                val = args.next()
@@ -5218,12 +5174,10 @@ if __name__ == '__main__':
                        doError('Invalid argument: '+arg, True)
 
        # compatibility errors
-       if(sysvals.usecallgraph and sysvals.execcount > 1):
-               doError('-x2 is not compatible with -f', False)
        if(sysvals.usecallgraph and sysvals.usedevsrc):
-               doError('-dev is not compatible with -f', False)
+               doError('-dev is not compatible with -f')
        if(sysvals.usecallgraph and sysvals.useprocmon):
-               doError('-proc is not compatible with -f', False)
+               doError('-proc is not compatible with -f')
 
        # callgraph size cannot exceed device size
        if sysvals.mincglen < sysvals.mindevlen:
@@ -5238,8 +5192,7 @@ if __name__ == '__main__':
                elif(cmd == 'usbtopo'):
                        detectUSB()
                elif(cmd == 'modes'):
-                       modes = getModes()
-                       print modes
+                       print getModes()
                elif(cmd == 'flist'):
                        sysvals.getFtraceFilterFunctions(True)
                elif(cmd == 'flistall'):