feat: add TTFS instrumentation to run_inference pipeline

Log timestamps at each step from video open through model loading,
worker start, first GPU inference, and first stream publish so
bottlenecks are visible in logs.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

inference.py

@@ -614,8 +614,15 @@ def run_inference(
     depth_scale: float = 1.0,
     stream_queue: Optional[Queue] = None,
     first_frame_detections: Optional[List[Dict[str, Any]]] = None,
+    _ttfs_t0: Optional[float] = None,
 ) -> Tuple[str, List[List[Dict[str, Any]]]]:
-    
+
+    def _ttfs(msg):
+        if _ttfs_t0 is not None:
+            logging.info("[TTFS:%s] +%.1fs %s", job_id, time.perf_counter() - _ttfs_t0, msg)
+
+    _ttfs("enter run_inference")
+
     # 1. Setup Video Reader
     try:
         reader = AsyncVideoReader(input_video_path)
@@ -627,18 +634,20 @@ def run_inference(
     width = reader.width
     height = reader.height
     total_frames = reader.total_frames
-    
+
     if max_frames is not None:
         total_frames = min(total_frames, max_frames)
 
+    _ttfs(f"video_opened ({total_frames} frames, {width}x{height}, {fps:.1f}fps)")
+
     # 2. Defaults and Config
     if not queries:
         queries = ["person", "car", "truck", "motorcycle", "bicycle", "bus", "train", "airplane"]
         logging.info("No queries provided, using defaults: %s", queries)
-    
+
     logging.info("Detection queries: %s", queries)
     active_detector = detector_name or "yolo11"
-    
+
     # Parallel Model Loading
     num_gpus = torch.cuda.device_count()
     detectors = []
@@ -686,6 +695,8 @@ def run_inference(
         else:
             depth_estimators.append(None)
 
+    _ttfs(f"models_loaded ({active_detector}, {num_gpus} GPUs, depth={'yes' if depth_estimator_name else 'no'})")
+
     # 4. Incremental Depth Stats (replaces expensive pre-scan)
     depth_stats = IncrementalDepthStats(warmup_frames=30) if depth_estimator_name else None
 
@@ -854,13 +865,13 @@ def run_inference(
     # 6. Start Workers
     workers = []
     num_workers = len(detectors)
-    # If using CPU, maybe use more threads? No, CPU models usually multithread internally.
-    # If using GPU, 1 thread per GPU is efficient.
     for i in range(num_workers):
         t = Thread(target=worker_task, args=(i,), daemon=True)
         t.start()
         workers.append(t)
 
+    _ttfs(f"workers_started ({num_workers} GPU workers)")
+
     # 7. Start Writer / Output Collection (Main Thread or separate)
     # We will run writer logic in the main thread after feeding is done? 
     # No, we must write continuously.
@@ -871,8 +882,10 @@ def run_inference(
     # writer_finished = False 
 
     
+    _first_frame_published = False
+
     def writer_loop():
-        nonlocal writer_finished
+        nonlocal writer_finished, _first_frame_published
         next_idx = 0
         buffer = {}
 
@@ -896,6 +909,9 @@ def run_inference(
                             idx, p_frame, dets = item
                             buffer[idx] = (p_frame, dets)
 
+                        if next_idx == 0:
+                            _ttfs("first_frame_dequeued_from_gpu")
+
                         # Write next_idx
                         p_frame, dets = buffer.pop(next_idx)
 
@@ -921,6 +937,9 @@ def run_inference(
                                 _publish(job_id, p_frame)
                             else:
                                 stream_queue.put(p_frame)
+                            if not _first_frame_published:
+                                _first_frame_published = True
+                                _ttfs("first_frame_published_to_stream")
 
                         all_detections_map[next_idx] = dets
 
@@ -963,7 +982,8 @@ def run_inference(
     writer_thread = Thread(target=writer_loop, daemon=True)
     writer_thread.start()
 
-    # 8. Feed Frames (Main Thread)
+    _ttfs("writer_thread_started")
+
     # 8. Feed Frames (Main Thread)
     try:
         frames_fed = 0
@@ -979,6 +999,8 @@ def run_inference(
                 break
                 
             queue_in.put((frames_fed, frame)) # Blocks if full
+            if frames_fed == 0:
+                _ttfs("first_frame_fed_to_gpu")
             frames_fed += 1
             
         logging.info("Feeder finished. Fed %d frames (expected %d)", frames_fed, total_frames)

jobs/background.py

@@ -50,9 +50,11 @@ async def process_video_async(job_id: str) -> None:
                 None,
                 job.detector_name,
                 job_id,
-                job.depth_estimator_name, # Pass depth estimator to trigger unified loop
+                job.depth_estimator_name,
                 job.depth_scale,
                 stream_queue,
+                None,  # first_frame_detections
+                job.ttfs_t0,
             )
             detection_path, detections_list = result_pkg