def loadTraceLog(data):
# load the data to a temp file if none given
if not sysvals.ftracefile:
lib = aslib.sysvals
aslib.rootCheck(True)
if not lib.verifyFtrace():
doError('ftrace not available')
if lib.fgetVal('current_tracer').strip() != 'function_graph':
doError('ftrace not configured for a boot callgraph')
sysvals.ftracefile = '/tmp/boot_ftrace.%s.txt' % os.getpid()
call('cat ' + lib.tpath + 'trace > ' + sysvals.ftracefile, shell=True)
if not sysvals.ftracefile:
doError('No trace data available')
# parse the trace log
ftemp = dict()
tp = aslib.TestProps()
tp.setTracerType('function_graph')
tf = open(sysvals.ftracefile, 'r')
for line in tf:
if line[0] == '#':
continue
m = re.match(tp.ftrace_line_fmt, line.strip())
if (not m):
continue
m_time, m_proc, m_pid, m_msg, m_dur = \
m.group('time', 'proc', 'pid', 'msg', 'dur')
if float(m_time) > data.end:
break
if (m_time and m_pid and m_msg):
t = aslib.FTraceLine(m_time, m_msg, m_dur)
pid = int(m_pid)
else:
continue
if t.fevent or t.fkprobe:
continue
key = (m_proc, pid)
if (key not in ftemp):
ftemp[key] = []
ftemp[key].append(aslib.FTraceCallGraph(pid))
cg = ftemp[key][-1]
if (cg.addLine(t)):
ftemp[key].append(aslib.FTraceCallGraph(pid))
tf.close()
# add the callgraph data to the device hierarchy
for key in ftemp:
proc, pid = key
for cg in ftemp[key]:
if len(cg.list) < 1 or cg.invalid:
continue
if (not cg.postProcess()):
print('Sanity check failed for %s-%d' % (proc, pid))
continue
# match cg data to devices
if not data.deviceMatch(cg):
print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid,
cg.start, cg.end)
def parseTraceLog(data):
# parse the trace log
ftemp = dict()
tp = aslib.TestProps()
tp.setTracerType('function_graph')
tf = open(sysvals.ftracefile, 'r')
for line in tf:
if line[0] == '#':
continue
m = re.match(tp.ftrace_line_fmt, line.strip())
if (not m):
continue
m_time, m_proc, m_pid, m_msg, m_dur = \
m.group('time', 'proc', 'pid', 'msg', 'dur')
if float(m_time) > data.end:
break
if (m_time and m_pid and m_msg):
t = aslib.FTraceLine(m_time, m_msg, m_dur)
pid = int(m_pid)
else:
continue
if t.fevent or t.fkprobe:
continue
key = (m_proc, pid)
if (key not in ftemp):
ftemp[key] = []
ftemp[key].append(aslib.FTraceCallGraph(pid))
cg = ftemp[key][-1]
if (cg.addLine(t)):
ftemp[key].append(aslib.FTraceCallGraph(pid))
tf.close()
# add the callgraph data to the device hierarchy
for key in ftemp:
proc, pid = key
for cg in ftemp[key]:
if len(cg.list) < 1 or cg.invalid:
continue
if (not cg.postProcess()):
print('Sanity check failed for %s-%d' % (proc, pid))
continue
# match cg data to devices
if not data.deviceMatch(pid, cg):
print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid,
cg.start, cg.end)
def parseKernelLog():
phase = 'kernel'
data = Data(0)
data.dmesg['kernel']['start'] = data.start = ktime = 0.0
sysvals.stamp = {
'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
'host': sysvals.hostname,
'mode': 'boot',
'kernel': ''
}
tp = aslib.TestProps()
devtemp = dict()
if (sysvals.dmesgfile):
lf = open(sysvals.dmesgfile, 'r')
else:
lf = Popen('dmesg', stdout=PIPE).stdout
for line in lf:
line = line.replace('\r\n', '')
# grab the stamp and sysinfo
if re.match(tp.stampfmt, line):
tp.stamp = line
continue
elif re.match(tp.sysinfofmt, line):
tp.sysinfo = line
continue
idx = line.find('[')
if idx > 1:
line = line[idx:]
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
if (not m):
continue
ktime = float(m.group('ktime'))
if (ktime > 120):
break
msg = m.group('msg')
data.dmesgtext.append(line)
if (ktime == 0.0 and re.match('^Linux version .*', msg)):
if (not sysvals.stamp['kernel']):
sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
continue
m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg)
if (m):
bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S')
bt = bt - timedelta(seconds=int(ktime))
data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
continue
m = re.match('^calling *(?P<f>.*)\+.* @ (?P<p>[0-9]*)', msg)
if (m):
func = m.group('f')
pid = int(m.group('p'))
devtemp[func] = (ktime, pid)
continue
m = re.match(
'^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs',
msg)
if (m):
data.valid = True
data.end = ktime
f, r, t = m.group('f', 'r', 't')
if (f in devtemp):
start, pid = devtemp[f]
data.newAction(phase, f, pid, start, ktime, int(r), int(t))
del devtemp[f]
continue
if (re.match('^Freeing unused kernel memory.*', msg)):
data.tUserMode = ktime
data.dmesg['kernel']['end'] = ktime
data.dmesg['user']['start'] = ktime
phase = 'user'
if tp.stamp:
sysvals.stamp = 0
tp.parseStamp(data, sysvals)
data.dmesg['user']['end'] = data.end
lf.close()
return data
def parseFtraceLog():
data = Data(0)
data.dmesg['boot']['start'] = data.start = ktime = 0.0
sysvals.stamp = {
'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
'host': sysvals.hostname,
'mode': 'boot',
'kernel': ''
}
tp = aslib.TestProps()
devtemp = dict()
if (sysvals.ftracefile):
lf = open(sysvals.ftracefile, 'r')
else:
lf = Popen('dmesg', stdout=PIPE).stdout
for line in lf:
line = line.replace('\r\n', '')
line = line.replace('\n', '')
# grab the stamp and sysinfo
# if re.match(tp.stampfmt, line):
# tp.stamp = line
# continue
# elif re.match(tp.sysinfofmt, line):
# tp.sysinfo = line
# continue
# idx = line.find('[')
# if idx > 1:
# line = line[idx:]
# m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
ftrace_line_fmt_nop = \
' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
'(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
'(?P<msg>.*)'
m = re.match(ftrace_line_fmt_nop, line)
if (not m):
continue
proc = m.group('proc')
ktime = float(m.group('time'))
#if(ktime > 120):
# break
msg = m.group('msg')
data.end = data.initstart = ktime
data.dmesgtext.append(line)
#if(ktime == 0.0 and re.match('^Linux version .*', msg)):
# if(not sysvals.stamp['kernel']):
# sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
# continue
#Wakeup source processing
if (sysvals.trace_wakeup_source):
#m = re.match('^calling *(?P<f>.*)\+.*', msg)
m = re.match('^wakeup_source_activate: *(?P<f>.*) .*', msg)
if (m):
if (data.dmesg['boot']['start'] == 0.0):
data.dmesg['boot']['start'] = data.start = ktime
devtemp[m.group('f')] = ktime
continue
#m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
m = re.match('^wakeup_source_deactivate: *(?P<f>.*) .*', msg)
if (m):
data.valid = True
f = m.group('f')
r = 0
if (f in devtemp):
t = ktime - devtemp[m.group('f')]
data.newAction('boot', 'ws-' + f, devtemp[f], ktime,
int(r), int(t))
data.end = ktime
del devtemp[f]
continue
#Wakelock processing
if (sysvals.trace_wakelock):
m = re.match('^pm_wake_lock: *(?P<f>.*)', msg)
if (m):
if (data.dmesg['boot']['start'] == 0.0):
data.dmesg['boot']['start'] = data.start = ktime
devtemp[m.group('f')] = ktime
continue
m = re.match('^pm_wake_unlock: *(?P<f>.*)', msg)
if (m):
data.valid = True
f = m.group('f')
r = 0
if (f in devtemp):
t = ktime - devtemp[m.group('f')]
data.newAction('boot', 'wl-' + f, devtemp[f], ktime,
int(r), int(t))
data.end = ktime
print(f, str(devtemp[f]) + '-' + str(ktime))
del devtemp[f]
continue
#Cpuidle start/end processing
if (sysvals.trace_cpuidle):
m = re.match('^cpu_idle: state=(?P<state>[0-9]*) *(?P<f>.*)', msg)
if (m):
if (data.dmesg['boot']['start'] == 0.0):
data.dmesg['boot']['start'] = data.start = ktime
state = int(m.group('state'))
if state < 2:
if state == 0:
idle_state = 'WFI'
elif state == 1:
idle_state = 'POWEROFF'
devtemp[m.group('f')] = ktime
#print (m.group('f'), idle_state, 'start')
continue
else:
data.valid = True
f = m.group('f')
r = 0
if (f in devtemp):
t = ktime - devtemp[m.group('f')]
#print (f,idle_state, 'end')
data.newAction('boot', 'idle-' + f + '-' + idle_state,
devtemp[f], ktime, int(r), int(t))
data.end = ktime
del devtemp[f]
continue
#cpufreq processing
if (sysvals.trace_cpufreq):
m = re.match('^cpu_frequency: state=(?P<freq>[0-9]*) *(?P<f>.*)',
msg)
if (m):
if (data.dmesg['boot']['start'] == 0.0):
data.dmesg['boot']['start'] = data.start = ktime
r = 0
t = 0.01
f = m.group('f')
freq = m.group('freq')
data.valid = True
data.newAction('boot', 'cf-' + f + '-' + freq, ktime,
ktime + t, int(r), int(t))
print(f, freq, ktime)
data.end = ktime + t
if tp.stamp:
sysvals.stamp = 0
tp.parseStamp(data, sysvals)
data.dmesg['boot']['end'] = data.end
lf.close()
return data