frame id visionicp

selfdrive/common/swaglog.h

@@ -22,7 +22,7 @@ void cloudlog_e(int levelnum, const char* filename, int lineno, const char* func
 #define cloudlog_t(lvl, event_name, frame_id, ...)                                 \
 {                                                                 \
   uint64_t ns = nanos_since_boot();                               \
-  std::string msg = std::string("{'timestamp': {'event':") + std::string(event_name) + std::string(",'frameId':")+ std::to_string(frame_id) + std::string(",'time':") + std::to_string(ns)+std::string("}}");   \
+  std::string msg = std::string("{'timestamp': {'event': '") + std::string(event_name) + std::string("' ,'frameId':")+ std::to_string(frame_id) + std::string(",'time':") + std::to_string(ns)+std::string("}}");   \
   cloudlog(lvl, msg.c_str(), ## __VA_ARGS__);                             \
 }
 

selfdrive/modeld/modeld.cc

@@ -89,11 +89,7 @@ void run_model(ModelState &model, VisionIpcClient &vipc_client_main, VisionIpcCl
       LOGE("vipc_client_main no frame");
       continue;
     }
-    // TODO: path planner timeout?
-    sm.update(0);
-    int desire = ((int)sm["lateralPlan"].getLateralPlan().getDesire());
-    frame_id = sm["roadCameraState"].getRoadCameraState().getFrameId();
-    LOGT("vicp read main", frame_id)
+    LOGT("vicp read main", meta_main.frame_id)
 
     if (use_extra_client) {
       // Keep receiving extra frames until frame id matches main camera
@@ -105,7 +101,7 @@ void run_model(ModelState &model, VisionIpcClient &vipc_client_main, VisionIpcCl
         LOGE("vipc_client_extra no frame");
         continue;
       }
-	LOGT("vicp read extra", frame_id)
+	LOGT("vicp read extra", meta_main.frame_id)
 
       if (std::abs((int64_t)meta_main.timestamp_sof - (int64_t)meta_extra.timestamp_sof) > 10000000ULL) {
         LOGE("frames out of sync! main: %d (%.5f), extra: %d (%.5f)",
@@ -118,6 +114,10 @@ void run_model(ModelState &model, VisionIpcClient &vipc_client_main, VisionIpcCl
       meta_extra = meta_main;
     }
 
+    // TODO: path planner timeout?
+    sm.update(0);
+    int desire = ((int)sm["lateralPlan"].getLateralPlan().getDesire());
+    frame_id = sm["roadCameraState"].getRoadCameraState().getFrameId();
     if (sm.updated("liveCalibration")) {
       auto extrinsic_matrix = sm["liveCalibration"].getLiveCalibration().getExtrinsicMatrix();
       Eigen::Matrix<float, 3, 4> extrinsic_matrix_eigen;
@@ -135,10 +135,10 @@ void run_model(ModelState &model, VisionIpcClient &vipc_client_main, VisionIpcCl
       vec_desire[desire] = 1.0;
     }
 
-    LOGT("Model start", frame_id);
+    LOGT("Model start", meta_main.frame_id);
     double mt1 = millis_since_boot();
     ModelOutput *model_output = model_eval_frame(&model, buf_main, buf_extra, model_transform_main, model_transform_extra, vec_desire);
-    LOGT("Model end", frame_id);
+    LOGT("Model end", meta_main.frame_id);
     double mt2 = millis_since_boot();
     float model_execution_time = (mt2 - mt1) / 1000.0;
 
@@ -157,7 +157,7 @@ void run_model(ModelState &model, VisionIpcClient &vipc_client_main, VisionIpcCl
                   kj::ArrayPtr<const float>(model.output.data(), model.output.size()), live_calib_seen);
     posenet_publish(pm, meta_main.frame_id, vipc_dropped_frames, *model_output, meta_main.timestamp_eof, live_calib_seen);
 
-    LOGT("Model published", frame_id);
+    LOGT("Model published", meta_main.frame_id);
 
     //printf("model process: %.2fms, from last %.2fms, vipc_frame_id %u, frame_id, %u, frame_drop %.3f\n", mt2 - mt1, mt1 - last, extra.frame_id, frame_id, frame_drop_ratio);
     last = mt1;

tools/latency_logging/graph_json.py

@@ -11,7 +11,7 @@ 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)
+gnt.set_xlim(0, 150)
 maxy = len(timestamps)
 gnt.set_ylim(0, maxy)
 
@@ -22,13 +22,16 @@ for frame_id, services in timestamps.items():
     t0 = min([min(events.values())for events in services.values()])
     service_bars = []
     event_bars = []
+    print(frame_id)
     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)
+            t = (time-t0)/1e6
+            event_bars.append((t, 1))
+            avg_times[service+"."+event].append(t)
+            print("    ", service+"."+event, t)
     gnt.broken_barh(service_bars, (count, 0.9), facecolors=("blue"))
     gnt.broken_barh(event_bars, (count, 0.9), facecolors=("black"))
     count+=1

tools/latency_logging/read_cloudlog.py

@@ -3,11 +3,26 @@ from tools.lib.route import Route
 from tools.lib.logreader import LogReader
 
 import json
+from collections import defaultdict
 
-r = Route("9f583b1d93915c31|2022-03-21--18-30-38")
+
+timestamps = defaultdict(lambda: defaultdict(lambda: defaultdict(int)))
+
+r = Route("9f583b1d93915c31|2022-03-21--19-26-32")
 lr = LogReader(r.log_paths()[0])
 
 for msg in lr:
   if msg.which() == "logMessage":
-    msg_json = json.loads(msg.logMessage)
-    print(msg_json['msg'])
+    msg = msg.logMessage.replace("'", '"').replace('"{', "{").replace('}"', "}")
+    if 'timestamp' in msg:
+        try:
+            jmsg = json.loads(msg)
+            frame_id = jmsg['msg']['timestamp']['frameId']
+            service = jmsg['ctx']['daemon']
+            event = jmsg['msg']['timestamp']['event']
+            time = jmsg['msg']['timestamp']['time']
+            timestamps[frame_id][service][event] = time
+        except :
+            print( msg)
+with open('timestamps.json', 'w') as outfile:
+    json.dump(timestamps, outfile)