Add long videos timing breakdown

dumas_h3_longvideos.py

@@ -47,6 +47,7 @@ import logging
 import math
 import os
 import re
+import time
 import torch
 
 import nodes
@@ -4075,6 +4076,65 @@ def _coerce_bool_flag(value):
     return bool(value)
 
 
+def _format_elapsed_seconds(seconds):
+    seconds = max(0.0, float(seconds or 0.0))
+    if seconds >= 3600:
+        hours = int(seconds // 3600)
+        minutes = int((seconds % 3600) // 60)
+        secs = seconds % 60
+        return f"{hours}h{minutes:02d}m{secs:04.1f}s"
+    if seconds >= 60:
+        minutes = int(seconds // 60)
+        secs = seconds % 60
+        return f"{minutes}m{secs:04.1f}s"
+    return f"{seconds:0.1f}s"
+
+
+def _format_timing_note(shot_timings):
+    if not shot_timings:
+        return ""
+    totals = {
+        "total": 0.0,
+        "retry_elapsed": 0.0,
+        "sample": 0.0,
+        "detail_sample": 0.0,
+        "decode_video": 0.0,
+        "decode_audio": 0.0,
+        "cleanup": 0.0,
+        "retries": 0,
+    }
+    slowest = None
+    for shot in shot_timings:
+        totals["total"] += float(shot.get("total", 0.0) or 0.0)
+        totals["retry_elapsed"] += float(shot.get("retry_elapsed", 0.0) or 0.0)
+        totals["sample"] += float(shot.get("sample", 0.0) or 0.0)
+        totals["detail_sample"] += float(shot.get("detail_sample", 0.0) or 0.0)
+        totals["decode_video"] += float(shot.get("decode_video", 0.0) or 0.0)
+        totals["decode_audio"] += float(shot.get("decode_audio", 0.0) or 0.0)
+        totals["cleanup"] += float(shot.get("cleanup", 0.0) or 0.0)
+        totals["retries"] += max(0, int(shot.get("attempts", 1) or 1) - 1)
+        if slowest is None or float(shot.get("total", 0.0) or 0.0) > float(slowest.get("total", 0.0) or 0.0):
+            slowest = shot
+    pieces = [
+        f"timing: {len(shot_timings)} shot(s) total {_format_elapsed_seconds(totals['total'])}",
+        f"sample {_format_elapsed_seconds(totals['sample'])}",
+        f"decode video {_format_elapsed_seconds(totals['decode_video'])}",
+        f"decode audio {_format_elapsed_seconds(totals['decode_audio'])}",
+        f"cleanup {_format_elapsed_seconds(totals['cleanup'])}",
+    ]
+    if totals["retry_elapsed"]:
+        pieces.append(f"retry elapsed {_format_elapsed_seconds(totals['retry_elapsed'])}")
+    if totals["detail_sample"]:
+        pieces.append(f"detail {_format_elapsed_seconds(totals['detail_sample'])}")
+    if totals["retries"]:
+        pieces.append(f"retries {totals['retries']}")
+    if slowest is not None:
+        pieces.append(
+            f"slowest shot {int(slowest.get('shot', 0) or 0)} {_format_elapsed_seconds(slowest.get('total', 0.0))}"
+        )
+    return "; ".join(pieces)
+
+
 # --- ref2va reference conditioning ----------------------------------------
 # H3's reference pipeline encodes a reference image at up to a 2048 short edge.
 # Reference rows ride through EVERY sampling step, so this is also the setting
@@ -6300,7 +6360,8 @@ class H3LongVideos:
                 handoff, decode_tile_frames=0, decode_tile_size=0,
                 refs=None, ref_image_size="match", ref_noise_aug=None, silent=False,
                 detail_pass=False, detail_sampler_name="euler", detail_scheduler="beta",
-                detail_steps=8, detail_denoise=0.4):
+                detail_steps=8, detail_denoise=0.4, timing_sink=None):
+        timing = {"sample": 0.0, "detail_sample": 0.0, "decode_video": 0.0, "decode_audio": 0.0, "cleanup": 0.0}
         positive, latent = _build_shot_conditioning(clip, vae, prompt, w, h, ln, fps, handoff,
                                                     ref_images=refs, ref_image_size=ref_image_size,
                                                     ref_noise_aug=ref_noise_aug,
@@ -6310,8 +6371,10 @@ class H3LongVideos:
         # whole sampling loop -- evict them and keep only the DiT on the card.
         _evict_all_but(model)
         try:
+            sample_start = time.perf_counter()
             (out,) = nodes.common_ksampler(model, seed, steps, cfg, sn, sch, positive, negative,
                                            latent, denoise=denoise)
+            timing["sample"] += time.perf_counter() - sample_start
         except Exception as e:
             # Mark WHERE this failed. `tiled` only affects the DECODE, so the caller's
             # OOM retry cannot help an OOM raised here -- it just re-runs the whole
@@ -6325,9 +6388,11 @@ class H3LongVideos:
         if detail_pass:
             detail_latent = _latent_with_replaced_samples(latent, out)
             try:
+                detail_start = time.perf_counter()
                 (refined_out,) = nodes.common_ksampler(
                     model, seed, int(detail_steps), cfg, detail_sampler_name, detail_scheduler,
                     positive, negative, detail_latent, denoise=float(detail_denoise))
+                timing["detail_sample"] += time.perf_counter() - detail_start
             except Exception as e:
                 if _is_oom(e):
                     e._h3_stage = "sampling"
@@ -6338,12 +6403,21 @@ class H3LongVideos:
         # 1344x768 124f shot is ~1.5MB against ~1.5GB), so carrying one per shot for
         # the whole chain is free. Detached and moved off the card immediately, for
         # the same reason the decoded frames are.
+        decode_video_start = time.perf_counter()
         shot_latent = _copy_sample_latent(refined_out)
         video = _decode_video(vae, refined_out, tiled, free_first=model,
                               tile_t=decode_tile_frames, tile_xy=decode_tile_size)
+        timing["decode_video"] += time.perf_counter() - decode_video_start
+        decode_audio_start = time.perf_counter()
         audio = _decode_audio(audio_vae, out)
+        timing["decode_audio"] += time.perf_counter() - decode_audio_start
+        cleanup_start = time.perf_counter()
         del out, refined_out, positive, latent
         _deep_cleanup()
+        timing["cleanup"] += time.perf_counter() - cleanup_start
+        if timing_sink is not None:
+            timing["total"] = sum(timing.values())
+            timing_sink.append(timing)
         return video, audio, shot_latent
 
     def run(self, model, clip, vae, audio_vae, prompt, resolution,
@@ -6797,6 +6871,7 @@ class H3LongVideos:
         ref_mode_used = []
         continuity_used = []
         ref_aug_used = []
+        shot_timings = []
         if cleanup_between_shots:
             _deep_cleanup()          # start the first (heaviest) shot with max free VRAM
 
@@ -6905,15 +6980,24 @@ class H3LongVideos:
             ref_aug_used.append(shot_aug)
             if shot_refs:
                 ref_shots.append(i + 1)
+            shot_total_start = time.perf_counter()
+            shot_retry_elapsed = 0.0
+            shot_attempts = 0
+            shot_timing = []
             if i == 0:
                 while True:
+                    shot_attempts += 1
+                    attempt_start = time.perf_counter()
                     try:
-                        frames, audio, shot_latent = self._render(model, clip, vae, audio_vae, negative, gen_prompt, w, h, ln_i, fps, tiled, sa, shot_handoff, decode_tile_frames, decode_tile_size,
+                        frames, audio, shot_latent = self._render(
+                            model, clip, vae, audio_vae, negative, gen_prompt, w, h, ln_i, fps,
+                            tiled, sa, shot_handoff, decode_tile_frames, decode_tile_size,
                             shot_refs, ref_image_size, shot_aug, shot_silent,
                             detail_pass, detail_sampler_name, detail_scheduler,
-                                                     detail_steps, detail_denoise)
+                            detail_steps, detail_denoise, timing_sink=shot_timing)
                         break
                     except (torch.cuda.OutOfMemoryError, RuntimeError) as e:
+                        shot_retry_elapsed += time.perf_counter() - attempt_start
                         if not _is_oom(e):
                             raise
                         mm.soft_empty_cache(True)
@@ -6926,11 +7010,16 @@ class H3LongVideos:
                                                "Pick a smaller resolution, close other GPU apps, or use a smaller quant.")
             else:
                 try:
-                    frames, audio, shot_latent = self._render(model, clip, vae, audio_vae, negative, gen_prompt, w, h, ln_i, fps, tiled, sa, shot_handoff, decode_tile_frames, decode_tile_size,
+                    shot_attempts += 1
+                    attempt_start = time.perf_counter()
+                    frames, audio, shot_latent = self._render(
+                        model, clip, vae, audio_vae, negative, gen_prompt, w, h, ln_i, fps,
+                        tiled, sa, shot_handoff, decode_tile_frames, decode_tile_size,
                         shot_refs, ref_image_size, shot_aug, shot_silent,
                         detail_pass, detail_sampler_name, detail_scheduler,
-                                                     detail_steps, detail_denoise)
+                        detail_steps, detail_denoise, timing_sink=shot_timing)
                 except (torch.cuda.OutOfMemoryError, RuntimeError) as e:
+                    shot_retry_elapsed += time.perf_counter() - attempt_start
                     if _is_oom(e) and getattr(e, "_h3_stage", "") == "sampling":
                         # Retrying with tiles would re-run the whole sampling pass and
                         # fail identically. Fail now, and say what actually shrinks it.
@@ -6941,10 +7030,28 @@ class H3LongVideos:
                     if not _is_oom(e) or tiled:
                         raise
                     mm.soft_empty_cache(True); tiled = True; backoff.append(f"shot {i+1}: tiled")
-                    frames, audio, shot_latent = self._render(model, clip, vae, audio_vae, negative, gen_prompt, w, h, ln_i, fps, tiled, sa, shot_handoff, decode_tile_frames, decode_tile_size,
+                    shot_attempts += 1
+                    attempt_start = time.perf_counter()
+                    frames, audio, shot_latent = self._render(
+                        model, clip, vae, audio_vae, negative, gen_prompt, w, h, ln_i, fps,
+                        tiled, sa, shot_handoff, decode_tile_frames, decode_tile_size,
                         shot_refs, ref_image_size, shot_aug, shot_silent,
                         detail_pass, detail_sampler_name, detail_scheduler,
-                                                     detail_steps, detail_denoise)
+                        detail_steps, detail_denoise, timing_sink=shot_timing)
+                    shot_retry_elapsed += time.perf_counter() - attempt_start
+
+            shot_total = time.perf_counter() - shot_total_start
+            if shot_timing:
+                render_timing = dict(shot_timing[-1])
+            else:
+                render_timing = {}
+            shot_timings.append({
+                "shot": i + 1,
+                "total": shot_total,
+                "retry_elapsed": shot_retry_elapsed,
+                "attempts": shot_attempts,
+                **render_timing,
+            })
 
             if shot_latent is not None:
                 latent_chunks.append(shot_latent)
@@ -7181,6 +7288,7 @@ class H3LongVideos:
                         + (f" (source {direct_ref_count} direct)" if direct_ref_count else ""))
         else:
             ref_note = ""
+        timing_note = _format_timing_note(shot_timings)
         info = ((anchor_note + " ") if anchor_note else "") + \
                (f"{shape_str} at {w}x{h}; {all_frames.shape[0]} frames (~{actual:.1f}s actual). "
                 f"decode {'tiled' if tiled else 'full'}. {vram_str}.{hoff_str}"
@@ -7209,6 +7317,7 @@ class H3LongVideos:
                 + (" OVERRIDES -- " + "; ".join(override_notes) + "."
                    if override_notes else "")
                 + (f"{ref_note}." if ref_note else "")
+                + (f" {timing_note}." if timing_note else "")
                 + (f" {fps_note}." if fps_note else "")
                 + (f" {swap_note}." if swap_note else "")
                 + (f" free VRAM/shot: {vram_trace}." if len(vram_trace) > 1 else "")

tests/test_dumas_h3_longvideos.py

@@ -160,6 +160,41 @@ class DumasH3LongVideosHelperTests(unittest.TestCase):
             "keyframe carry",
         )
 
+    def test_timing_summary_reports_retry_and_bucket_totals(self):
+        note = self.module._format_timing_note([
+            {
+                "shot": 1,
+                "total": 12.4,
+                "retry_elapsed": 1.2,
+                "attempts": 2,
+                "sample": 8.0,
+                "detail_sample": 0.5,
+                "decode_video": 2.1,
+                "decode_audio": 0.4,
+                "cleanup": 0.2,
+            },
+            {
+                "shot": 2,
+                "total": 7.6,
+                "retry_elapsed": 0.0,
+                "attempts": 1,
+                "sample": 6.5,
+                "decode_video": 0.5,
+                "decode_audio": 0.3,
+                "cleanup": 0.1,
+            },
+        ])
+
+        self.assertIn("timing: 2 shot(s) total 20.0s", note)
+        self.assertIn("sample 14.5s", note)
+        self.assertIn("decode video 2.6s", note)
+        self.assertIn("decode audio 0.7s", note)
+        self.assertIn("cleanup 0.3s", note)
+        self.assertIn("retry elapsed 1.2s", note)
+        self.assertIn("detail 0.5s", note)
+        self.assertIn("retries 1", note)
+        self.assertIn("slowest shot 1 12.4s", note)
+
     def test_detail_pass_refines_video_but_preserves_audio(self):
         class FakeTensor:
             def __init__(self, name):