Output: expand verbose render progress

README.md

@@ -236,7 +236,12 @@ path automatically.
 
 The PSF-cache completion line is printed before tracing and catalog splatting
 begin.  For long renders, pass `--verbose` to print catalog-prefetch state,
-splat and image-write boundaries without adding work to the splat hot path.
+splat-worker local heartbeats (8, 16, 32, ... completed triangles per worker),
+and image-write boundaries.  The worker heartbeats use neither global progress
+accounting nor cross-worker synchronization.
+Verbose ray-trace output reports the initial mesh trace and refinement stages
+for single frames; movie mode additionally reports each generation's sample
+count and each time slab's activation and terminal-ray summary.
 Movie renders always print one summary per time slab; `--verbose` also prints
 the ray counts before each slab is loaded.
 

src/frame.c

@@ -668,13 +668,25 @@ int frame_lens_mesh_refine(FrameLensMesh *mesh,
                            const ObserverState *observer,
                            const GeodesicTraceConfig *trace,
                            const RefinementConfig *config) {
+  return frame_lens_mesh_refine_with_progress(mesh, spacetime, observer, trace,
+                                              config, NULL, NULL);
+}
+
+int frame_lens_mesh_refine_with_progress(
+    FrameLensMesh *mesh, const SpacetimeSource *spacetime,
+    const ObserverState *observer, const GeodesicTraceConfig *trace,
+    const RefinementConfig *config, FrameRefinementProgressCallback callback,
+    void *context) {
   if (mesh == NULL || spacetime == NULL || observer == NULL || trace == NULL ||
       config == NULL)
     return -1;
-  for (;;) {
+  for (size_t generation = 0;; ++generation) {
     const int requested = frame_lens_mesh_prepare_generation(mesh, config);
     if (requested < 0) return -1;
     if (requested == 0) return 0;
+    if (callback != NULL)
+      callback(context, generation, mesh->sample_count, mesh->vertex_count,
+               mesh->triangle_count, 0, 0);
 #pragma omp parallel for schedule(static)
     for (size_t i = 0; i < mesh->sample_count; ++i) {
       const FrameSample *sample = &mesh->samples[i];
@@ -683,7 +695,11 @@ int frame_lens_mesh_refine(FrameLensMesh *mesh,
       /* Each request has a distinct destination vertex or probe slot. */
       (void)frame_lens_mesh_install_sample(mesh, i, &endpoint);
     }
-    if (frame_lens_mesh_finish_generation(mesh, config) < 0) return -1;
+    const int added = frame_lens_mesh_finish_generation(mesh, config);
+    if (added < 0) return -1;
+    if (callback != NULL)
+      callback(context, generation, 0, mesh->vertex_count, mesh->triangle_count,
+               added, 1);
   }
 }
 
@@ -950,18 +966,43 @@ size_t frame_splat_catalog(const FrameLensMesh *mesh,
   }
 
   size_t images = 0, direct_fallbacks = 0;
+  /* Keep the ordinary render loop byte-for-byte free of progress checks. */
+  if (progress != NULL && progress->worker_callback != NULL) {
 #pragma omp parallel num_threads((int)worker_count) reduction(+ : images, direct_fallbacks)
-  {
-    const size_t worker = (size_t)omp_get_thread_num();
-    /* Source density and lens magnification can vary by orders of magnitude
-     * between neighboring image triangles.  Dynamic single-triangle chunks
-     * prevent a small sky region from leaving the other private HDR workers
-     * idle.  Each worker still owns its HDR buffer exclusively. */
+    {
+      const size_t worker = (size_t)omp_get_thread_num();
+      size_t local_triangles = 0, next_report = 8;
+      progress->worker_callback(progress->context, worker, worker_count, 0, 0);
+      /* Source density and lens magnification can vary by orders of magnitude
+       * between neighboring image triangles.  Dynamic single-triangle chunks
+       * prevent a small sky region from leaving the other private HDR workers
+       * idle.  Each worker still owns its HDR buffer exclusively. */
 #pragma omp for schedule(dynamic, 1)
-    for (size_t triangle = 0; triangle < mesh->triangle_count; ++triangle)
-      images += splat_catalog_triangles(mesh, catalog, private_hdr[worker], width,
-                                        height, exposure, psf, psf_cache, triangle,
-                                        triangle + 1, &direct_fallbacks);
+      for (size_t triangle = 0; triangle < mesh->triangle_count; ++triangle) {
+        images += splat_catalog_triangles(mesh, catalog, private_hdr[worker], width,
+                                          height, exposure, psf, psf_cache, triangle,
+                                          triangle + 1, &direct_fallbacks);
+        ++local_triangles;
+        if (local_triangles == next_report) {
+          progress->worker_callback(progress->context, worker, worker_count,
+                                    local_triangles, 0);
+          if (next_report <= SIZE_MAX / 2)
+            next_report *= 2;
+        }
+      }
+      progress->worker_callback(progress->context, worker, worker_count,
+                                local_triangles, 1);
+    }
+  } else {
+#pragma omp parallel num_threads((int)worker_count) reduction(+ : images, direct_fallbacks)
+    {
+      const size_t worker = (size_t)omp_get_thread_num();
+#pragma omp for schedule(dynamic, 1)
+      for (size_t triangle = 0; triangle < mesh->triangle_count; ++triangle)
+        images += splat_catalog_triangles(mesh, catalog, private_hdr[worker], width,
+                                          height, exposure, psf, psf_cache, triangle,
+                                          triangle + 1, &direct_fallbacks);
+    }
   }
 #pragma omp parallel for schedule(static)
   for (size_t pixel = 0; pixel < pixel_count; ++pixel)

src/frame.h

@@ -67,12 +67,28 @@ typedef enum {
 typedef void (*FrameSplatProgressCallback)(void *context,
                                            FrameSplatProgressStage stage,
                                            size_t completed, size_t total);
+/* Invoked by the splat worker itself.  `triangle_count` is local to that
+ * worker; callers must not infer global completion order from it. */
+typedef void (*FrameSplatWorkerProgressCallback)(void *context,
+                                                 size_t worker_id,
+                                                 size_t worker_count,
+                                                 size_t triangle_count,
+                                                 int finished);
 
 typedef struct {
   FrameSplatProgressCallback callback;
+  FrameSplatWorkerProgressCallback worker_callback;
   void *context;
 } FrameSplatProgress;
 
+typedef void (*FrameRefinementProgressCallback)(void *context,
+                                                size_t generation,
+                                                size_t sample_count,
+                                                size_t vertex_count,
+                                                size_t triangle_count,
+                                                int added_vertices,
+                                                int finished);
+
 int frame_lens_mesh_build_coarse(FrameLensMesh *mesh, int width, int height,
                                  int cell_pixels, double horizontal_fov_deg);
 int frame_lens_mesh_trace(FrameLensMesh *mesh, const SpacetimeSource *spacetime,
@@ -95,6 +111,11 @@ int frame_lens_mesh_refine(FrameLensMesh *mesh,
                            const ObserverState *observer,
                            const GeodesicTraceConfig *trace,
                            const RefinementConfig *config);
+int frame_lens_mesh_refine_with_progress(
+    FrameLensMesh *mesh, const SpacetimeSource *spacetime,
+    const ObserverState *observer, const GeodesicTraceConfig *trace,
+    const RefinementConfig *config, FrameRefinementProgressCallback callback,
+    void *context);
 
 /* Each locally invertible escaped triangle contributes one image per contained
  * star. */

src/main.c

@@ -287,6 +287,55 @@ static void report_splat_progress(void *context, FrameSplatProgressStage stage,
   }
 }
 
+static void report_splat_worker_progress(void *context, size_t worker_id,
+                                         size_t worker_count,
+                                         size_t triangle_count, int finished) {
+  const RenderProgress *progress = context;
+  if (progress == NULL || !progress->verbose)
+    return;
+  if (finished)
+    fprintf(stderr, "Frame %zu: splat worker %zu/%zu finished after %zu local triangles.\n",
+            progress->frame_id, worker_id + 1, worker_count, triangle_count);
+  else if (triangle_count == 0)
+    fprintf(stderr, "Frame %zu: splat worker %zu/%zu started.\n",
+            progress->frame_id, worker_id + 1, worker_count);
+  else
+    fprintf(stderr, "Frame %zu: splat worker %zu/%zu reached %zu local triangles.\n",
+            progress->frame_id, worker_id + 1, worker_count, triangle_count);
+}
+
+static void ray_pool_status_counts(const RayPool *rays, size_t *pending,
+                                   size_t *active, size_t *terminated,
+                                   size_t *failed) {
+  *pending = *active = *terminated = *failed = 0;
+  for (size_t i = 0; i < rays->count; ++i)
+    switch (rays->status[i]) {
+    case RAY_POOL_PENDING: ++*pending; break;
+    case RAY_POOL_ACTIVE: ++*active; break;
+    case RAY_POOL_TERMINATED: ++*terminated; break;
+    case RAY_POOL_FAILED: ++*failed; break;
+    }
+}
+
+static void report_frame_refinement(void *context, size_t generation,
+                                    size_t sample_count, size_t vertex_count,
+                                    size_t triangle_count, int added_vertices,
+                                    int finished) {
+  const Settings *settings = context;
+  if (settings == NULL || !settings->verbose)
+    return;
+  if (!finished)
+    fprintf(stderr,
+            "Frame 0: refinement generation %zu tracing %zu samples "
+            "from %zu vertices and %zu triangles.\n",
+            generation, sample_count, vertex_count, triangle_count);
+  else
+    fprintf(stderr,
+            "Frame 0: refinement generation %zu finished; added %d vertices, "
+            "now %zu vertices and %zu triangles.\n",
+            generation, added_vertices, vertex_count, triangle_count);
+}
+
 static GeodesicTraceConfig trace_config(void) {
 #ifdef SPACETIME_SCHWARZSCHILD
   return (GeodesicTraceConfig){.coordinate_time_step = 0.1,
@@ -316,17 +365,42 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog,
   const GeodesicTraceConfig trace = trace_config();
   FrameLensMesh mesh = {0};
   double *hdr = calloc((size_t)s->width * s->height * 3, sizeof *hdr);
-  if (hdr == NULL ||
-      frame_lens_mesh_build_coarse(&mesh, s->width, s->height,
-                                   s->coarse_cell_pixels,
-                                   s->horizontal_fov_deg) ||
-      frame_lens_mesh_trace(&mesh, spacetime, observer, &trace) ||
-      frame_lens_mesh_refine(&mesh, spacetime, observer, &trace,
-                             &s->refinement)) {
+  if (hdr == NULL || frame_lens_mesh_build_coarse(&mesh, s->width, s->height,
+                                                   s->coarse_cell_pixels,
+                                                   s->horizontal_fov_deg)) {
     frame_lens_mesh_destroy(&mesh);
     free(hdr);
     return -1;
   }
+  if (s->verbose)
+    fprintf(stderr, "Frame 0: tracing %zu initial rays from %zu mesh triangles...\n",
+            mesh.vertex_count, mesh.triangle_count);
+  const double initial_trace_start = omp_get_wtime();
+  if (frame_lens_mesh_trace(&mesh, spacetime, observer, &trace)) {
+    frame_lens_mesh_destroy(&mesh);
+    free(hdr);
+    return -1;
+  }
+  if (s->verbose)
+    fprintf(stderr, "Frame 0: initial ray trace finished in %.3f s.\n",
+            omp_get_wtime() - initial_trace_start);
+  if (s->refinement.max_level > 0 && s->verbose)
+    fprintf(stderr, "Frame 0: starting adaptive ray-trace refinement (max level %u)...\n",
+            s->refinement.max_level);
+  const double refinement_start = omp_get_wtime();
+  if (frame_lens_mesh_refine_with_progress(
+          &mesh, spacetime, observer, &trace, &s->refinement,
+          s->verbose ? report_frame_refinement : NULL, (void *)s)) {
+    frame_lens_mesh_destroy(&mesh);
+    free(hdr);
+    return -1;
+  }
+  if (s->refinement.max_level > 0 && s->verbose)
+    fprintf(stderr,
+            "Frame 0: adaptive ray-trace refinement finished in %.3f s; "
+            "%zu vertices, %zu triangles.\n",
+            omp_get_wtime() - refinement_start, mesh.vertex_count,
+            mesh.triangle_count);
   if (s->verbose)
     fprintf(stderr, "Frame 0: traced %zu lens vertices; starting catalog render.\n",
             mesh.vertex_count);
@@ -341,7 +415,9 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog,
       &mesh, catalog, hdr, s->width, s->height, s->exposure, &s->psf,
       &s->psf_cache, spacetime_limits_render_workers_by_memory(spacetime),
       s->catalog_load_workers, &prefetch, &psf_stats,
-      &(FrameSplatProgress){report_splat_progress, &progress});
+      &(FrameSplatProgress){report_splat_progress,
+                            s->verbose ? report_splat_worker_progress : NULL,
+                            &progress});
   if (s->draw_mesh)
     frame_draw_mesh(&mesh, hdr, s->width, s->height, 0.5, 0.5);
 #ifdef ENABLE_HDR_DEBUG
@@ -395,6 +471,7 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
                                   size_t generation) {
   RayPool rays = {0};
   size_t ray_count = 0;
+  size_t total_added = 0;
   for (size_t f = 0; f < movie->frame_count; ++f) {
     const int prepared = frame_lens_mesh_prepare_generation(
         &movie->frames[f].mesh, &s->refinement);
@@ -402,6 +479,10 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
     ray_count += (size_t)prepared;
   }
   if (ray_count == 0) return 0;
+  if (s->verbose)
+    fprintf(stderr,
+            "Ray trace generation %zu: collected %zu new samples across %zu frames.\n",
+            generation, ray_count, movie->frame_count);
   if (ray_pool_init(&rays, ray_count)) return -1;
   for (size_t f = 0; f < movie->frame_count; ++f) {
     size_t count = 0;
@@ -418,16 +499,29 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
   while (ray_pool_has_live(&rays)) {
     const double slab_lo = slab_hi - s->slab_duration;
     MetricSlab *slab = NULL;
+    size_t pending_before, active_before, terminated_before, failed_before;
+    ray_pool_status_counts(&rays, &pending_before, &active_before,
+                           &terminated_before, &failed_before);
     if (spacetime_load_slab(spacetime, slab_hi, slab_lo, &slab)) {
       ray_pool_destroy(&rays);
       return -1;
     }
     ray_pool_activate_in_time_range(&rays, slab);
+    size_t pending_active, active_active, terminated_active, failed_active;
+    ray_pool_status_counts(&rays, &pending_active, &active_active,
+                           &terminated_active, &failed_active);
     ray_pool_advance_active(&rays, slab, trace);
     spacetime_free_slab(slab);
+    size_t pending_after, active_after, terminated_after, failed_after;
+    ray_pool_status_counts(&rays, &pending_after, &active_after,
+                           &terminated_after, &failed_after);
     if (s->verbose)
-      fprintf(stderr, "Refinement generation %zu, slab %zu completed.\n",
-              generation, ++slab_id);
+      fprintf(stderr,
+              "Ray trace generation %zu, slab %zu [%.6g, %.6g]: activated %zu; "
+              "live %zu -> %zu, terminated %zu, failed %zu.\n",
+              generation, ++slab_id, slab_hi, slab_lo,
+              active_active - active_before, pending_before + active_before,
+              pending_after + active_after, terminated_after, failed_after);
     slab_hi = slab_lo;
   }
   for (size_t i = 0; i < rays.count; ++i)
@@ -437,10 +531,24 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
       return -1;
     }
   ray_pool_destroy(&rays);
-  for (size_t f = 0; f < movie->frame_count; ++f)
-    if (frame_lens_mesh_finish_generation(&movie->frames[f].mesh,
-                                          &s->refinement) < 0)
+  if (s->verbose)
+    fprintf(stderr, "Ray trace generation %zu: installing endpoints and refining meshes.\n",
+            generation);
+  for (size_t f = 0; f < movie->frame_count; ++f) {
+    const int added = frame_lens_mesh_finish_generation(&movie->frames[f].mesh,
+                                                         &s->refinement);
+    if (added < 0)
       return -1;
+    total_added += (size_t)added;
+    if (s->verbose && added > 0)
+      fprintf(stderr, "Ray trace generation %zu: frame %zu added %d vertices.\n",
+              generation, movie->frames[f].frame_id, added);
+  }
+  if (s->verbose)
+    fprintf(stderr,
+            "Ray trace generation %zu: refinement finished; added %zu vertices "
+            "across %zu frames.\n",
+            generation, total_added, movie->frame_count);
   return 1;
 }
 
@@ -485,7 +593,9 @@ static int render_movie(const Settings *s, StarCatalog *catalog,
         &s->psf, &s->psf_cache,
         spacetime_limits_render_workers_by_memory(spacetime),
         s->catalog_load_workers, &prefetch, &psf_stats,
-        &(FrameSplatProgress){report_splat_progress, &progress});
+        &(FrameSplatProgress){report_splat_progress,
+                              s->verbose ? report_splat_worker_progress : NULL,
+                              &progress});
     if (s->draw_mesh)
       frame_draw_mesh(&movie.frames[i].mesh, hdr, s->width, s->height, 0.5, 0.5);
     const int write_result = write_tonemapped_image(output_path, hdr, s->width, s->height);