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