+ if(t.name == 'RESUME COMPLETE'):
+ testrun[testidx].inthepipe = False
+ data.setEnd(t.time)
+ if(testidx == testcnt - 1):
+ break
+ continue
+ # general trace events have two types, begin and end
+ if(re.match('(?P<name>.*) begin$', t.name)):
+ isbegin = True
+ elif(re.match('(?P<name>.*) end$', t.name)):
+ isbegin = False
+ else:
+ continue
+ m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
+ if(m):
+ val = m.group('val')
+ if val == '0':
+ name = m.group('name')
+ else:
+ name = m.group('name')+'['+val+']'
+ else:
+ m = re.match('(?P<name>.*) .*', t.name)
+ name = m.group('name')
+ # special processing for trace events
+ if re.match('dpm_prepare\[.*', name):
+ continue
+ elif re.match('machine_suspend.*', name):
+ continue
+ elif re.match('suspend_enter\[.*', name):
+ if(not isbegin):
+ data.dmesg['suspend_prepare']['end'] = t.time
+ continue
+ elif re.match('dpm_suspend\[.*', name):
+ if(not isbegin):
+ data.dmesg['suspend']['end'] = t.time
+ continue
+ elif re.match('dpm_suspend_late\[.*', name):
+ if(isbegin):
+ data.dmesg['suspend_late']['start'] = t.time
+ else:
+ data.dmesg['suspend_late']['end'] = t.time
+ continue
+ elif re.match('dpm_suspend_noirq\[.*', name):
+ if(isbegin):
+ data.dmesg['suspend_noirq']['start'] = t.time
+ else:
+ data.dmesg['suspend_noirq']['end'] = t.time
+ continue
+ elif re.match('dpm_resume_noirq\[.*', name):
+ if(isbegin):
+ data.dmesg['resume_machine']['end'] = t.time
+ data.dmesg['resume_noirq']['start'] = t.time
+ else:
+ data.dmesg['resume_noirq']['end'] = t.time
+ continue
+ elif re.match('dpm_resume_early\[.*', name):
+ if(isbegin):
+ data.dmesg['resume_early']['start'] = t.time
+ else:
+ data.dmesg['resume_early']['end'] = t.time
+ continue
+ elif re.match('dpm_resume\[.*', name):
+ if(isbegin):
+ data.dmesg['resume']['start'] = t.time
+ else:
+ data.dmesg['resume']['end'] = t.time
+ continue
+ elif re.match('dpm_complete\[.*', name):
+ if(isbegin):
+ data.dmesg['resume_complete']['start'] = t.time
+ else:
+ data.dmesg['resume_complete']['end'] = t.time
+ continue
+ # is this trace event outside of the devices calls
+ if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
+ # global events (outside device calls) are simply graphed
+ if(isbegin):
+ # store each trace event in ttemp
+ if(name not in testrun[testidx].ttemp):
+ testrun[testidx].ttemp[name] = []
+ testrun[testidx].ttemp[name].append(\
+ {'begin': t.time, 'end': t.time})
+ else:
+ # finish off matching trace event in ttemp
+ if(name in testrun[testidx].ttemp):
+ testrun[testidx].ttemp[name][-1]['end'] = t.time
+ else:
+ if(isbegin):
+ data.addIntraDevTraceEvent('', name, pid, t.time)
+ else:
+ data.capIntraDevTraceEvent('', name, pid, t.time)
+ # call/return processing
+ elif sysvals.usecallgraph:
+ # create a callgraph object for the data
+ if(pid not in testrun[testidx].ftemp):
+ testrun[testidx].ftemp[pid] = []
+ testrun[testidx].ftemp[pid].append(FTraceCallGraph())
+ # when the call is finished, see which device matches it
+ cg = testrun[testidx].ftemp[pid][-1]
+ if(cg.addLine(t, m)):
+ testrun[testidx].ftemp[pid].append(FTraceCallGraph())
+ tf.close()
+
+ for test in testrun:
+ # add the traceevent data to the device hierarchy
+ if(sysvals.usetraceevents):
+ for name in test.ttemp:
+ for event in test.ttemp[name]:
+ begin = event['begin']
+ end = event['end']
+ # if event starts before timeline start, expand timeline
+ if(begin < test.data.start):
+ test.data.setStart(begin)
+ # if event ends after timeline end, expand the timeline
+ if(end > test.data.end):
+ test.data.setEnd(end)
+ test.data.newActionGlobal(name, begin, end)
+
+ # add the callgraph data to the device hierarchy
+ for pid in test.ftemp:
+ for cg in test.ftemp[pid]:
+ if(not cg.sanityCheck()):
+ id = 'task %s cpu %s' % (pid, m.group('cpu'))
+ vprint('Sanity check failed for '+\
+ id+', ignoring this callback')
+ continue
+ callstart = cg.start
+ callend = cg.end
+ for p in test.data.phases:
+ if(test.data.dmesg[p]['start'] <= callstart and
+ callstart <= test.data.dmesg[p]['end']):
+ list = test.data.dmesg[p]['list']
+ for devname in list:
+ dev = list[devname]
+ if(pid == dev['pid'] and
+ callstart <= dev['start'] and
+ callend >= dev['end']):
+ dev['ftrace'] = cg
+ break
+
+ if(sysvals.verbose):
+ test.data.printDetails()
+
+
+ # add the time in between the tests as a new phase so we can see it
+ if(len(testruns) > 1):
+ t1e = testruns[0].getEnd()
+ t2s = testruns[-1].getStart()
+ testruns[-1].newPhaseWithSingleAction('user mode', \
+ 'user mode', t1e, t2s, '#FF9966')
+
+# Function: parseTraceLog
+# Description:
+# Analyze an ftrace log output file generated from this app during
+# the execution phase. Used when the ftrace log is the primary data source
+# and includes the suspend_resume and device_pm_callback trace events
+# The ftrace filename is taken from sysvals
+# Output:
+# An array of Data objects
+def parseTraceLog():
+ global sysvals
+
+ vprint('Analyzing the ftrace data...')
+ if(os.path.exists(sysvals.ftracefile) == False):
+ doError('%s doesnt exist' % sysvals.ftracefile, False)
+
+ # extract the callgraph and traceevent data
+ testruns = []
+ testdata = []
+ testrun = 0
+ data = 0
+ tf = open(sysvals.ftracefile, 'r')
+ phase = 'suspend_prepare'
+ for line in tf:
+ # remove any latent carriage returns
+ line = line.replace('\r\n', '')
+ # stamp line: each stamp means a new test run
+ m = re.match(sysvals.stampfmt, line)
+ if(m):
+ data = Data(len(testdata))
+ testdata.append(data)
+ testrun = TestRun(data)
+ testruns.append(testrun)
+ parseStamp(m, data)
+ continue
+ if(not data):
+ continue
+ # firmware line: pull out any firmware data
+ m = re.match(sysvals.firmwarefmt, line)
+ if(m):
+ data.fwSuspend = int(m.group('s'))
+ data.fwResume = int(m.group('r'))
+ if(data.fwSuspend > 0 or data.fwResume > 0):
+ data.fwValid = True
+ continue
+ # tracer type line: determine the trace data type
+ m = re.match(sysvals.tracertypefmt, line)
+ if(m):
+ tracer = m.group('t')
+ testrun.setTracerType(tracer)
+ continue
+ # post resume time line: did this test run include post-resume data
+ m = re.match(sysvals.postresumefmt, line)
+ if(m):
+ t = int(m.group('t'))
+ if(t > 0):
+ sysvals.postresumetime = t
+ continue
+ # ftrace line: parse only valid lines
+ m = re.match(testrun.ftrace_line_fmt, line)
+ if(not m):
+ continue
+ # gather the basic message data from the line
+ m_time = m.group('time')
+ m_pid = m.group('pid')
+ m_msg = m.group('msg')
+ if(testrun.cgformat):
+ m_param3 = m.group('dur')
+ else:
+ m_param3 = 'traceevent'
+ if(m_time and m_pid and m_msg):
+ t = FTraceLine(m_time, m_msg, m_param3)
+ pid = int(m_pid)
+ else:
+ continue
+ # the line should be a call, return, or event
+ if(not t.fcall and not t.freturn and not t.fevent):
+ continue
+ # only parse the ftrace data during suspend/resume
+ if(not testrun.inthepipe):
+ # look for the suspend start marker
+ if(t.fevent):
+ if(t.name == 'SUSPEND START'):
+ testrun.inthepipe = True
+ data.setStart(t.time)
+ continue
+ # trace event processing
+ if(t.fevent):
+ if(t.name == 'RESUME COMPLETE'):
+ if(sysvals.postresumetime > 0):
+ phase = 'post_resume'
+ data.newPhase(phase, t.time, t.time, '#FF9966', -1)
+ else:
+ testrun.inthepipe = False
+ data.setEnd(t.time)
+ continue
+ if(phase == 'post_resume'):
+ data.setEnd(t.time)
+ if(t.type == 'suspend_resume'):
+ # suspend_resume trace events have two types, begin and end
+ if(re.match('(?P<name>.*) begin$', t.name)):
+ isbegin = True
+ elif(re.match('(?P<name>.*) end$', t.name)):
+ isbegin = False
+ else:
+ continue
+ m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
+ if(m):
+ val = m.group('val')
+ if val == '0':
+ name = m.group('name')
+ else:
+ name = m.group('name')+'['+val+']'
+ else:
+ m = re.match('(?P<name>.*) .*', t.name)
+ name = m.group('name')
+ # ignore these events
+ if(re.match('acpi_suspend\[.*', t.name) or
+ re.match('suspend_enter\[.*', name)):
+ continue
+ # -- phase changes --
+ # suspend_prepare start
+ if(re.match('dpm_prepare\[.*', t.name)):
+ phase = 'suspend_prepare'
+ if(not isbegin):
+ data.dmesg[phase]['end'] = t.time
+ continue
+ # suspend start
+ elif(re.match('dpm_suspend\[.*', t.name)):
+ phase = 'suspend'
+ data.setPhase(phase, t.time, isbegin)
+ continue
+ # suspend_late start
+ elif(re.match('dpm_suspend_late\[.*', t.name)):
+ phase = 'suspend_late'
+ data.setPhase(phase, t.time, isbegin)
+ continue
+ # suspend_noirq start
+ elif(re.match('dpm_suspend_noirq\[.*', t.name)):
+ phase = 'suspend_noirq'
+ data.setPhase(phase, t.time, isbegin)
+ if(not isbegin):
+ phase = 'suspend_machine'
+ data.dmesg[phase]['start'] = t.time
+ continue
+ # suspend_machine/resume_machine
+ elif(re.match('machine_suspend\[.*', t.name)):
+ if(isbegin):
+ phase = 'suspend_machine'
+ data.dmesg[phase]['end'] = t.time
+ data.tSuspended = t.time
+ else:
+ if(sysvals.suspendmode in ['mem', 'disk']):
+ data.dmesg['suspend_machine']['end'] = t.time
+ data.tSuspended = t.time
+ phase = 'resume_machine'
+ data.dmesg[phase]['start'] = t.time
+ data.tResumed = t.time
+ data.tLow = data.tResumed - data.tSuspended
+ continue
+ # resume_noirq start
+ elif(re.match('dpm_resume_noirq\[.*', t.name)):
+ phase = 'resume_noirq'
+ data.setPhase(phase, t.time, isbegin)
+ if(isbegin):
+ data.dmesg['resume_machine']['end'] = t.time
+ continue
+ # resume_early start
+ elif(re.match('dpm_resume_early\[.*', t.name)):
+ phase = 'resume_early'
+ data.setPhase(phase, t.time, isbegin)
+ continue
+ # resume start
+ elif(re.match('dpm_resume\[.*', t.name)):
+ phase = 'resume'
+ data.setPhase(phase, t.time, isbegin)
+ continue
+ # resume complete start
+ elif(re.match('dpm_complete\[.*', t.name)):
+ phase = 'resume_complete'
+ if(isbegin):
+ data.dmesg[phase]['start'] = t.time
+ continue
+
+ # is this trace event outside of the devices calls
+ if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
+ # global events (outside device calls) are simply graphed
+ if(name not in testrun.ttemp):
+ testrun.ttemp[name] = []
+ if(isbegin):
+ # create a new list entry
+ testrun.ttemp[name].append(\
+ {'begin': t.time, 'end': t.time})
+ else:
+ if(len(testrun.ttemp[name]) > 0):
+ # if an antry exists, assume this is its end
+ testrun.ttemp[name][-1]['end'] = t.time
+ elif(phase == 'post_resume'):
+ # post resume events can just have ends
+ testrun.ttemp[name].append({
+ 'begin': data.dmesg[phase]['start'],
+ 'end': t.time})
+ else:
+ if(isbegin):
+ data.addIntraDevTraceEvent('', name, pid, t.time)
+ else:
+ data.capIntraDevTraceEvent('', name, pid, t.time)
+ # device callback start
+ elif(t.type == 'device_pm_callback_start'):
+ m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
+ t.name);
+ if(not m):
+ continue
+ drv = m.group('drv')
+ n = m.group('d')
+ p = m.group('p')
+ if(n and p):
+ data.newAction(phase, n, pid, p, t.time, -1, drv)
+ # device callback finish
+ elif(t.type == 'device_pm_callback_end'):
+ m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
+ if(not m):
+ continue
+ n = m.group('d')
+ list = data.dmesg[phase]['list']
+ if(n in list):
+ dev = list[n]
+ dev['length'] = t.time - dev['start']
+ dev['end'] = t.time
+ # callgraph processing
+ elif sysvals.usecallgraph:
+ # this shouldn't happen, but JIC, ignore callgraph data post-res
+ if(phase == 'post_resume'):