#!/usr/bin/env python # SPDX-License-Identifier: Apache-2.0 # # Copyright (C) 2017, ARM Limited, Google, and contributors. # # Licensed under the Apache License, Version 2.0 (the "License"); you may # not use this file except in compliance with the License. # You may obtain a copy of the License at # # http://www.apache.org/licenses/LICENSE-2.0 # # Unless required by applicable law or agreed to in writing, software # distributed under the License is distributed on an "AS IS" BASIS, WITHOUT # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. # 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)