1#!/usr/bin/env python 2 3from collections import namedtuple 4import trappy 5import argparse 6 7EventData = namedtuple('EventData', ['time', 'event', 'data']) 8LatData = namedtuple('LatData', ['pid', 'switch_data', 'wake_data', 'last_wake_data', 'running', 'wake_pend', 'latency', 'lat_total']) 9 10# path_to_html = "/home/joelaf/repo/catapult/systrace/trace_sf-dispsync_rt_pull_fail_1504ms.html" 11# path_to_html = "/home/joelaf/Downloads/trace_sf_late_wakeup_ipi.html" 12# path_to_html = "/home/joelaf/repo/lisa/results/ChromeMonkey/trace.html" 13 14parser = argparse.ArgumentParser(description='Analyze runnable times') 15 16parser.add_argument('--trace', dest='trace_file', action='store', required=True, 17 help='trace file') 18 19parser.add_argument('--rt', dest='rt', action='store_true', default=False, 20 help='only consider RT tasks') 21 22parser.add_argument('--normalize', dest='normalize', action='store_true', default=False, 23 help='normalize time') 24 25parser.add_argument('--rows', dest='nrows', action='store', default=20, type=int, 26 help='normalize time') 27 28parser.add_argument('--total', dest='lat_total', action='store_true', default=False, 29 help='sort by total runnable time') 30 31parser.add_argument('--start-time', dest='start_time', action='store', default=0, type=float, 32 help='trace window start time') 33 34parser.add_argument('--end-time', dest='end_time', action='store', default=None, type=float, 35 help='trace window end time') 36 37args = parser.parse_args() 38 39path_to_html = args.trace_file 40rtonly = args.rt 41nrows = args.nrows 42 43# "/home/joelaf/repo/lisa-aosp/results/camera-trace-manual/trace.html" 44# path_to_html = "/home/joelaf/repo/catapult/systrace/trace_sf-dispsync_rt_pull_fail_1504ms.html" 45# path_to_html = "/home/joelaf/Downloads/trace_sf_late_wakeup_ipi.html" 46# path_to_html = "/home/joelaf/repo/lisa/results/ChromeMonkey/trace.html" 47 48 49# Hash table of pid -> LatData named tuple 50latpids = {} 51 52# Debugging aids for debugging within the callbacks 53dpid = 21047 54debugg = False 55 56normalize = False # Normalize with the base timestamp 57printrows = False # Debug aid to print all switch and wake events in a time range 58 59switch_events = [] 60wake_events = [] 61basetime = None 62 63def switch_cb(data): 64 event = "switch" 65 prevpid = data['prev_pid'] 66 nextpid = data['next_pid'] 67 time = data['Index'] 68 69 # print str(time) + ": " + str(data) 70 71 global basetime, switch_events 72 # basetime = time if (normalize and not basetime) else basetime 73 # time = time - basetime if normalize else time 74 75 e = EventData(time, event, data) 76 if printrows: 77 switch_events.append(e) 78 79 debug = False # debugg and (prevpid == dpid or nextpid == dpid) 80 if debug: print ("\nProcessing switch nextpid=" + str(nextpid) + " prevpid=" + str(prevpid) + \ 81 " time=" + str(time)) 82 83 # prev pid processing (switch out) 84 if latpids.has_key(prevpid): 85 if latpids[prevpid].running == 1: 86 latpids[prevpid] = latpids[prevpid]._replace(running=0) 87 if latpids[prevpid].wake_pend == 1: 88 print "Impossible: switch out during wake_pend " + str(e) 89 latpids[prevpid] = latpids[prevpid]._replace(wake_pend=0) 90 return 91 # raise RuntimeError("error") 92 93 if not latpids.has_key(nextpid): 94 return 95 96 # nextpid processing (switch in) 97 pid = nextpid 98 if latpids[pid].running == 1: 99 print "INFO: previous pid switch-out not seen for an event, ignoring\n" + str(e) 100 return 101 latpids[pid] = latpids[pid]._replace(running=1) 102 103 # Ignore latency calc for next-switch events for which wake never seen 104 # They are still valid in this scenario because of preemption 105 if latpids[pid].wake_pend == 0: 106 if debug: print "wake_pend = 0, doing nothing" 107 return 108 109 if debug: print "recording" 110 # Measure latency 111 lat = time - latpids[pid].last_wake_data.time 112 total = latpids[pid].lat_total + lat 113 latpids[pid] = latpids[pid]._replace(lat_total=total) 114 115 if lat > latpids[pid].latency: 116 latpids[pid] = LatData(pid, switch_data = e, 117 wake_data = latpids[pid].last_wake_data, 118 last_wake_data=None, latency=lat, lat_total=latpids[pid].lat_total, running=1, wake_pend=0) 119 return 120 latpids[pid] = latpids[pid]._replace(running=1, wake_pend=0) 121 122def wake_cb(data): 123 event = "wake" 124 pid = data['pid'] 125 time = data['Index'] 126 debug = False # debugg and (pid == dpid) 127 128 global basetime, wake_events 129 # basetime = time if (normalize and not basetime) else basetime 130 # time = time - basetime if normalize else time 131 132 e = EventData(time, event, data) 133 wake_events.append(e) 134 135 if rtonly and data["prio"] > 99: 136 return 137 138 if debug: print "\nProcessing wake pid=" + str(pid) + " time=" + str(time) 139 if not latpids.has_key(pid): 140 latpids[pid] = LatData(pid, switch_data=None, wake_data=None, 141 last_wake_data = e, running=0, latency=-1, lat_total=0, wake_pend=1) 142 if debug: print "new wakeup" 143 return 144 145 if latpids[pid].running == 1 or latpids[pid].wake_pend == 1: 146 if debug: print "already running or wake_pend" 147 # Task already running or a wakeup->switch pending, ignore 148 return 149 150 if debug: print "recording wake" 151 latpids[pid] = latpids[pid]._replace(last_wake_data = e, wake_pend=1) 152 153 154if args.normalize: 155 kwargs = { 'window': (args.start_time, args.end_time) } 156else: 157 kwargs = { 'abs_window': (args.start_time, args.end_time) } 158 159systrace_obj = trappy.SysTrace(name="systrace", path=path_to_html, \ 160 scope="sched", events=["sched_switch", "sched_wakeup", "sched_waking"], normalize_time=args.normalize, **kwargs) 161 162systrace_obj.apply_callbacks({ "sched_switch": switch_cb, "sched_wakeup": wake_cb, \ 163 "sched_waking": wake_cb }) 164 165# Print the results: PID, latency, start, end, sort 166if args.lat_total: 167 result = sorted(latpids.items(), key=lambda x: x[1].lat_total, reverse=True) 168else: 169 result = sorted(latpids.items(), key=lambda x: x[1].latency, reverse=True) 170 171print "PID".ljust(10) + "\t" + "name".ljust(20) + "\t" + "latency (secs)".ljust(20) + \ 172 "\t" + "start time".ljust(20) + "\t" + "end time".ljust(20) + "\t" + "total (secs)".ljust(20) 173for r in result[:nrows]: 174 l = r[1] # LatData named tuple 175 if l.pid != r[0]: 176 raise RuntimeError("BUG: pid inconsitency found") # Sanity check 177 wake_time = l.wake_data.time 178 switch_time = l.switch_data.time 179 total = l.lat_total 180 181 print str(r[0]).ljust(10) + "\t" + str(l.wake_data.data['comm']).ljust(20) + "\t" + \ 182 str(l.latency).ljust(20)[:20] + "\t" + str(wake_time).ljust(20)[:20] + \ 183 "\t" + str(switch_time).ljust(20)[:20] + "\t" + str(total).ljust(20)[:20] 184 185############################################################# 186## Debugging aids to print all events in a given time range # 187############################################################# 188def print_event_rows(events, start, end): 189 print "time".ljust(20) + "\t" + "event".ljust(10) + "\tpid" + "\tprevpid" + "\tnextpid" 190 for e in events: 191 if e.time < start or e.time > end: 192 continue 193 if e.event == "switch": 194 nextpid = e.data['next_pid'] 195 prevpid = e.data['prev_pid'] 196 pid = -1 197 elif e.event == "wake": 198 pid = e.data['pid'] 199 nextpid = -1 200 prevpid = -1 201 else: 202 raise RuntimeError("unknown event seen") 203 print str(e.time).ljust(20)[:20] + "\t" + e.event.ljust(10) + "\t" + str(pid) + "\t" + str(prevpid) + "\t" + str(nextpid) 204 205if printrows: 206 rows = switch_events + wake_events 207 rows = sorted(rows, key=lambda r: r.time) 208 print_event_rows(rows, 1.1, 1.2) 209