tools/analysis/runtime.py

#!/usr/bin/env python

from time import gmtime, strftime
from collections import namedtuple
import trappy, os, sys
import numpy as np
import pandas as pd
import argparse

class RunData:
    def __init__(self, pid, comm, time):
        self.pid = pid
        self.comm = comm
        self.last_start_time = time
        self.total_time = np.float64(0.0)
        self.start_time = -1
        self.end_time = -1
        self.running = 1
        self.maxrun = -1

parser = argparse.ArgumentParser(description='Analyze runnable times')

parser.add_argument('--trace', dest='trace_file', action='store', required=True,
                    help='trace file')

parser.add_argument('--rt', dest='rt', action='store_true', default=False,
                    help='only consider RT tasks')

parser.add_argument('--normalize', dest='normalize', action='store_true', default=False,
                    help='normalize time')

parser.add_argument('--rows', dest='nrows', action='store', default=20, type=int,
                    help='normalize time')

parser.add_argument('--total', dest='lat_total', action='store_true', default=False,
                    help='sort by total runnable time')

parser.add_argument('--start-time', dest='start_time', action='store', default=0, type=float,
                    help='trace window start time')

parser.add_argument('--end-time', dest='end_time', action='store', default=None, type=float,
                    help='trace window end time')

args = parser.parse_args()

path_to_html = args.trace_file
rtonly = args.rt
nrows = args.nrows

# Hash table for runtimes
runpids = {}

# Debugging aids for debugging within the callbacks
dpid = -1       # Debug all pids
debugg = False  # Global debug switch
printrows = False   # Debug aid to print all switch and wake events in a time range

switch_events = []

starttime = None
endtime = None

def switch_cb(data):
    global starttime, endtime, dpid

    prevpid = data['prev_pid']
    nextpid = data['next_pid']
    time = data['Index']

    if not starttime:
        starttime = time
    endtime = time

    debug = (dpid == prevpid or dpid == nextpid or dpid == -1) and debugg

    if debug:
        print "{}: {} {} -> {} {}".format(time, prevpid, data['prev_comm'], nextpid, data['next_comm'])

    if prevpid != 0:
       # prev pid processing (switch out)
        if runpids.has_key(prevpid):
            rp = runpids[prevpid]
            if rp.running == 1:
                rp.running = 0
                runtime = time - rp.last_start_time
                if runtime > rp.maxrun:
                    rp.maxrun = runtime
                    rp.start_time = rp.last_start_time
                    rp.end_time = time
                rp.total_time += runtime
                if debug and dpid == prevpid: print 'adding to total time {}, new total {}'.format(runtime, rp.total_time)

            else:
                print 'switch out seen while no switch in {}'.format(prevpid)
        else:
            print 'switch out seen while no switch in {}'.format(prevpid)

    if nextpid == 0:
        return

    # nextpid processing  (switch in)
    if not runpids.has_key(nextpid):
        # print 'creating data for nextpid {}'.format(nextpid)
        rp = RunData(nextpid, data['next_comm'], time)
        runpids[nextpid] = rp
        return

    rp = runpids[nextpid]
    if rp.running == 1:
        print 'switch in seen for already running task {}'.format(nextpid)
        return

    rp.running = 1
    rp.last_start_time = time


if args.normalize:
    kwargs = { 'window': (args.start_time, args.end_time) }
else:
    kwargs = { 'abs_window': (args.start_time, args.end_time) }

systrace_obj = trappy.SysTrace(name="systrace", path=path_to_html, \
        scope="sched", events=["sched_switch"], normalize_time=args.normalize, **kwargs)

ncpus = systrace_obj.sched_switch.data_frame["__cpu"].max() + 1
print 'cpus found: {}\n'.format(ncpus)

systrace_obj.apply_callbacks({ "sched_switch": switch_cb })

## Print results
testtime = (endtime - starttime) * ncpus              # for 4 cpus
print "total test time (scaled by number of CPUs): {} secs".format(testtime)

# Print the results: PID, latency, start, end, sort
result = sorted(runpids.items(), key=lambda x: x[1].total_time, reverse=True)
print "PID".ljust(10) + "\t" + "name".ljust(15) + "\t" + "max run (secs)".ljust(15) + \
      "\t" + "start time".ljust(15) + "\t" + "end time".ljust(15) + "\t" + "total runtime".ljust(15) + "\t" + "percent cpu".ljust(15) \
      + "\t" + "totalpc"

totalpc = np.float64(0.0)
for r in result[:nrows]:
	rd = r[1] # RunData named tuple
	if rd.pid != r[0]:
		raise RuntimeError("BUG: pid inconsitency found") # Sanity check
        start = rd.start_time
        end = rd.end_time
        cpupc = (rd.total_time / testtime) * 100
        totalpc += cpupc

	print str(r[0]).ljust(10) + "\t" + str(rd.comm).ljust(15) + "\t" + \
		  str(rd.maxrun).ljust(15)[:15] + "\t" + str(start).ljust(15)[:15] + \
		  "\t" + str(end).ljust(15)[:15] + "\t" + str(rd.total_time).ljust(15) + \
                    "\t" + str(cpupc) \
                    + "\t" + str(totalpc)

#############################################################
## Debugging aids to print all events in a given time range #
#############################################################
def print_event_rows(events, start, end):
	print "time".ljust(20) + "\t" + "event".ljust(10) + "\tpid" + "\tprevpid" + "\tnextpid"
	for e in events:
		if e.time < start or e.time > end:
			continue
		if e.event == "switch":
			nextpid =  e.data['next_pid']
			prevpid = e.data['prev_pid']
			pid = -1
		elif e.event == "wake":
			pid = e.data['pid']
			nextpid = -1
			prevpid = -1
		else:
			raise RuntimeError("unknown event seen")
		print str(e.time).ljust(20)[:20] + "\t" + e.event.ljust(10) + "\t" + str(pid) + "\t" + str(prevpid) + "\t" + str(nextpid)

if printrows:
    rows = switch_events + wake_events
    rows =  sorted(rows, key=lambda r: r.time)
    print_event_rows(rows, 1.1, 1.2)