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