xen/tools/xentrace/xentrace_format

#!/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()