graph json

cereal

@@ -1 +1 @@
-Subproject commit 4fbad0bd5d764edb269ecb2c8d2c72243fa6976c
+Subproject commit f546024f76a1d7d8f502f8cf67cb847e29327ba2

common/logging_extra.py

@@ -7,8 +7,9 @@ import uuid
 import socket
 import logging
 import traceback
+import time
 from threading import local
-from collections import OrderedDict
+from collections import OrderedDict, defaultdict
 from contextlib import contextmanager
 
 def json_handler(obj):
@@ -124,6 +125,12 @@ class SwagLogger(logging.Logger):
     self.log_local = local()
     self.log_local.ctx = {}
 
+    #TODO: do it similar to rest of code
+    self.timestamps = defaultdict(lambda: defaultdict(lambda: defaultdict(int)))
+  
+  def timestamp(self, frame_id, service, event):
+    self.timestamps[frame_id][service][event] = current_mili_time() 
+
   def local_ctx(self):
     try:
       return self.log_local.ctx

selfdrive/controls/controlsd.py

@@ -486,7 +486,7 @@ class Controls:
     long_plan = self.sm['longitudinalPlan']
 
     CC = car.CarControl.new_message()
-    # lat and long should give same Id
+    # lat and long should have the same id (and they have)
     CC.frameId = lat_plan.frameId
     CC.enabled = self.enabled
     # Check which actuators can be enabled

tools/latency_logging/graph_json.py

@@ -0,0 +1,36 @@
+import json
+import matplotlib.pyplot as plt
+import matplotlib.patches as mpatches
+from collections import defaultdict
+from tabulate import tabulate
+
+
+json_file = open('timestamps.json')
+timestamps = json.load(json_file)
+
+
+fig, gnt = plt.subplots()
+maxx = max([max([max(events.values()) for events in services.values()]) for services in timestamps.values()])/1e6
+gnt.set_xlim(0, maxx)
+maxy = len(timestamps)
+gnt.set_ylim(0, maxy)
+
+avg_times = defaultdict(list)
+
+count = 0
+for frame_id, services in timestamps.items():
+    t0 = min([min(events.values())for events in services.values()])
+    service_bars = []
+    event_bars = []
+    for service, events in services.items():
+        start = min(events.values())
+        end = max(events.values())
+        service_bars.append(((start-t0)/1e6, (end-start)/1e6))
+        for event, time in events.items():
+            event_bars.append(((time-t0)/1e6, maxx/300))
+            avg_times[service+"."+event].append((time-t0)/1e6)
+    gnt.broken_barh(service_bars, (count, 0.9), facecolors=("blue"))
+    gnt.broken_barh(event_bars, (count, 0.9), facecolors=("black"))
+    count+=1
+print(tabulate([[event, sum(times)/len(times), max(times), len(times)] for event, times in avg_times.items()], headers=["event", "avg", "max", "len"]))
+plt.show(block=True)

tools/latency_logging/latlog.py

@@ -28,17 +28,12 @@ avg_times = defaultdict(list)
 fig, gnt = plt.subplots()
 gnt.set_xlim(0, 150)
 gnt.set_ylim(0, len(frames))
-col_list = ['red', 'blue', 'green', 'cyan', 'magenta', 'yellow', 'olive', 'steelblue', 'deeppink', 'darkseagreen', 'coral', 'brown', 'gray']
-colors = {}
-for i, topic in enumerate(list(frames.values())[10].keys()):
-    colors[topic] = col_list[i]
-
+colors = {"road_cam_start":'red', "wide_cam_start":'blue', "driver_cam_start":'green', "road_cam_end":'cyan', "wide_cam_end":'magenta', "driver_cam_end":'yellow', 'roadCameraState':'olive', 'wideRoadCameraState':'steelblue', 'driverCameraState':'deeppink', 'modelV2':'darkseagreen', 'lateralPlan':'coral', 'longitudinalPlan':'brown', 'carControl':'gray'}
 
 count = 0
 for frame, times in frames.items():
     t0 = min(times.values())
     events = {}
-    #for topic, time in dict(sorted(times.items(), key= lambda x: x[1])).items():
     for topic, time in times.items():
         #print("     ", topic, (time-t0)/1e6)
         events[((time-t0)/1e6, 0.3)] = colors[topic]

tools/latency_logging/timestamps.json

@@ -0,0 +1,48 @@
+{
+  "1": {
+    "camerad":{
+      "start_driver": 100000000,
+      "start_road": 110000000,
+      "end_driver": 10000000000,
+      "end_road": 12000000000
+    },
+    "modeld":{
+      "event":20000000000,
+      "another_event":23000000000,
+      "last_event":22000000000
+    },
+    "planner":{
+      "event":40000000000,
+      "another_event":41000000000,
+      "last_event":45000000000
+    },
+    "controls":{
+      "event":80000000000,
+      "another_event":83000000000,
+      "last_event":78000000000
+    }
+  },
+  "2": {
+    "camerad":{
+      "start_driver": 130000000,
+      "start_road": 120000000,
+      "end_driver": 11000000000,
+      "end_road": 14000000000
+    },
+    "modeld":{
+      "event":28000000000,
+      "another_event":29000000000,
+      "last_event":27000000000
+    },
+    "planner":{
+      "event":48000000000,
+      "another_event":42000000000,
+      "last_event":49000000000
+    },
+    "controls":{
+      "event":83000000000,
+      "another_event":89000000000,
+      "last_event":73000000000
+    }
+  }
+}