diff --git a/README.md b/README.md index 8d4d6ab..5d41a63 100644 --- a/README.md +++ b/README.md @@ -166,6 +166,12 @@ cached/direct-fallback image counts. Pass `--psf-direct` to use the slower whose required HDR-tail support exceeds the cache radius selects that reference 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. +Movie renders always print one summary per time slab; `--verbose` also prints +the ray counts before each slab is loaded. + For PSF validation only, `make psf-hdr-test` builds `build/minkowski_psf_hdr_test`, a separate binary with a `--hdr-output PATH` option. It writes the pre-tone-mapping RGB framebuffer as a 32-bit float PFM diff --git a/src/frame.c b/src/frame.c index 2f1b2dc..01bdfff 100644 --- a/src/frame.c +++ b/src/frame.c @@ -292,16 +292,27 @@ size_t frame_splat_catalog(const FrameLensMesh *mesh, const PsfKernelCache *psf_cache, int catalog_load_workers, CatalogPrefetchStats *prefetch_stats, - PsfSplatStats *psf_stats) { + PsfSplatStats *psf_stats, + const FrameSplatProgress *progress) { if (mesh == NULL || catalog == NULL || hdr == NULL || exposure <= 0.0 || psf == NULL || width <= 0 || height <= 0 || catalog_load_workers <= 0) return 0; /* A bounded parallel read phase completes before splatting. Its serial cache * commit leaves immutable tile data for the OpenMP splat workers. */ + if (progress != NULL && progress->callback != NULL) + progress->callback(progress->context, FRAME_SPLAT_PROGRESS_PREFETCH_BEGIN, + 0, mesh->triangle_count); prefetch_catalog_for_mesh(mesh, catalog, catalog_load_workers, prefetch_stats); + if (progress != NULL && progress->callback != NULL) + progress->callback(progress->context, FRAME_SPLAT_PROGRESS_PREFETCH_END, + prefetch_stats == NULL ? 0 : prefetch_stats->requested_tiles, + prefetch_stats == NULL ? 0 : prefetch_stats->requested_tiles); if (psf_stats != NULL) *psf_stats = (PsfSplatStats){0}; + if (progress != NULL && progress->callback != NULL) + progress->callback(progress->context, FRAME_SPLAT_PROGRESS_BEGIN, 0, + mesh->triangle_count); const size_t pixel_count = (size_t)width * height * 3; if (pixel_count > SIZE_MAX / sizeof(double) || @@ -381,6 +392,9 @@ size_t frame_splat_catalog(const FrameLensMesh *mesh, free(private_hdr); if (psf_stats != NULL) *psf_stats = (PsfSplatStats){images - direct_fallbacks, direct_fallbacks}; + if (progress != NULL && progress->callback != NULL) + progress->callback(progress->context, FRAME_SPLAT_PROGRESS_END, + mesh->triangle_count, mesh->triangle_count); return images; } diff --git a/src/frame.h b/src/frame.h index 13f6e9a..c6257d9 100644 --- a/src/frame.h +++ b/src/frame.h @@ -27,6 +27,22 @@ typedef struct { size_t vertex_count, triangle_count; } FrameLensMesh; +typedef enum { + FRAME_SPLAT_PROGRESS_PREFETCH_BEGIN, + FRAME_SPLAT_PROGRESS_PREFETCH_END, + FRAME_SPLAT_PROGRESS_BEGIN, + FRAME_SPLAT_PROGRESS_END +} FrameSplatProgressStage; + +typedef void (*FrameSplatProgressCallback)(void *context, + FrameSplatProgressStage stage, + size_t completed, size_t total); + +typedef struct { + FrameSplatProgressCallback callback; + void *context; +} FrameSplatProgress; + 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, @@ -42,7 +58,8 @@ size_t frame_splat_catalog(const FrameLensMesh *mesh, const PsfKernelCache *psf_cache, int catalog_load_workers, CatalogPrefetchStats *prefetch_stats, - PsfSplatStats *psf_stats); + PsfSplatStats *psf_stats, + const FrameSplatProgress *progress); void frame_draw_mesh(const FrameLensMesh *mesh, double *hdr, int width, int height, double gray, double opacity); void frame_lens_mesh_destroy(FrameLensMesh *mesh); diff --git a/src/main.c b/src/main.c index 7223a5c..27b3ece 100644 --- a/src/main.c +++ b/src/main.c @@ -9,6 +9,7 @@ #include #include #include +#include #include #include #include @@ -19,6 +20,7 @@ typedef struct { int coarse_cell_pixels; int draw_mesh; int psf_direct; + int verbose; double horizontal_fov_deg, look_ra_deg, look_dec_deg, exposure; double observer_radius; double observer_inward_speed; @@ -161,6 +163,8 @@ static int parse_args(int argc, char **argv, Settings *s, !parse_moffat_beta(argv[++i], &s->psf.moffat_beta)) { } else if (!strcmp(argv[i], "--psf-direct")) { s->psf_direct = 1; + } else if (!strcmp(argv[i], "--verbose")) { + s->verbose = 1; } else if (!strcmp(argv[i], "--write-catalog") && i + 1 < argc) *write_path = argv[++i]; else if (!strcmp(argv[i], "--observer-track") && i + 1 < argc) @@ -191,6 +195,66 @@ static int parse_args(int argc, char **argv, Settings *s, return 0; } +typedef struct { + int verbose; + size_t frame_id; + double splat_start; + const CatalogPrefetchStats *prefetch; + int catalog_load_workers; + int all_sky_catalog; +} RenderProgress; + +static void report_splat_progress(void *context, FrameSplatProgressStage stage, + size_t completed, size_t total) { + RenderProgress *progress = context; + (void)completed; + if (progress == NULL) + return; + if (stage == FRAME_SPLAT_PROGRESS_PREFETCH_END && progress->all_sky_catalog) { + const CatalogPrefetchStats *prefetch = progress->prefetch; + fprintf(stderr, + "Catalog prefetch: %zu requested, %zu newly loaded (%zu stars), " + "%zu unavailable in %.3f s; %d loader workers\n", + prefetch->requested_tiles, prefetch->newly_loaded_tiles, + prefetch->newly_loaded_stars, prefetch->unavailable_tiles, + prefetch->load_seconds, progress->catalog_load_workers); + } + if (!progress->verbose) + return; + switch (stage) { + case FRAME_SPLAT_PROGRESS_PREFETCH_BEGIN: + fprintf(stderr, "Frame %zu: finding and prefetching catalog tiles...\n", + progress->frame_id); + break; + case FRAME_SPLAT_PROGRESS_PREFETCH_END: + fprintf(stderr, "Frame %zu: catalog prefetch finished (%zu candidate tiles).\n", + progress->frame_id, total); + break; + case FRAME_SPLAT_PROGRESS_BEGIN: + progress->splat_start = omp_get_wtime(); + fprintf(stderr, "Frame %zu: splatting %zu lens triangles...\n", + progress->frame_id, total); + break; + case FRAME_SPLAT_PROGRESS_END: + fprintf(stderr, "Frame %zu: catalog splatting finished in %.1f s; writing image...\n", + progress->frame_id, omp_get_wtime() - progress->splat_start); + break; + } +} + +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 GeodesicTraceConfig trace_config(void) { #ifdef SPACETIME_SCHWARZSCHILD return (GeodesicTraceConfig){.coordinate_time_step = 0.1, @@ -229,11 +293,20 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog, free(hdr); return -1; } + if (s->verbose) + fprintf(stderr, "Frame 0: traced %zu lens vertices; starting catalog render.\n", + mesh.vertex_count); CatalogPrefetchStats prefetch = {0}; PsfSplatStats psf_stats = {0}; + RenderProgress progress = {.verbose = s->verbose, + .frame_id = 0, + .prefetch = &prefetch, + .catalog_load_workers = s->catalog_load_workers, + .all_sky_catalog = catalog->kind == STAR_CATALOG_ALL_SKY}; size_t images = frame_splat_catalog( &mesh, catalog, hdr, s->width, s->height, s->exposure, &s->psf, - &s->psf_cache, s->catalog_load_workers, &prefetch, &psf_stats); + &s->psf_cache, s->catalog_load_workers, &prefetch, &psf_stats, + &(FrameSplatProgress){report_splat_progress, &progress}); if (s->draw_mesh) frame_draw_mesh(&mesh, hdr, s->width, s->height, 0.5, 0.5); #ifdef ENABLE_HDR_DEBUG @@ -250,14 +323,6 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog, images, catalog->count, output_path, result == 0 ? "ok" : "write failed"); psf_kernel_cache_report(&s->psf_cache, &psf_stats, stderr); - if (catalog->kind == STAR_CATALOG_ALL_SKY) - fprintf(stderr, - "Catalog prefetch: %zu requested, %zu newly loaded (%zu stars), " - "%zu unavailable in %.3f s; %d loader workers\n", - prefetch.requested_tiles, prefetch.newly_loaded_tiles, - prefetch.newly_loaded_stars, prefetch.unavailable_tiles, - prefetch.load_seconds, - s->catalog_load_workers); frame_lens_mesh_destroy(&mesh); free(hdr); return result; @@ -314,14 +379,33 @@ static int render_movie(const Settings *s, StarCatalog *catalog, f, v)) goto done; double slab_hi = movie.frames[movie.frame_count - 1].coordinate_time; + size_t slab_id = 0; 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 (s->verbose) + fprintf(stderr, "Time slab %zu: loading [%.6g, %.6g] with %zu pending and %zu active rays.\n", + slab_id + 1, slab_hi, slab_lo, pending_before, active_before); if (spacetime_load_slab(spacetime, slab_hi, slab_lo, &slab)) goto done; 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); + fprintf(stderr, + "Time slab %zu [%.6g, %.6g]: activated %zu; live %zu -> %zu, " + "terminated %zu, failed %zu\n", + ++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) { @@ -342,9 +426,16 @@ static int render_movie(const Settings *s, StarCatalog *catalog, } CatalogPrefetchStats prefetch = {0}; PsfSplatStats psf_stats = {0}; + RenderProgress progress = { + .verbose = s->verbose, + .frame_id = movie.frames[i].frame_id, + .prefetch = &prefetch, + .catalog_load_workers = s->catalog_load_workers, + .all_sky_catalog = catalog->kind == STAR_CATALOG_ALL_SKY}; const size_t images = frame_splat_catalog( &movie.frames[i].mesh, catalog, hdr, s->width, s->height, s->exposure, - &s->psf, &s->psf_cache, s->catalog_load_workers, &prefetch, &psf_stats); + &s->psf, &s->psf_cache, s->catalog_load_workers, &prefetch, &psf_stats, + &(FrameSplatProgress){report_splat_progress, &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); @@ -352,14 +443,6 @@ static int render_movie(const Settings *s, StarCatalog *catalog, fprintf(stderr, "Rendered %zu images from %zu catalog stars to %s (%s)\n", images, catalog->count, output_path, write_result == 0 ? "ok" : "write failed"); psf_kernel_cache_report(&s->psf_cache, &psf_stats, stderr); - if (catalog->kind == STAR_CATALOG_ALL_SKY) - fprintf(stderr, - "Catalog prefetch: %zu requested, %zu newly loaded (%zu stars), " - "%zu unavailable in %.3f s; %d loader workers\n", - prefetch.requested_tiles, prefetch.newly_loaded_tiles, - prefetch.newly_loaded_stars, prefetch.unavailable_tiles, - prefetch.load_seconds, - s->catalog_load_workers); if (write_result) goto done; } @@ -393,7 +476,7 @@ int main(int argc, char **argv) { "N] [--fov-deg D] [--look-ra-deg D] [--look-dec-deg D] " "[--exposure E] [--observer-radius R] [--observer-inward-speed V] " "[--psf-fwhm-pixels N] [--psf-moffat-beta N] " - "[--psf-direct] " + "[--psf-direct] [--verbose] " #ifdef ENABLE_HDR_DEBUG "[--hdr-output PATH] " #endif @@ -440,6 +523,7 @@ int main(int argc, char **argv) { } if (!settings.psf_direct && psf_kernel_cache_init(&settings.psf_cache, &settings.psf)) fputs("PSF cache construction failed; using direct evaluator.\n", stderr); + psf_kernel_cache_report_ready(&settings.psf_cache, stderr); int result = settings.frames_dir != NULL ? render_movie(&settings, &catalog, &spacetime) : render_frame(&settings, &catalog, &spacetime); diff --git a/src/optics.c b/src/optics.c index 0465d32..5ac7fcb 100644 --- a/src/optics.c +++ b/src/optics.c @@ -263,22 +263,28 @@ int psf_kernel_cache_init(PsfKernelCache *cache, const PointSpreadFunction *psf) return 0; } -void psf_kernel_cache_report(const PsfKernelCache *cache, - const PsfSplatStats *stats, FILE *stream) -{ +void psf_kernel_cache_report_ready(const PsfKernelCache *cache, FILE *stream) { if (stream == NULL) return; if (cache == NULL || !cache->ready) { - fprintf(stream, "PSF cache: disabled; cached splats 0, direct fallbacks %zu\n", - stats == NULL ? 0u : stats->direct_fallbacks); + fputs("PSF cache: disabled; using the direct evaluator.\n", stream); return; } - fprintf(stream, "PSF cache: 64x64 phases, radius %.0f px, tail abs %.0e, " - "boundary %.0e, build %.3f s; cached splats %zu, direct fallbacks %zu\n", + fprintf(stream, "PSF cache ready: 64x64 phases, radius %.0f px, tail abs %.0e, " + "boundary %.0e, build %.3f s\n", cache->max_radius_pixels, psf_tail_absolute_hdr_budget, - psf_boundary_hdr_budget, cache->build_seconds, - stats == NULL ? 0u : stats->cached_splats, - stats == NULL ? 0u : stats->direct_fallbacks); + psf_boundary_hdr_budget, cache->build_seconds); +} + +void psf_kernel_cache_report(const PsfKernelCache *cache, + const PsfSplatStats *stats, FILE *stream) +{ + if (stream == NULL) + return; + (void)cache; + fprintf(stream, "PSF splats: cached %zu, direct fallbacks %zu\n", + stats == NULL ? 0u : stats->cached_splats, + stats == NULL ? 0u : stats->direct_fallbacks); } void splat_moffat_direct(double *hdr, int width, int height, double x, double y, diff --git a/src/optics.h b/src/optics.h index 3b809dc..08a53f9 100644 --- a/src/optics.h +++ b/src/optics.h @@ -31,6 +31,7 @@ LinearRgb blackbody_to_linear_rgb(double temperature_K); int psf_kernel_cache_init(PsfKernelCache *cache, const PointSpreadFunction *psf); void psf_kernel_cache_destroy(PsfKernelCache *cache); +void psf_kernel_cache_report_ready(const PsfKernelCache *cache, FILE *stream); void psf_kernel_cache_report(const PsfKernelCache *cache, const PsfSplatStats *stats, FILE *stream); /* Reference implementation: pixel-area-integrated Moffat with the same tail diff --git a/tests/test_frame.c b/tests/test_frame.c index 2169b88..b1d8fd7 100644 --- a/tests/test_frame.c +++ b/tests/test_frame.c @@ -27,7 +27,7 @@ int main(void) { goto done; const size_t images = frame_splat_catalog(&mesh, &catalog, hdr, width, height, test_exposure, - &psf, NULL, 1, NULL, NULL); + &psf, NULL, 1, NULL, NULL, NULL); if (images != 1 || hdr[3 * (50 * width + 50)] <= 0.0) { fputs("flat-space inverse lens-map regression failed\n", stderr); goto done; @@ -44,10 +44,10 @@ int main(void) { omp_set_dynamic(0); omp_set_num_threads(1); const size_t serial_images = frame_splat_catalog( - &mesh, &catalog, serial_hdr, width, height, test_exposure, &psf, NULL, 1, NULL, NULL); + &mesh, &catalog, serial_hdr, width, height, test_exposure, &psf, NULL, 1, NULL, NULL, NULL); omp_set_num_threads(4); const size_t parallel_images = frame_splat_catalog( - &mesh, &catalog, parallel_hdr, width, height, test_exposure, &psf, NULL, 1, NULL, NULL); + &mesh, &catalog, parallel_hdr, width, height, test_exposure, &psf, NULL, 1, NULL, NULL, NULL); omp_set_num_threads(original_threads); for (int value = 0; value < width * height * 3; ++value) if (fabs(serial_hdr[value] - parallel_hdr[value]) > @@ -152,7 +152,7 @@ int main(void) { if (frame_lens_mesh_build_coarse(&fine_mesh, width, height, 1, 0.1) || frame_lens_mesh_trace(&fine_mesh, &spacetime, &observer, &trace) || frame_splat_catalog(&fine_mesh, &fine_catalog, hdr, width, height, - test_exposure, &psf, NULL, 1, NULL, NULL) != 1) { + test_exposure, &psf, NULL, 1, NULL, NULL, NULL) != 1) { fputs("fine source-triangle containment regression failed\n", stderr); frame_lens_mesh_destroy(&fine_mesh); goto done;