1#!/usr/bin/env python
2
3from time import gmtime, strftime
4from collections import namedtuple
5import trappy, os, sys
6import numpy as np
7import pandas as pd
8import argparse
9
10class RunData:
11    def __init__(self, pid, comm, time):
12        self.pid = pid
13        self.comm = comm
14        self.last_start_time = time
15        self.total_time = np.float64(0.0)
16        self.start_time = -1
17        self.end_time = -1
18        self.running = 1
19        self.maxrun = -1
20
21parser = argparse.ArgumentParser(description='Analyze runnable times')
22
23parser.add_argument('--trace', dest='trace_file', action='store', required=True,
24                    help='trace file')
25
26parser.add_argument('--rt', dest='rt', action='store_true', default=False,
27                    help='only consider RT tasks')
28
29parser.add_argument('--normalize', dest='normalize', action='store_true', default=False,
30                    help='normalize time')
31
32parser.add_argument('--rows', dest='nrows', action='store', default=20, type=int,
33                    help='normalize time')
34
35parser.add_argument('--total', dest='lat_total', action='store_true', default=False,
36                    help='sort by total runnable time')
37
38parser.add_argument('--start-time', dest='start_time', action='store', default=0, type=float,
39                    help='trace window start time')
40
41parser.add_argument('--end-time', dest='end_time', action='store', default=None, type=float,
42                    help='trace window end time')
43
44args = parser.parse_args()
45
46path_to_html = args.trace_file
47rtonly = args.rt
48nrows = args.nrows
49
50# Hash table for runtimes
51runpids = {}
52
53# Debugging aids for debugging within the callbacks
54dpid = -1       # Debug all pids
55debugg = False  # Global debug switch
56printrows = False   # Debug aid to print all switch and wake events in a time range
57
58switch_events = []
59
60starttime = None
61endtime = None
62
63def switch_cb(data):
64    global starttime, endtime, dpid
65
66    prevpid = data['prev_pid']
67    nextpid = data['next_pid']
68    time = data['Index']
69
70    if not starttime:
71        starttime = time
72    endtime = time
73
74    debug = (dpid == prevpid or dpid == nextpid or dpid == -1) and debugg
75
76    if debug:
77        print "{}: {} {} -> {} {}".format(time, prevpid, data['prev_comm'], nextpid, data['next_comm'])
78
79    if prevpid != 0:
80       # prev pid processing (switch out)
81        if runpids.has_key(prevpid):
82            rp = runpids[prevpid]
83            if rp.running == 1:
84                rp.running = 0
85                runtime = time - rp.last_start_time
86                if runtime > rp.maxrun:
87                    rp.maxrun = runtime
88                    rp.start_time = rp.last_start_time
89                    rp.end_time = time
90                rp.total_time += runtime
91                if debug and dpid == prevpid: print 'adding to total time {}, new total {}'.format(runtime, rp.total_time)
92
93            else:
94                print 'switch out seen while no switch in {}'.format(prevpid)
95        else:
96            print 'switch out seen while no switch in {}'.format(prevpid)
97
98    if nextpid == 0:
99        return
100
101    # nextpid processing  (switch in)
102    if not runpids.has_key(nextpid):
103        # print 'creating data for nextpid {}'.format(nextpid)
104        rp = RunData(nextpid, data['next_comm'], time)
105        runpids[nextpid] = rp
106        return
107
108    rp = runpids[nextpid]
109    if rp.running == 1:
110        print 'switch in seen for already running task {}'.format(nextpid)
111        return
112
113    rp.running = 1
114    rp.last_start_time = time
115
116
117if args.normalize:
118    kwargs = { 'window': (args.start_time, args.end_time) }
119else:
120    kwargs = { 'abs_window': (args.start_time, args.end_time) }
121
122systrace_obj = trappy.SysTrace(name="systrace", path=path_to_html, \
123        scope="sched", events=["sched_switch"], normalize_time=args.normalize, **kwargs)
124
125ncpus = systrace_obj.sched_switch.data_frame["__cpu"].max() + 1
126print 'cpus found: {}\n'.format(ncpus)
127
128systrace_obj.apply_callbacks({ "sched_switch": switch_cb })
129
130## Print results
131testtime = (endtime - starttime) * ncpus              # for 4 cpus
132print "total test time (scaled by number of CPUs): {} secs".format(testtime)
133
134# Print the results: PID, latency, start, end, sort
135result = sorted(runpids.items(), key=lambda x: x[1].total_time, reverse=True)
136print "PID".ljust(10) + "\t" + "name".ljust(15) + "\t" + "max run (secs)".ljust(15) + \
137      "\t" + "start time".ljust(15) + "\t" + "end time".ljust(15) + "\t" + "total runtime".ljust(15) + "\t" + "percent cpu".ljust(15) \
138      + "\t" + "totalpc"
139
140totalpc = np.float64(0.0)
141for r in result[:nrows]:
142	rd = r[1] # RunData named tuple
143	if rd.pid != r[0]:
144		raise RuntimeError("BUG: pid inconsitency found") # Sanity check
145        start = rd.start_time
146        end = rd.end_time
147        cpupc = (rd.total_time / testtime) * 100
148        totalpc += cpupc
149
150	print str(r[0]).ljust(10) + "\t" + str(rd.comm).ljust(15) + "\t" + \
151		  str(rd.maxrun).ljust(15)[:15] + "\t" + str(start).ljust(15)[:15] + \
152		  "\t" + str(end).ljust(15)[:15] + "\t" + str(rd.total_time).ljust(15) + \
153                    "\t" + str(cpupc) \
154                    + "\t" + str(totalpc)
155
156#############################################################
157## Debugging aids to print all events in a given time range #
158#############################################################
159def print_event_rows(events, start, end):
160	print "time".ljust(20) + "\t" + "event".ljust(10) + "\tpid" + "\tprevpid" + "\tnextpid"
161	for e in events:
162		if e.time < start or e.time > end:
163			continue
164		if e.event == "switch":
165			nextpid =  e.data['next_pid']
166			prevpid = e.data['prev_pid']
167			pid = -1
168		elif e.event == "wake":
169			pid = e.data['pid']
170			nextpid = -1
171			prevpid = -1
172		else:
173			raise RuntimeError("unknown event seen")
174		print str(e.time).ljust(20)[:20] + "\t" + e.event.ljust(10) + "\t" + str(pid) + "\t" + str(prevpid) + "\t" + str(nextpid)
175
176if printrows:
177    rows = switch_events + wake_events
178    rows =  sorted(rows, key=lambda r: r.time)
179    print_event_rows(rows, 1.1, 1.2)
180