#!/usr/bin/env python # by Mark Williamson, (C) 2004 Intel Research Cambridge # Program for reformatting trace buffer output according to user-supplied rules import re, sys, string, signal, struct, os, getopt def usage(): print >> sys.stderr, \ "Usage: " + sys.argv[0] + """ defs-file Parses trace data in binary format, as output by Xentrace and reformats it according to the rules in a file of definitions. The rules in this file should have the format ({ and } show grouping and are not part of the syntax): {event_id}{whitespace}{text format string} The textual format string may include format specifiers, such as: %(cpu)d, %(tsc)d, %(event)d, %(1)d, %(2)d, %(3)d, %(4)d, ... [ the 'd' format specifier outputs in decimal, alternatively 'x' will output in hexadecimal and 'o' will output in octal ] Which correspond to the CPU number, event ID, timestamp counter and the 7 data fields from the trace record. There should be one such rule for each type of event. Depending on your system and the volume of trace buffer data, this script may not be able to keep up with the output of xentrace if it is piped directly. In these circumstances you should have xentrace output to a file for processing off-line. """ sys.exit(1) def read_defs(defs_file): defs = {} fd = open(defs_file) reg = re.compile('(\S+)\s+(\S.*)') while True: line = fd.readline() if not line: break if line[0] == '#' or line[0] == '\n': continue m = reg.match(line) if not m: print >> sys.stderr, "Bad format file" ; sys.exit(1) defs[str(eval(m.group(1)))] = m.group(2) return defs def sighand(x,y): global interrupted interrupted = 1 ##### Main code mhz = 0 if len(sys.argv) < 2: usage() try: opts, arg = getopt.getopt(sys.argv[1:], "c:" ) for opt in opts: if opt[0] == '-c' : mhz = int(opt[1]) except getopt.GetoptError: usage() signal.signal(signal.SIGTERM, sighand) signal.signal(signal.SIGHUP, sighand) signal.signal(signal.SIGINT, sighand) interrupted = 0 try: defs = read_defs(arg[0]) except IOError, exn: print exn sys.exit(1) # structure of trace record (as output by xentrace): # HDR(I) {TSC(Q)} D1(I) D2(I) D3(I) D4(I) D5(I) D6(I) D7(I) # # HDR consists of EVENT:28:, n_data:3:, tsc_in:1: # EVENT means Event ID # n_data means number of data (like D1, D2, ...) # tsc_in means TSC data exists(1) or not(0). # if tsc_in == 0, TSC(Q) does not exists. # # CPU ID exists on trace data of EVENT=0x0001f003 # HDRREC = "I" TSCREC = "Q" D1REC = "I" D2REC = "II" D3REC = "III" D4REC = "IIII" D5REC = "IIIII" D6REC = "IIIIII" D7REC = "IIIIIII" last_tsc = [0] TRC_TRACE_IRQ = 0x1f004 TRC_PV_HYPERCALL_V2 = 0x20100d TRC_PV_HYPERCALL_SUBCALL = 0x20100e NR_VECTORS = 256 irq_measure = [{'count':0, 'tot_cycles':0, 'max_cycles':0}] * NR_VECTORS i=0 while not interrupted: try: i=i+1 line = sys.stdin.read(struct.calcsize(HDRREC)) if not line: break event = struct.unpack(HDRREC, line)[0] n_data = event >> 28 & 0x7 tsc_in = event >> 31 d1 = 0 d2 = 0 d3 = 0 d4 = 0 d5 = 0 d6 = 0 d7 = 0 tsc = 0 if tsc_in == 1: line = sys.stdin.read(struct.calcsize(TSCREC)) if not line: break tsc = struct.unpack(TSCREC, line)[0] if n_data == 1: line = sys.stdin.read(struct.calcsize(D1REC)) if not line: break d1 = struct.unpack(D1REC, line)[0] if n_data == 2: line = sys.stdin.read(struct.calcsize(D2REC)) if not line: break (d1, d2) = struct.unpack(D2REC, line) if n_data == 3: line = sys.stdin.read(struct.calcsize(D3REC)) if not line: break (d1, d2, d3) = struct.unpack(D3REC, line) if n_data == 4: line = sys.stdin.read(struct.calcsize(D4REC)) if not line: break (d1, d2, d3, d4) = struct.unpack(D4REC, line) if n_data == 5: line = sys.stdin.read(struct.calcsize(D5REC)) if not line: break (d1, d2, d3, d4, d5) = struct.unpack(D5REC, line) if n_data == 6: line = sys.stdin.read(struct.calcsize(D6REC)) if not line: break (d1, d2, d3, d4, d5, d6) = struct.unpack(D6REC, line) if n_data == 7: line = sys.stdin.read(struct.calcsize(D7REC)) if not line: break (d1, d2, d3, d4, d5, d6, d7) = struct.unpack(D7REC, line) # Event field is 28bit of 'uint32_t' in header, not 'long'. event &= 0x0fffffff if event == 0x1f003: cpu = d1 if event == TRC_TRACE_IRQ: # IN - d1:vector, d2:tsc_in, d3:tsc_out # OUT - d1:vector, d2:count, d3:tot_cycles, d4:max_cycles tsc_diff = d3 - d2 if tsc_diff < 0: break irq_measure[d1]['count'] += 1 irq_measure[d1]['tot_cycles'] += tsc_diff if irq_measure[d1]['max_cycles'] < tsc_diff: irq_measure[d1]['max_cycles'] = tsc_diff d2 = irq_measure[d1]['count'] d3 = irq_measure[d1]['tot_cycles'] d4 = irq_measure[d1]['max_cycles'] if event == TRC_PV_HYPERCALL_V2 or event == TRC_PV_HYPERCALL_SUBCALL: # Mask off the argument present bits. d1 &= 0x000fffff #tsc = (tscH<<32) | tscL #print i, tsc if cpu >= len(last_tsc): last_tsc += [0] * (cpu - len(last_tsc) + 1) elif tsc < last_tsc[cpu] and tsc_in == 1: print "TSC stepped backward cpu %d ! %d %d" % (cpu,tsc,last_tsc[cpu]) # provide relative TSC if last_tsc[cpu] > 0 and tsc_in == 1: reltsc = tsc - last_tsc[cpu] else: reltsc = 0 if tsc_in == 1: last_tsc[cpu] = tsc if mhz: tsc = tsc / (mhz*1000000.0) args = {'cpu' : cpu, 'tsc' : tsc, 'event' : event, 'reltsc': reltsc, '1' : d1, '2' : d2, '3' : d3, '4' : d4, '5' : d5, '6' : d6, '7' : d7 } try: if defs.has_key(str(event)): print defs[str(event)] % args else: if defs.has_key(str(0)): print defs[str(0)] % args except TypeError: if defs.has_key(str(event)): print defs[str(event)] print args else: if defs.has_key(str(0)): print defs[str(0)] print args except IOError, struct.error: sys.exit()