histogram-trace

#!/usr/bin/python

import re, sys

def make_int_scanner(*names):
    INT_RX = r'[\-]?\d+'
    rx = r'^'
    for name in names:
        rx += r'\s+(?P<' + name + r'>'+ INT_RX +r')'
    return re.compile(rx)

# global_time thread_time tid reason entry/exit hw_interrupts page_faults adapted_rbc instructions eax ebx ecx edx esi edi ebp orig_eax esp eip eflags
TRACE_FIELDS = ('global_time', 'thread_time', 'tid', 'reason', 'entry_exit',
                'hw_ints', 'page_faults', 'rbc', 'insns',
                'eax', 'ebx', 'ecx', 'edx', 'esi', 'edi', 'ebp', 'orig_eax')
TRACE_EVENT_RX = make_int_scanner(*TRACE_FIELDS)
TRACE_SYNTH_EVENT_RX = make_int_scanner(*TRACE_FIELDS[0:4])
TRACE_NAME = 'trace_0'

class Event:
    def __init__(self, m):
        values = m.groupdict(-1)
        for field in TRACE_FIELDS:
            setattr(self, field, int(values.get(field, -1)))

def iterevents(inf):
    for line in inf:
        m = TRACE_EVENT_RX.match(line)
        if not m:
            m = TRACE_SYNTH_EVENT_RX.match(line)
            if not m:
                continue
        yield Event(m)

def incr_histogram_item(hist, item):
    count = hist.get(item, 0)
    count += 1
    hist[item] = count

##-----------------------------------------------------------------------------
## Accumulators.

SIG_SEGV_RDTSC = -1022
USR_SCHED = -1020
def is_syscall_entry(ev):
    return ev.entry_exit == 0 and (ev.reason >=0
                                   or USR_SCHED == ev.reason
                                   or SIG_SEGV_RDTSC == ev.reason)

def accum_syscall_histogram(inf, hist={}):
    for ev in iterevents(inf):
        if is_syscall_entry(ev):
            incr_histogram_item(hist, ev.reason)
    return hist

def accum_insn_histogram(inf, hist={}):
    for ev in iterevents(inf):
        if ev.insns <= 0 or ev.rbc <= 0:
            continue
        insns_per_rcb = int(ev.insns / ev.rbc)
        incr_histogram_item(hist, insns_per_rcb)
    return hist

FLUSH_EVENT = -1018
def accum_flush_histogram(inf, hist={}):
    flushed = 0
    for ev in iterevents(inf):
        if ev.reason == FLUSH_EVENT:
            assert not flushed
            flushed = 1
            continue
        if flushed:
            flushed = 0
            incr_histogram_item(hist, ev.reason)

SYS_socketcall = 102
def accum_socketcall_histogram(inf, hist={}):
    for ev in iterevents(inf):
        if is_syscall_entry(ev) and SYS_socketcall == ev.reason:
            incr_histogram_item(hist, ev.ebx)

SYS_futex = 240
FUTEX_PRIVATE_FLAG = 128
FUTEX_CLOCK_REALTIME = 256
FUTEX_CMD_MASK = ~(FUTEX_PRIVATE_FLAG | FUTEX_CLOCK_REALTIME)
def accum_futex_histogram(inf, hist={}):
    for ev in iterevents(inf):
        if is_syscall_entry(ev) and SYS_futex == ev.reason:
            incr_histogram_item(hist, ev.ecx & FUTEX_CMD_MASK)

SYS_fcntl = 55
SYS_fcntl64 = 221
def accum_fcntl_histogram(inf, hist={}):
    for ev in iterevents(inf):
        if is_syscall_entry(ev) and (SYS_fcntl == ev.reason or
                                     SYS_fcntl64 == ev.reason):
            incr_histogram_item(hist, ev.ecx)

##-----------------------------------------------------------------------------
## Stringifiers.

def read_syscalls():
    t = { }
    rx = re.compile(r'^#define __NR_([^ ]+) (\d+)')
    for line in open('/usr/include/asm/unistd_32.h', 'r'):
        m = rx.match(line)
        if not m:
            continue
        t[int(m.group(2))] = m.group(1)
    return t

SYSCALL_TABLE = read_syscalls()
def stringify_syscall(no):
    return ('USR_SCHED' if USR_SCHED == no else
            'SIG_SEGV_RDTSC' if SIG_SEGV_RDTSC == no else
            'rrcall_init_buf' if 442 == no else
            'rrcall_monkeypatch_vdso' if 443 == no else
            SYSCALL_TABLE.get(no, '???'))

def stringify_futex(op):
    private = ' (private)' if op & FUTEX_PRIVATE_FLAG else ''
    rt = ' (rt)' if op & FUTEX_CLOCK_REALTIME else ''
    strop = {
        0: 'FUTEX_WAIT',
        1: 'FUTEX_WAKE',
        2: 'FUTEX_FD',
        3: 'FUTEX_REQUEUE',
        4: 'FUTEX_CMP_REQUEUE',
        5: 'FUTEX_WAKE_OP',
        6: 'FUTEX_LOCK_PI',
        7: 'FUTEX_UNLOCK_PI',
        8: 'FUTEX_TRYLOCK_PI',
        9: 'FUTEX_WAIT_BITSET',
        10: 'FUTEX_WAKE_BITSET',
        11: 'FUTEX_WAIT_REQUEUE_PI',
        12: 'FUTEX_CMP_REQUEUE_PI',
    } [op & FUTEX_CMD_MASK]
    return strop + private + rt

def stringify_socketcall(op):
    return {
        1: 'SYS_SOCKET',
        2: 'SYS_BIND',
        3: 'SYS_CONNECT',
        4: 'SYS_LISTEN',
        5: 'SYS_ACCEPT',
        6: 'SYS_GETSOCKNAME',
        7: 'SYS_GETPEERNAME',
        8: 'SYS_SOCKETPAIR',
        9: 'SYS_SEND',
        10: 'SYS_RECV',
        11: 'SYS_SENDTO',
        12: 'SYS_RECVFROM',
        13: 'SYS_SHUTDOWN',
        14: 'SYS_SETSOCKOPT',
        15: 'SYS_GETSOCKOPT',
        16: 'SYS_SENDMSG',
        17: 'SYS_RECVMSG',
        18: 'SYS_ACCEPT4',
        19: 'SYS_RECVMMSG',
        20: 'SYS_SENDMMSG',
    }[op]

def stringify_fcntl(which):
    m = {
        4: 'F_SETFL',
        5: 'F_GETLK',
        6: 'F_SETLK',
        7: 'F_SETLKW',
        10: 'F_SETSIG',
        12: 'F_GETLK64',
        13: 'F_SETLK64',
        14: 'F_SETLKW64',
        15: 'F_SETOWN_EX'
    }
    return m.get(which, '???')

##-----------------------------------------------------------------------------
## Printers.

def print_histogram(label, hist, stringify, outf=sys.stdout):
    total = sum(hist.values())
    print>>outf, 'count\t     %  .... '+ label
    print>>outf, '-----\t-------'
    for k in sorted(hist, key=hist.get, reverse=True):
        print>>outf, '%6u\t%6.2f%% .... %s (%d)'% (hist[k],
                                                   100.0 * hist[k] / total,
                                                   stringify(k), k)
    print>>outf, '-------'
    print>>outf, '%6u\t%6.2f%% .... %s'% (total, 100.0, 'Total')

def usage(exe):
    print>>sys.stderr, 'Usage:'
    print>>sys.stderr, '   rr dump -r <trace-dir> |', exe, '(syscall|insns/rcb|flush|socketcall|futex|fcntl)'
    sys.exit(1)

def lookup_accum_stringify(which):
    if which == 'syscall':
        return accum_syscall_histogram, stringify_syscall
    elif which == 'insns/rcb':
        return accum_insn_histogram, None
    elif which == 'flush':
        return accum_flush_histogram, stringify_syscall
    elif which == 'socketcall':
        return accum_socketcall_histogram, stringify_socketcall
    elif which == 'futex':
        return accum_futex_histogram, stringify_futex
    elif which == 'fcntl':
        return accum_fcntl_histogram, stringify_fcntl    
    else:
        usage(argv)


def main(argv):
    exe = argv.pop(0)
    if 0 == len(argv):
        usage(exe)

    which = argv.pop(0)
    hist = {}
    accum_hist, stringify = lookup_accum_stringify(which)

    if 0 == len(argv):
        argv.append(sys.stdin)
    for f in argv:
        trace_file = f
        if isinstance(f, str): trace_file = open(f +'/'+ TRACE_NAME, 'r')
        accum_hist(trace_file, hist)
        trace_file.close()

    print_histogram(which, hist, stringify)

if __name__ == '__main__':
    main(sys.argv[:])