more logging

selfdrive/camerad/cameras/camera_common.cc

@@ -376,11 +376,13 @@ void *processing_thread(MultiCameraState *cameras, CameraState *cs, process_thre
   while (!do_exit) {
     if (!cs->buf.acquire()) continue;
 
+    //TODO: is this frame id fake, maybe it is created in the callback
     uint32_t frame_id = cs->buf.cur_frame_data.frame_id;
     LOGT((std::string(thread_name)+std::string(": Start")).c_str(), frame_id);
 
     callback(cameras, cs, cnt);
 
+    LOGT((std::string(thread_name)+std::string(": END")).c_str(), frame_id);
 
     if (cs == &(cameras->road_cam) && cameras->pm && cnt % 100 == 3) {
       // this takes 10ms???
@@ -447,7 +449,10 @@ void common_process_driver_camera(MultiCameraState *s, CameraState *c, int cnt)
   if (env_send_driver) {
     framed.setImage(get_frame_image(&c->buf));
   }
+  uint32_t frame_id = c->buf.cur_frame_data.frame_id;
+  LOGT("DriverCamera: Image set", frame_id);
   s->pm->send("driverCameraState", msg);
+  LOGT("DriverCamera: Published", frame_id);
 }
 
 

selfdrive/camerad/cameras/camera_qcom2.cc

@@ -1032,10 +1032,14 @@ void process_road_camera(MultiCameraState *s, CameraState *c, int cnt) {
   if ((c == &s->road_cam && env_send_road) || (c == &s->wide_road_cam && env_send_wide_road)) {
     framed.setImage(get_frame_image(b));
   }
+  uint32_t frame_id = c->buf.cur_frame_data.frame_id;
+  LOGT((std::string(c == &s->road_cam ? "RoadCamera" : "WideRoadCamera")+std::string(": Image set")).c_str(), frame_id);
   if (c == &s->road_cam) {
     framed.setTransform(b->yuv_transform.v);
+    LOGT((std::string(c == &s->road_cam ? "RoadCamera" : "WideRoadCamera")+std::string(": Transformed")).c_str(), frame_id);
   }
   s->pm->send(c == &s->road_cam ? "roadCameraState" : "wideRoadCameraState", msg);
+  LOGT((std::string(c == &s->road_cam ? "RoadCamera" : "WideRoadCamera")+std::string(": Published")).c_str(), frame_id);
 
   const auto [x, y, w, h] = (c == &s->wide_road_cam) ? std::tuple(96, 250, 1734, 524) : std::tuple(96, 160, 1734, 986);
   const int skip = 2;

selfdrive/controls/controlsd.py

@@ -633,7 +633,7 @@ class Controls:
       self.last_actuators, can_sends = self.CI.apply(CC)
       sendcan_msg = can_list_to_can_capnp(can_sends, msgtype='sendcan')
       self.pm.send('sendcan', sendcan_msg , valid=CS.canValid)
-      cloudlog.event("translate", logMonoTime=sendcan_msg.logMonoTime, frameId=frame_id)
+      cloudlog.event("translation", logMonoTime=sendcan_msg.logMonoTime, frameId=frame_id, debug=True)
       cloudlog.timestamp("sendcan Published", frame_id)
       CC.actuatorsOutput = self.last_actuators
 

tools/latency_logging/graph_json.py

@@ -18,7 +18,7 @@ for frame_id, services in timestamps.items():
             time = (time-t0)/1e6
             d[time] = (service, event)
     s = sorted(d.items())
-    print(tabulate([[item[1][0], item[1][1], item[0]] for item in s], headers=["service", "event", "time"]))
+    print(tabulate([[item[1][0], item[1][1], item[0]] for item in s], headers=["service", "event", "time (ms)"]))
     print()
 
 exit()

tools/latency_logging/read_cloudlog.py

@@ -8,9 +8,16 @@ from collections import defaultdict
 
 timestamps = defaultdict(lambda: defaultdict(lambda: defaultdict(list)))
 
-r = Route("9f583b1d93915c31|2022-03-22--15-59-29")
+#r = Route("9f583b1d93915c31|2022-03-22--15-59-29")
+r = Route("9f583b1d93915c31|2022-03-22--18-06-12")
 lr = LogReader(r.log_paths()[0])
 
+for msg in lr:
+    if msg.which() == "logMessage":
+        msg = msg.logMessage.replace("'", '"').replace('"{', "{").replace('}"', "}")
+        if "logMonoTime" in msg:
+            print(msg)
+exit()
 for msg in lr:
   if msg.which() == "logMessage":
     msg = msg.logMessage.replace("'", '"').replace('"{', "{").replace('}"', "}")
@@ -21,9 +28,12 @@ for msg in lr:
             service = jmsg['ctx']['daemon']
             event = jmsg['msg']['timestamp']['event']
             time = jmsg['msg']['timestamp']['time']
-            timestamps[frame_id][service][event].append(time)
+            if jmsg['msg']['timestamp']['translate']:
+                timestamps[frame_id][service][event].append()
+            else:
+                timestamps[frame_id][service][event].append(time)
         except :
-            print( msg)
+            print(msg)
 
 del timestamps[0]