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