1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
|
#!/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)
|
