diff --git a/tools/latencylogger/latency_logger.py b/tools/latencylogger/latency_logger.py index 47c4347166..b03dc84f61 100644 --- a/tools/latencylogger/latency_logger.py +++ b/tools/latencylogger/latency_logger.py @@ -8,7 +8,7 @@ from collections import defaultdict from tools.lib.logreader import logreader_from_route_or_segment -DEMO_ROUTE = "9f583b1d93915c31|2022-04-06--11-34-03" +DEMO_ROUTE = "9f583b1d93915c31|2022-04-26--18-49-49" SERVICES = ['camerad', 'modeld', 'plannerd', 'controlsd', 'boardd'] # Retrive controlsd frameId from lateralPlan, mismatch with longitudinalPlan will be ignored @@ -32,6 +32,7 @@ def read_logs(lr): data = defaultdict(lambda: defaultdict(lambda: defaultdict(list))) mono_to_frame = {} frame_mismatches = [] + frame_id_fails = 0 latest_sendcan_monotime = 0 for msg in lr: if msg.which() == 'sendcan': @@ -56,6 +57,9 @@ def read_logs(lr): frame_id = mono_to_frame[getattr(msg_obj, key)] if continue_outer: continue + if frame_id == -1: + frame_id_fails += 1 + continue mono_to_frame[msg.logMonoTime] = frame_id data['timestamp'][frame_id][service].append((msg.which()+" published", msg.logMonoTime)) @@ -79,9 +83,7 @@ def read_logs(lr): if msg_obj.frameIdExtra != frame_id: frame_mismatches.append(frame_id) - # Failed frameId fetches are stored in -1 - assert sum([len(data['timestamp'][-1][service]) for service in data['timestamp'][-1].keys()]) < 20, "Too many frameId fetch fails" - del data['timestamp'][-1] + assert frame_id_fails < 20, "Too many frameId fetch fails" assert len(frame_mismatches) < 20, "Too many frame mismatches" return (data, frame_mismatches) @@ -91,9 +93,20 @@ def find_frame_id(time, service, start_times, end_times): if start_times[frame_id][service] <= time <= end_times[frame_id][service]: yield frame_id +def find_t0(start_times, frame_id=-1): + frame_id = frame_id if frame_id > -1 else min(start_times.keys()) + m = max(start_times.keys()) + while frame_id <= m: + for service in SERVICES: + if service in start_times[frame_id]: + return start_times[frame_id][service] + frame_id += 1 + raise Exception('No start time has been set') + + ## ASSUMES THAT AT LEAST ONE CLOUDLOG IS MADE IN CONTROLSD def insert_cloudlogs(lr, timestamps, start_times, end_times): - t0 = start_times[min(start_times.keys())][SERVICES[0]] + t0 = find_t0(start_times) failed_inserts = 0 latest_controls_frameid = 0 for msg in lr: @@ -129,12 +142,13 @@ def insert_cloudlogs(lr, timestamps, start_times, end_times): assert failed_inserts < len(timestamps), "Too many failed cloudlog inserts" def print_timestamps(timestamps, durations, start_times, relative): - t0 = start_times[min(start_times.keys())][SERVICES[0]] + t0 = find_t0(start_times) for frame_id in timestamps.keys(): print('='*80) print("Frame ID:", frame_id) if relative: - t0 = start_times[frame_id][SERVICES[0]] + t0 = find_t0(start_times, frame_id) + for service in SERVICES: print(" "+service) events = timestamps[frame_id][service] @@ -144,10 +158,11 @@ def print_timestamps(timestamps, durations, start_times, relative): print(" "+'%-53s%-53s' %(event, str(time*1000))) def graph_timestamps(timestamps, start_times, end_times, relative): - t0 = start_times[min(start_times.keys())][SERVICES[0]] + t0 = find_t0(start_times) + y0 = min(start_times.keys()) fig, ax = plt.subplots() ax.set_xlim(0, 150 if relative else 750) - ax.set_ylim(0, 15) + ax.set_ylim(y0, y0+15) ax.set_xlabel('milliseconds') ax.set_ylabel('Frame ID') colors = ['blue', 'green', 'red', 'yellow', 'purple'] @@ -156,7 +171,7 @@ def graph_timestamps(timestamps, start_times, end_times, relative): points = {"x": [], "y": [], "labels": []} for frame_id, services in timestamps.items(): if relative: - t0 = start_times[frame_id][SERVICES[0]] + t0 = find_t0(start_times, frame_id) service_bars = [] for service, events in services.items(): if start_times[frame_id][service] and end_times[frame_id][service]: diff --git a/tools/lib/logreader.py b/tools/lib/logreader.py index 06dd248bf1..1ad9474701 100755 --- a/tools/lib/logreader.py +++ b/tools/lib/logreader.py @@ -107,9 +107,9 @@ def logreader_from_route_or_segment(r, sort_by_time=False): sn = SegmentName(r, allow_route_name=True) route = Route(sn.route_name.canonical_name) if sn.segment_num < 0: - return MultiLogIterator(route.log_paths(), sort_by_time) + return MultiLogIterator(route.log_paths(), sort_by_time=sort_by_time) else: - return LogReader(route.log_paths()[sn.segment_num], sort_by_time) + return LogReader(route.log_paths()[sn.segment_num], sort_by_time=sort_by_time) if __name__ == "__main__":