def parseTraceLog(data): sysvals.vprint('Analyzing the ftrace data (%s)...' % \ os.path.basename(sysvals.ftracefile)) # if available, calculate cgfilter allowable ranges cgfilter = [] if len(sysvals.cgfilter) > 0: for p in data.phases: list = data.dmesg[p]['list'] for i in sysvals.cgfilter: if i in list: cgfilter.append( [list[i]['start'] - 0.0001, list[i]['end'] + 0.0001]) # 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') t = float(m_time) if len(cgfilter) > 0: allow = False for r in cgfilter: if t >= r[0] and t < r[1]: allow = True break if not allow: continue if t > 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, sysvals)) cg = ftemp[key][-1] res = cg.addLine(t) if (res != 0): ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals)) if (res == -1): ftemp[key][-1].addLine(t) 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 or (cg.end - cg.start == 0): continue if (not cg.postProcess()): pprint('Sanity check failed for %s-%d' % (proc, pid)) continue # match cg data to devices devname = data.deviceMatch(pid, cg) if not devname: kind = 'Orphan' if cg.partial: kind = 'Partial' sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\ (kind, cg.name, proc, pid, cg.start, cg.end)) elif len(cg.list) > 1000000: pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\ (devname, len(cg.list)))
def parseKernelLog(): sysvals.vprint('Analyzing the dmesg data (%s)...' % \ os.path.basename(sysvals.dmesgfile)) 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 elif re.match(tp.cmdlinefmt, line): tp.cmdline = line continue elif re.match(tp.kparamsfmt, line): tp.kparams = 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