feat: add job processing timing and latency measurements to backend and frontend

app.py

@@ -28,6 +28,7 @@ except Exception as e:
 import asyncio
 import shutil
 import tempfile
+import time
 import uuid
 from contextlib import asynccontextmanager
 from datetime import timedelta
@@ -88,6 +89,7 @@ async def _enrich_first_frame_gpt(
     """
     if not enable_gpt or not detections:
         return
+    t_gpt_start = time.monotonic()
     try:
         # Non-LLM_EXTRACTED relevance filter runs BEFORE run_enrichment (FAST_PATH case)
         if mission_spec and mission_spec.parse_mode != "LLM_EXTRACTED":
@@ -99,7 +101,13 @@ async def _enrich_first_frame_gpt(
             if not filtered:
                 for det in detections:
                     det["assessment_status"] = AssessmentStatus.ASSESSED
-                get_job_storage().update(job_id, first_frame_detections=detections)
+                gpt_elapsed = time.monotonic() - t_gpt_start
+                logging.info("TIMING gpt_first_frame=%.3fs for job %s (all non-relevant)", gpt_elapsed, job_id)
+                get_job_storage().update(
+                    job_id,
+                    first_frame_detections=detections,
+                    timing_gpt_first_frame_s=gpt_elapsed,
+                )
                 logging.info("All detections non-relevant for job %s; marked ASSESSED", job_id)
                 return
 
@@ -107,13 +115,19 @@ async def _enrich_first_frame_gpt(
             run_enrichment, 0, frame, detections, mission_spec,
             job_id=job_id,
         )
+        gpt_elapsed = time.monotonic() - t_gpt_start
+        logging.info("TIMING gpt_first_frame=%.3fs for job %s", gpt_elapsed, job_id)
         logging.info("Background GPT enrichment complete for job %s", job_id)
 
         if not gpt_results:
             # All detections filtered as not relevant
             for det in detections:
                 det["assessment_status"] = AssessmentStatus.ASSESSED
-            get_job_storage().update(job_id, first_frame_detections=detections)
+            get_job_storage().update(
+                job_id,
+                first_frame_detections=detections,
+                timing_gpt_first_frame_s=gpt_elapsed,
+            )
             logging.info("All detections non-relevant for job %s; marked ASSESSED", job_id)
             return
 
@@ -127,6 +141,7 @@ async def _enrich_first_frame_gpt(
             job_id,
             first_frame_detections=detections,
             first_frame_gpt_results=gpt_results,
+            timing_gpt_first_frame_s=gpt_elapsed,
         )
         logging.info("Updated first_frame_detections with GPT results for job %s", job_id)
 
@@ -410,6 +425,7 @@ async def detect_async_endpoint(
         raise HTTPException(status_code=400, detail="Video file is required.")
 
     job_id = uuid.uuid4().hex
+    t_job_start = time.monotonic()
     job_dir = get_job_directory(job_id)
     input_path = get_input_video_path(job_id)
     output_path = get_output_video_path(job_id)
@@ -482,6 +498,8 @@ async def detect_async_endpoint(
             segmenter_name=segmenter,
         )
         cv2.imwrite(str(first_frame_path), processed_frame)
+        first_frame_elapsed = time.monotonic() - t_job_start
+        logging.info("TIMING first_frame=%.3fs for job %s", first_frame_elapsed, job_id)
         # GPT and depth are now handled in the async pipeline (enrichment thread)
         depth_map = None
         first_frame_gpt_results = None
@@ -509,6 +527,7 @@ async def detect_async_endpoint(
         mission_spec=mission_spec,
         mission_mode=mission_mode,
         first_frame_gpt_results=first_frame_gpt_results,
+        timing_first_frame_s=first_frame_elapsed,
     )
     get_job_storage().create(job)
     asyncio.create_task(process_video_async(job_id))
@@ -563,6 +582,13 @@ async def detect_status(job_id: str):
         "completed_at": job.completed_at.isoformat() if job.completed_at else None,
         "error": job.error,
         "first_frame_detections": job.first_frame_detections,
+        "timing": {
+            "first_frame_s": job.timing_first_frame_s,
+            "video_processing_s": job.timing_video_processing_s,
+            "gpt_first_frame_s": job.timing_gpt_first_frame_s,
+            "gpt_enrichment_s": job.timing_gpt_enrichment_s,
+            "total_s": job.timing_total_s,
+        },
     }
 
 

frontend/js/api/client.js

@@ -192,6 +192,18 @@ APP.api.client.pollAsyncJob = async function () {
                         syncGpt(status.first_frame_detections, "final sync");
                     }
 
+                    // Display timing summary
+                    if (status.timing) {
+                        const t = status.timing;
+                        const parts = [];
+                        if (t.first_frame_s != null) parts.push(`1st frame: ${t.first_frame_s.toFixed(2)}s`);
+                        if (t.video_processing_s != null) parts.push(`video: ${t.video_processing_s.toFixed(2)}s`);
+                        if (t.gpt_first_frame_s != null) parts.push(`GPT: ${t.gpt_first_frame_s.toFixed(2)}s`);
+                        if (t.gpt_enrichment_s != null) parts.push(`GPT enrich: ${t.gpt_enrichment_s.toFixed(2)}s`);
+                        if (t.total_s != null) parts.push(`total: ${t.total_s.toFixed(2)}s`);
+                        if (parts.length) log(`Timing: ${parts.join(" | ")}`, "t");
+                    }
+
                     try {
                         await fetchProcessedVideo();
                         await fetchDepthVideo();

inference.py

@@ -1985,12 +1985,15 @@ def run_grounded_sam2_tracking(
                     break
                 frame_idx, frame_data, gpt_dets, ms = item
                 try:
+                    t_enrich_start = time.monotonic()
                     gpt_res = run_enrichment(
                         frame_idx, frame_data, gpt_dets, ms,
                         first_frame_gpt_results=first_frame_gpt_results,
                         job_id=job_id,
                         relevance_refined_event=_relevance_refined,
                     )
+                    gpt_enrichment_elapsed = time.monotonic() - t_enrich_start
+                    logging.info("TIMING gpt_enrichment=%.3fs for job %s", gpt_enrichment_elapsed, job_id)
 
                     # GSAM2-specific: store results in per-track dict and persist to job storage
                     if gpt_res:
@@ -2032,6 +2035,7 @@ def run_grounded_sam2_tracking(
                                         job_id,
                                         first_frame_detections=_st.first_frame_detections,
                                         first_frame_gpt_results=gpt_res,
+                                        timing_gpt_enrichment_s=gpt_enrichment_elapsed,
                                     )
                                     logging.info(
                                         "GSAM2 enrichment: updated first_frame_detections in job storage for %s",

jobs/background.py

@@ -1,5 +1,6 @@
 import asyncio
 import logging
+import time
 from datetime import datetime
 
 import torch
@@ -24,6 +25,8 @@ async def process_video_async(job_id: str) -> None:
     # Create stream for live view
     stream_queue = create_stream(job_id)
 
+    t_video_start = time.monotonic()
+
     try:
         # Run detection or segmentation first
         if job.mode == "segmentation":
@@ -63,8 +66,8 @@ async def process_video_async(job_id: str) -> None:
             detection_path, detections_list = result_pkg
 
             # If depth was requested, checking if output path exists for depth
-            # The unified pipeline creates 'output_video_path'. 
-            # If depth enabled, it might have written depth there? 
+            # The unified pipeline creates 'output_video_path'.
+            # If depth enabled, it might have written depth there?
             # Actually run_inference returns (video_path, detections).
             # If depth was ON, the video at video_path *has* depth overlays.
             # But the 'Depth Video' (heatmap only) is usually separate.
@@ -74,48 +77,68 @@ async def process_video_async(job_id: str) -> None:
             # Let's keep it simple: If depth enabled, the main video IS the depth view (overlay).
             # Or if we want separate `depth_output_path`, we need `run_inference` to handle it.
             # Let's assume for now `run_inference` writes the main visualization path.
-            
+
             if job.depth_estimator_name:
                  # In unified mode, the main video contains the depth viz
                  depth_path = detection_path
                  logging.info("Depth estimation included in main video for job %s", job_id)
 
+        video_elapsed = time.monotonic() - t_video_start
+        completed_at = datetime.utcnow()
+        total_elapsed = (completed_at - job.created_at).total_seconds()
+        logging.info("TIMING video_processing=%.3fs for job %s", video_elapsed, job_id)
+        logging.info("TIMING total=%.3fs for job %s", total_elapsed, job_id)
+
         # Mark as completed (with or without depth)
         storage.update(
             job_id,
             status=JobStatus.COMPLETED,
-            completed_at=datetime.utcnow(),
+            completed_at=completed_at,
             output_video_path=detection_path,
             depth_output_path=depth_path,
             partial_success=partial_success,
             depth_error=depth_error,
+            timing_video_processing_s=video_elapsed,
+            timing_total_s=total_elapsed,
         )
 
     except RuntimeError as exc:
+        video_elapsed = time.monotonic() - t_video_start
+        completed_at = datetime.utcnow()
+        total_elapsed = (completed_at - job.created_at).total_seconds()
         # Handle cancellation specifically
         if "cancelled" in str(exc).lower():
             logging.info("Job %s was cancelled", job_id)
             storage.update(
                 job_id,
                 status=JobStatus.CANCELLED,
-                completed_at=datetime.utcnow(),
+                completed_at=completed_at,
                 error="Cancelled by user",
+                timing_video_processing_s=video_elapsed,
+                timing_total_s=total_elapsed,
             )
         else:
             logging.exception("Background processing failed for job %s", job_id)
             storage.update(
                 job_id,
                 status=JobStatus.FAILED,
-                completed_at=datetime.utcnow(),
+                completed_at=completed_at,
                 error=str(exc),
+                timing_video_processing_s=video_elapsed,
+                timing_total_s=total_elapsed,
             )
     except Exception as exc:
+        video_elapsed = time.monotonic() - t_video_start
+        completed_at = datetime.utcnow()
+        total_elapsed = (completed_at - job.created_at).total_seconds()
         logging.exception("Background processing failed for job %s", job_id)
         storage.update(
             job_id,
             status=JobStatus.FAILED,
-            completed_at=datetime.utcnow(),
+            completed_at=completed_at,
             error=str(exc),
+            timing_video_processing_s=video_elapsed,
+            timing_total_s=total_elapsed,
         )
     finally:
         remove_stream(job_id)

jobs/models.py

@@ -38,3 +38,9 @@ class JobInfo:
     mission_spec: Optional[Any] = None  # utils.schemas.MissionSpecification
     mission_mode: str = "LEGACY"  # "MISSION" or "LEGACY"
     first_frame_gpt_results: Optional[Dict[str, Any]] = None  # Cached GPT results from process_first_frame
+    # Latency measurements (seconds)
+    timing_first_frame_s: Optional[float] = None
+    timing_video_processing_s: Optional[float] = None
+    timing_gpt_first_frame_s: Optional[float] = None
+    timing_gpt_enrichment_s: Optional[float] = None
+    timing_total_s: Optional[float] = None