wyj/GR-raytracing
1
0 Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Fix: Separate normal renderer output from diagnostics

Browse Source
This commit is contained in:
wyj committed 2026-10-07 22:14:56 -04:00
1 parent 69a8cb5647
commit af8b83007f
11 files changed
+249 -90
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

Makefile
+1
View File
@@ -299,6 +299,7 @@ test: $(CAMERA_TEST_TARGETS) $(TEST_TARGET) $(ADAPTIVE_GEODESIC_TEST_TARGET) $(A
$(SENSOR_BLOOM_TEST_TARGET) $(SENSOR_BLOOM_TEST_TARGET)
python3 tests/test_camera_cli.py $(BUILD_DIR) $(TEST_OUT_DIR) python3 tests/test_camera_cli.py $(BUILD_DIR) $(TEST_OUT_DIR)
python3 tests/test_adaptive_cli.py $(BUILD_DIR) $(TEST_OUT_DIR) python3 tests/test_adaptive_cli.py $(BUILD_DIR) $(TEST_OUT_DIR)
python3 tests/test_output_streams.py $(BUILD_DIR) $(TEST_OUT_DIR)
tone-map-test: $(TONE_MAP_TEST_TARGET) tone-map-test: $(TONE_MAP_TEST_TARGET)
$(TONE_MAP_TEST_TARGET) $(TONE_MAP_TEST_TARGET)
src/dummy_psf.c
+7 -7
View File
@@ -301,7 +301,7 @@ static void report_group(const DummyPsfSink *sink, int full_only,
if (!full_only || sink->samples[i].events == sink->event_capacity) if (!full_only || sink->samples[i].events == sink->event_capacity)
++count; ++count;
if (count == 0) { if (count == 0) {
fprintf(stderr, "Dummy PSF %s chunks: none\n", label); fprintf(stdout, "Dummy PSF %s chunks: none\n", label);
return; return;
} }
double *events = count > SIZE_MAX / (6 * sizeof *events) double *events = count > SIZE_MAX / (6 * sizeof *events)
@@ -338,7 +338,7 @@ static void report_group(const DummyPsfSink *sink, int full_only,
"maximum_successive_triangle_jump_px"}; "maximum_successive_triangle_jump_px"};
for (size_t field = 0; field < 6; ++field) { for (size_t field = 0; field < 6; ++field) {
qsort(series[field], count, sizeof **series, compare_double); qsort(series[field], count, sizeof **series, compare_double);
fprintf(stderr, fprintf(stdout,
"Dummy PSF %s %s: min=%.3f p10=%.3f p25=%.3f p50=%.3f " "Dummy PSF %s %s: min=%.3f p10=%.3f p25=%.3f p50=%.3f "
"p75=%.3f p90=%.3f p99=%.3f max=%.3f\n", "p75=%.3f p90=%.3f p99=%.3f max=%.3f\n",
label, names[field], series[field][0], label, names[field], series[field][0],
@@ -349,7 +349,7 @@ static void report_group(const DummyPsfSink *sink, int full_only,
percentile(series[field], count, 0.90), percentile(series[field], count, 0.90),
percentile(series[field], count, 0.99), series[field][count - 1]); percentile(series[field], count, 0.99), series[field][count - 1]);
} }
fprintf(stderr, fprintf(stdout,
"Dummy PSF %s adaptive criterion: %zu/%zu chunks tile16-eligible " "Dummy PSF %s adaptive criterion: %zu/%zu chunks tile16-eligible "
"(events>=8192 and events/occupied_32px_tiles>=32)\n", "(events>=8192 and events/occupied_32px_tiles>=32)\n",
label, adaptive, count); label, adaptive, count);
@@ -386,7 +386,7 @@ static void report_support_group(const DummyPsfSink *sink, int full_only,
for (size_t field = 0; field < 5; ++field) { for (size_t field = 0; field < 5; ++field) {
double *series = values + field * count; double *series = values + field * count;
qsort(series, count, sizeof *series, compare_double); qsort(series, count, sizeof *series, compare_double);
fprintf(stderr, fprintf(stdout,
"Dummy PSF %s %s: min=%.3f p10=%.3f p25=%.3f p50=%.3f " "Dummy PSF %s %s: min=%.3f p10=%.3f p25=%.3f p50=%.3f "
"p75=%.3f p90=%.3f p99=%.3f max=%.3f\n", "p75=%.3f p90=%.3f p99=%.3f max=%.3f\n",
label, names[field], series[0], label, names[field], series[0],
@@ -395,7 +395,7 @@ static void report_support_group(const DummyPsfSink *sink, int full_only,
percentile(series, count, 0.90), percentile(series, count, 0.99), percentile(series, count, 0.90), percentile(series, count, 0.99),
series[count - 1]); series[count - 1]);
} }
fprintf(stderr, fprintf(stdout,
"Dummy PSF %s support totals: references=%zu tasks=%zu summed_first_pass=%.3f s\n", "Dummy PSF %s support totals: references=%zu tasks=%zu summed_first_pass=%.3f s\n",
label, total_refs, total_tasks, total_pass); label, total_refs, total_tasks, total_pass);
free(values); free(values);
@@ -407,7 +407,7 @@ void dummy_psf_sink_report(const DummyPsfSink *sink) {
size_t full = 0; size_t full = 0;
for (size_t i = 0; i < sink->count; ++i) for (size_t i = 0; i < sink->count; ++i)
full += sink->samples[i].events == sink->event_capacity; full += sink->samples[i].events == sink->event_capacity;
fprintf(stderr, fprintf(stdout,
"Dummy PSF diagnostic only: no HDR or image was accumulated/written.\n" "Dummy PSF diagnostic only: no HDR or image was accumulated/written.\n"
"Dummy PSF chunks: total=%zu full=%zu partial=%zu events=%zu " "Dummy PSF chunks: total=%zu full=%zu partial=%zu events=%zu "
"capacity=%zu selector_tile=%dpx\n", "capacity=%zu selector_tile=%dpx\n",
@@ -416,7 +416,7 @@ void dummy_psf_sink_report(const DummyPsfSink *sink) {
report_group(sink, 0, "all"); report_group(sink, 0, "all");
report_group(sink, 1, "full"); report_group(sink, 1, "full");
if (sink->support_stats) { if (sink->support_stats) {
fputs("Dummy PSF support diagnostic: 16px rectangular cache-limited first pass only; no references were materialized or uploaded.\n", stderr); fputs("Dummy PSF support diagnostic: 16px rectangular cache-limited first pass only; no references were materialized or uploaded.\n", stdout);
report_support_group(sink, 0, "all"); report_support_group(sink, 0, "all");
report_support_group(sink, 1, "full"); report_support_group(sink, 1, "full");
} }
src/frame.c
+4 -4
View File
@@ -2260,7 +2260,7 @@ size_t frame_splat_catalog(const FrameLensMesh *mesh,
(size_t)dummy_workers, completed, 1); (size_t)dummy_workers, completed, 1);
} }
if (psf_event_sink_destroy(&owner)) dummy_failed = 1; if (psf_event_sink_destroy(&owner)) dummy_failed = 1;
fprintf(stderr, fprintf(stdout,
"Dummy PSF producers: %d workers; classification/chunk wall %.3f s\n", "Dummy PSF producers: %d workers; classification/chunk wall %.3f s\n",
dummy_workers, omp_get_wtime() - dummy_start); dummy_workers, omp_get_wtime() - dummy_start);
copy_psf_splat_stats(psf_stats, (CatalogSplatStats){ copy_psf_splat_stats(psf_stats, (CatalogSplatStats){
@@ -2349,14 +2349,14 @@ size_t frame_splat_catalog(const FrameLensMesh *mesh,
} }
omp_destroy_lock(&submit_lock); omp_destroy_lock(&submit_lock);
if (psf_event_sink_destroy(&owner)) hip_failed = 1; if (psf_event_sink_destroy(&owner)) hip_failed = 1;
fprintf(stderr, "HIP producers: %d workers; summed generation %.3f s, submission/fallback %.3f s; wall %.3f s\n", fprintf(stdout, "HIP producers: %d workers; summed generation %.3f s, submission/fallback %.3f s; wall %.3f s\n",
hip_workers, hip_generate_seconds, hip_submit_seconds, omp_get_wtime() - hip_start); hip_workers, hip_generate_seconds, hip_submit_seconds, omp_get_wtime() - hip_start);
fprintf(stderr, fprintf(stdout,
"HIP PSF accumulation: atomic %zu batches, tile16 %zu batches; selector %.3f s, binning %.3f s\n", "HIP PSF accumulation: atomic %zu batches, tile16 %zu batches; selector %.3f s, binning %.3f s\n",
owner.hip_timing.atomic_batch_count, owner.hip_timing.tile_batch_count, owner.hip_timing.atomic_batch_count, owner.hip_timing.tile_batch_count,
owner.hip_timing.selection_seconds, owner.hip_timing.bin_seconds); owner.hip_timing.selection_seconds, owner.hip_timing.bin_seconds);
if (owner.hip_timing.tile_batch_count) if (owner.hip_timing.tile_batch_count)
fprintf(stderr, fprintf(stdout,
"HIP PSF tile workload: references %zu, tasks %zu, merges %zu; peak references/chunk %zu\n", "HIP PSF tile workload: references %zu, tasks %zu, merges %zu; peak references/chunk %zu\n",
owner.hip_timing.tile_reference_count, owner.hip_timing.tile_task_count, owner.hip_timing.tile_reference_count, owner.hip_timing.tile_task_count,
owner.hip_timing.tile_merge_count, owner.hip_timing.tile_merge_count,
src/hip_psf.hip
+2 -2
View File
@@ -605,7 +605,7 @@ static int submit_prepared(HipPsfSink *sink, HipPsfPreparedChunk *prepared,
sink->timing.event_count += event_count; sink->timing.event_count += event_count;
const auto now = std::chrono::steady_clock::now(); const auto now = std::chrono::steady_clock::now();
if (std::chrono::duration<double>(now - sink->last_report).count() >= 5.0) { if (std::chrono::duration<double>(now - sink->last_report).count() >= 5.0) {
std::fprintf(stderr, std::fprintf(stdout,
"HIP PSF progress: %zu submitted / %zu completed events; %zu / %zu batches timed; kernel %.3f s\n", "HIP PSF progress: %zu submitted / %zu completed events; %zu / %zu batches timed; kernel %.3f s\n",
sink->timing.event_count, sink->completed_events, sink->timing.event_count, sink->completed_events,
sink->timing.timed_batch_count, sink->timing.batch_count, sink->timing.timed_batch_count, sink->timing.batch_count,
@@ -641,7 +641,7 @@ static int submit_prepared(HipPsfSink *sink, HipPsfPreparedChunk *prepared,
sink->timing.event_count += event_count; sink->timing.event_count += event_count;
const auto now = std::chrono::steady_clock::now(); const auto now = std::chrono::steady_clock::now();
if (std::chrono::duration<double>(now - sink->last_report).count() >= 5.0) { if (std::chrono::duration<double>(now - sink->last_report).count() >= 5.0) {
std::fprintf(stderr, "HIP PSF progress: %zu submitted / %zu completed events; %zu / %zu batches timed; kernel %.3f s\n", std::fprintf(stdout, "HIP PSF progress: %zu submitted / %zu completed events; %zu / %zu batches timed; kernel %.3f s\n",
sink->timing.event_count, sink->completed_events, sink->timing.timed_batch_count, sink->timing.event_count, sink->completed_events, sink->timing.timed_batch_count,
sink->timing.batch_count, sink->timing.kernel_seconds); sink->timing.batch_count, sink->timing.kernel_seconds);
sink->last_report = now; sink->last_report = now;
src/main.c
+64 -59
View File
@@ -352,7 +352,7 @@ static int apply_sensor_bloom(const Settings *s, double *hdr, int width,
stderr); stderr);
return -1; return -1;
} }
fprintf(stderr, fprintf(stdout,
"Sensor bloom: saturated=%zu clamped=%zu iterations=%zu/%zu " "Sensor bloom: saturated=%zu clamped=%zu iterations=%zu/%zu "
"peak=%.6g max_overflow=%.6g absorbed=%.6g boundary=%.6g " "peak=%.6g max_overflow=%.6g absorbed=%.6g boundary=%.6g "
"residual=%.6g elapsed=%.6fs\n", "residual=%.6g elapsed=%.6fs\n",
@@ -390,7 +390,8 @@ static int write_frame_outputs(const Settings *s, const FrameLensMesh *mesh,
const int write_result = const int write_result =
write_rgb8_timed(s, paths->output_path, rgb8, width, height, timing); write_rgb8_timed(s, paths->output_path, rgb8, width, height, timing);
free(rgb8); free(rgb8);
fprintf(stderr, "Rendered %zu images from %zu catalog stars to %s (%s%s)\n", fprintf(write_result == 0 ? stdout : stderr,
"Rendered %zu images from %zu catalog stars to %s (%s%s)\n",
images, stars, paths->output_path, images, stars, paths->output_path,
write_result == 0 ? "ok" : "write failed", note); write_result == 0 ? "ok" : "write failed", note);
if (write_result) if (write_result)
@@ -407,7 +408,7 @@ static int write_frame_outputs(const Settings *s, const FrameLensMesh *mesh,
return -1; return -1;
} }
free(mesh_rgb8); free(mesh_rgb8);
fprintf(stderr, "Wrote mesh overlay image: %s\n", paths->mesh_path); fprintf(stdout, "Wrote mesh overlay image: %s\n", paths->mesh_path);
} }
return 0; return 0;
} }
@@ -894,7 +895,7 @@ static void report_splat_progress(void *context, FrameSplatProgressStage stage,
return; return;
if (stage == FRAME_SPLAT_PROGRESS_PREFETCH_END && progress->all_sky_catalog) { if (stage == FRAME_SPLAT_PROGRESS_PREFETCH_END && progress->all_sky_catalog) {
const CatalogPrefetchStats *prefetch = progress->prefetch; const CatalogPrefetchStats *prefetch = progress->prefetch;
fprintf(stderr, fprintf(stdout,
"Catalog prefetch: %zu requested, %zu newly loaded (%zu stars), " "Catalog prefetch: %zu requested, %zu newly loaded (%zu stars), "
"%zu unavailable in %.3f s; %d loader workers\n", "%zu unavailable in %.3f s; %d loader workers\n",
prefetch->requested_tiles, prefetch->newly_loaded_tiles, prefetch->requested_tiles, prefetch->newly_loaded_tiles,
@@ -905,24 +906,24 @@ static void report_splat_progress(void *context, FrameSplatProgressStage stage,
return; return;
switch (stage) { switch (stage) {
case FRAME_SPLAT_PROGRESS_PREFETCH_BEGIN: case FRAME_SPLAT_PROGRESS_PREFETCH_BEGIN:
fprintf(stderr, "Frame %zu: finding and prefetching catalog tiles...\n", fprintf(stdout, "Frame %zu: finding and prefetching catalog tiles...\n",
progress->frame_id); progress->frame_id);
break; break;
case FRAME_SPLAT_PROGRESS_PREFETCH_END: case FRAME_SPLAT_PROGRESS_PREFETCH_END:
fprintf(stderr, "Frame %zu: catalog prefetch finished (%zu candidate tiles).\n", fprintf(stdout, "Frame %zu: catalog prefetch finished (%zu candidate tiles).\n",
progress->frame_id, total); progress->frame_id, total);
break; break;
case FRAME_SPLAT_PROGRESS_BEGIN: case FRAME_SPLAT_PROGRESS_BEGIN:
progress->splat_start = omp_get_wtime(); progress->splat_start = omp_get_wtime();
fprintf(stderr, "Frame %zu: splatting %zu lens triangles...\n", fprintf(stdout, "Frame %zu: splatting %zu lens triangles...\n",
progress->frame_id, total); progress->frame_id, total);
break; break;
case FRAME_SPLAT_PROGRESS_END: case FRAME_SPLAT_PROGRESS_END:
#ifdef PSF_BACKEND_DUMMY #ifdef PSF_BACKEND_DUMMY
fprintf(stderr, "Frame %zu: catalog classification finished in %.1f s; reporting chunk statistics...\n", fprintf(stdout, "Frame %zu: catalog classification finished in %.1f s; reporting chunk statistics...\n",
progress->frame_id, omp_get_wtime() - progress->splat_start); progress->frame_id, omp_get_wtime() - progress->splat_start);
#else #else
fprintf(stderr, "Frame %zu: catalog splatting finished in %.1f s; writing image...\n", fprintf(stdout, "Frame %zu: catalog splatting finished in %.1f s; writing image...\n",
progress->frame_id, omp_get_wtime() - progress->splat_start); progress->frame_id, omp_get_wtime() - progress->splat_start);
#endif #endif
break; break;
@@ -936,13 +937,13 @@ static void report_splat_worker_progress(void *context, size_t worker_id,
if (progress == NULL || !progress->verbose) if (progress == NULL || !progress->verbose)
return; return;
if (finished) if (finished)
fprintf(stderr, "Frame %zu: splat worker %zu/%zu finished after %zu local triangles.\n", fprintf(stdout, "Frame %zu: splat worker %zu/%zu finished after %zu local triangles.\n",
progress->frame_id, worker_id + 1, worker_count, triangle_count); progress->frame_id, worker_id + 1, worker_count, triangle_count);
else if (triangle_count == 0) else if (triangle_count == 0)
fprintf(stderr, "Frame %zu: splat worker %zu/%zu started.\n", fprintf(stdout, "Frame %zu: splat worker %zu/%zu started.\n",
progress->frame_id, worker_id + 1, worker_count); progress->frame_id, worker_id + 1, worker_count);
else else
fprintf(stderr, "Frame %zu: splat worker %zu/%zu reached %zu local triangles.\n", fprintf(stdout, "Frame %zu: splat worker %zu/%zu reached %zu local triangles.\n",
progress->frame_id, worker_id + 1, worker_count, triangle_count); progress->frame_id, worker_id + 1, worker_count, triangle_count);
} }
@@ -968,12 +969,12 @@ static void report_frame_refinement(void *context, size_t generation,
if (settings == NULL || !settings->verbose) if (settings == NULL || !settings->verbose)
return; return;
if (!finished) if (!finished)
fprintf(stderr, fprintf(stdout,
"Frame 0: refinement generation %zu tracing %zu samples " "Frame 0: refinement generation %zu tracing %zu samples "
"from %zu vertices and %zu triangles.\n", "from %zu vertices and %zu triangles.\n",
generation, sample_count, vertex_count, triangle_count); generation, sample_count, vertex_count, triangle_count);
else else
fprintf(stderr, fprintf(stdout,
"Frame 0: refinement generation %zu finished; added %d vertices, " "Frame 0: refinement generation %zu finished; added %d vertices, "
"now %zu vertices and %zu triangles.\n", "now %zu vertices and %zu triangles.\n",
generation, added_vertices, vertex_count, triangle_count); generation, added_vertices, vertex_count, triangle_count);
@@ -1089,7 +1090,7 @@ static void report_boundary_stats(const Settings *s,
if (out_total != NULL) if (out_total != NULL)
*out_total = total; *out_total = total;
if (s->verbose && frame_count > 0) if (s->verbose && frame_count > 0)
fprintf(stderr, fprintf(stdout,
"Boundary accounting: EEE=%zu DDD=%zu EED/EDD=%zu UUD/UDD=%zu " "Boundary accounting: EEE=%zu DDD=%zu EED/EDD=%zu UUD/UDD=%zu "
"U+E=%zu UUU=%zu error=%zu; approx-black=%zu (%.6g px^2), " "U+E=%zu UUU=%zu error=%zu; approx-black=%zu (%.6g px^2), "
"retries=%zu, budget-incomplete=%zu.\n", "retries=%zu, budget-incomplete=%zu.\n",
@@ -1098,7 +1099,7 @@ static void report_boundary_stats(const Settings *s,
total.approx_black_triangles, total.approx_black_area_pixels2, total.approx_black_triangles, total.approx_black_area_pixels2,
total.retry_requests, total.budget_incomplete_triangles); total.retry_requests, total.budget_incomplete_triangles);
if (s->verbose && total.approx_black_triangles) if (s->verbose && total.approx_black_triangles)
fprintf(stderr, "Approx-black achieved scale: max edge=%.6g px, max area=%.6g px^2, level stops=%zu.\n", fprintf(stdout, "Approx-black achieved scale: max edge=%.6g px, max area=%.6g px^2, level stops=%zu.\n",
total.approx_black_max_edge_pixels, total.approx_black_max_area_pixels2, total.approx_black_max_edge_pixels, total.approx_black_max_area_pixels2,
total.approx_black_level_stops); total.approx_black_level_stops);
} }
@@ -1134,7 +1135,7 @@ static void report_trace_stats(const Settings *s, const FrameTraceStats *stats,
const char *label) { const char *label) {
if (!s->verbose) if (!s->verbose)
return; return;
fprintf(stderr, fprintf(stdout,
"%s trace cost: accepted=%" PRIu64 " rejected=%" PRIu64 "%s trace cost: accepted=%" PRIu64 " rejected=%" PRIu64
" rhs=%" PRIu64 " over %zu vertices (saturated=%zu).\n", " rhs=%" PRIu64 " over %zu vertices (saturated=%zu).\n",
label, stats->accepted_steps, stats->rejected_steps, label, stats->accepted_steps, stats->rejected_steps,
@@ -1400,7 +1401,7 @@ static void report_trace_config(const Settings *s,
const char *label) { const char *label) {
if (!s->verbose) if (!s->verbose)
return; return;
fprintf(stderr, fprintf(stdout,
"%s: integrator=%s step=%.8g max_steps=%u threshold=%.8g " "%s: integrator=%s step=%.8g max_steps=%u threshold=%.8g "
"atol=(x %.8g, Pi %.8g, L %.8g) rtol=%.8g bounds=[%.8g, %.8g] " "atol=(x %.8g, Pi %.8g, L %.8g) rtol=%.8g bounds=[%.8g, %.8g] "
"max_rejections=%u lookback=%.8g\n", "max_rejections=%u lookback=%.8g\n",
@@ -1494,14 +1495,14 @@ static int build_observer(const Settings *s, const SpacetimeSource *spacetime,
static void report_psf_splat(const Settings *s, const PsfSplatStats *stats) { static void report_psf_splat(const Settings *s, const PsfSplatStats *stats) {
if (s->fast_mode) { if (s->fast_mode) {
fprintf(stderr, fprintf(stdout,
"Fast PSF splats: deposited %zu, wing-clipped %zu, discarded " "Fast PSF splats: deposited %zu, wing-clipped %zu, discarded "
"below min-Y %zu\n", "below min-Y %zu\n",
stats->cached_splats, stats->cached_wing_clipped, stats->cached_splats, stats->cached_wing_clipped,
stats->discarded_below_min_y); stats->discarded_below_min_y);
return; return;
} }
psf_kernel_cache_report(&s->psf_cache, stats, stderr); psf_kernel_cache_report(&s->psf_cache, stats, stdout);
} }
static int render_observer_frame(const Settings *s, StarCatalog *catalog, static int render_observer_frame(const Settings *s, StarCatalog *catalog,
@@ -1521,7 +1522,7 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog,
return -1; return -1;
} }
if (s->verbose) if (s->verbose)
fprintf(stderr, "Frame 0: tracing %zu initial rays from %zu mesh triangles...\n", fprintf(stdout, "Frame 0: tracing %zu initial rays from %zu mesh triangles...\n",
mesh.vertex_count, mesh.triangle_count); mesh.vertex_count, mesh.triangle_count);
const double initial_trace_start = omp_get_wtime(); const double initial_trace_start = omp_get_wtime();
if (frame_lens_mesh_trace(&mesh, spacetime, observer, &trace)) { if (frame_lens_mesh_trace(&mesh, spacetime, observer, &trace)) {
@@ -1530,10 +1531,10 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog,
return -1; return -1;
} }
if (s->verbose) if (s->verbose)
fprintf(stderr, "Frame 0: initial ray trace finished in %.3f s.\n", fprintf(stdout, "Frame 0: initial ray trace finished in %.3f s.\n",
omp_get_wtime() - initial_trace_start); omp_get_wtime() - initial_trace_start);
if (s->refinement.max_level > 0 && s->verbose) if (s->refinement.max_level > 0 && s->verbose)
fprintf(stderr, "Frame 0: starting adaptive ray-trace refinement (max level %u)...\n", fprintf(stdout, "Frame 0: starting adaptive ray-trace refinement (max level %u)...\n",
s->refinement.max_level); s->refinement.max_level);
const double refinement_start = omp_get_wtime(); const double refinement_start = omp_get_wtime();
if (frame_lens_mesh_refine_with_progress( if (frame_lens_mesh_refine_with_progress(
@@ -1544,7 +1545,7 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog,
return -1; return -1;
} }
if (s->refinement.max_level > 0 && s->verbose) if (s->refinement.max_level > 0 && s->verbose)
fprintf(stderr, fprintf(stdout,
"Frame 0: adaptive ray-trace refinement finished in %.3f s; " "Frame 0: adaptive ray-trace refinement finished in %.3f s; "
"%zu vertices, %zu triangles.\n", "%zu vertices, %zu triangles.\n",
omp_get_wtime() - refinement_start, mesh.vertex_count, omp_get_wtime() - refinement_start, mesh.vertex_count,
@@ -1576,11 +1577,11 @@ static int render_observer_frame(const Settings *s, StarCatalog *catalog,
free(hdr); free(hdr);
return -1; return -1;
} }
fprintf(stderr, "Wrote lens map: %s (%zu vertices, %zu triangles)\n", fprintf(stdout, "Wrote lens map: %s (%zu vertices, %zu triangles)\n",
s->lens_map_output_path, mesh.vertex_count, mesh.triangle_count); s->lens_map_output_path, mesh.vertex_count, mesh.triangle_count);
} }
if (s->verbose) if (s->verbose)
fprintf(stderr, "Frame 0: traced %zu lens vertices; starting catalog render.\n", fprintf(stdout, "Frame 0: traced %zu lens vertices; starting catalog render.\n",
mesh.vertex_count); mesh.vertex_count);
CatalogPrefetchStats prefetch = {0}; CatalogPrefetchStats prefetch = {0};
PsfSplatStats psf_stats = {0}; PsfSplatStats psf_stats = {0};
@@ -1654,7 +1655,7 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
} }
if (ray_count == 0) return 0; if (ray_count == 0) return 0;
if (s->verbose) if (s->verbose)
fprintf(stderr, fprintf(stdout,
"Ray trace generation %zu: collected %zu new samples across %zu frames.\n", "Ray trace generation %zu: collected %zu new samples across %zu frames.\n",
generation, ray_count, movie->frame_count); generation, ray_count, movie->frame_count);
if (ray_pool_init(&rays, ray_count)) return -1; if (ray_pool_init(&rays, ray_count)) return -1;
@@ -1712,7 +1713,7 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
ray_pool_status_counts(&rays, &pending_after, &active_after, ray_pool_status_counts(&rays, &pending_after, &active_after,
&terminated_after, &unresolved_after, &failed_after); &terminated_after, &unresolved_after, &failed_after);
if (s->verbose) if (s->verbose)
fprintf(stderr, fprintf(stdout,
"Ray trace generation %zu, slab %zu [%.6g, %.6g]: activated %zu; " "Ray trace generation %zu, slab %zu [%.6g, %.6g]: activated %zu; "
"live %zu -> %zu, terminated %zu, unresolved %zu, failed %zu.\n", "live %zu -> %zu, terminated %zu, unresolved %zu, failed %zu.\n",
generation, ++slab_id, slab_hi, slab_lo, generation, ++slab_id, slab_hi, slab_lo,
@@ -1729,7 +1730,7 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
} }
ray_pool_destroy(&rays); ray_pool_destroy(&rays);
if (s->verbose) if (s->verbose)
fprintf(stderr, "Ray trace generation %zu: installing endpoints and refining meshes.\n", fprintf(stdout, "Ray trace generation %zu: installing endpoints and refining meshes.\n",
generation); generation);
for (size_t f = 0; f < movie->frame_count; ++f) { for (size_t f = 0; f < movie->frame_count; ++f) {
/* Frames converge independently; only finish those traced this pass. */ /* Frames converge independently; only finish those traced this pass. */
@@ -1744,11 +1745,11 @@ static int trace_movie_generation(Movie *movie, const Settings *s,
} }
total_added += (size_t)added; total_added += (size_t)added;
if (s->verbose && added > 0) if (s->verbose && added > 0)
fprintf(stderr, "Ray trace generation %zu: frame %zu added %d vertices.\n", fprintf(stdout, "Ray trace generation %zu: frame %zu added %d vertices.\n",
generation, movie->frames[f].frame_id, added); generation, movie->frames[f].frame_id, added);
} }
if (s->verbose) if (s->verbose)
fprintf(stderr, fprintf(stdout,
"Ray trace generation %zu: refinement finished; added %zu vertices " "Ray trace generation %zu: refinement finished; added %zu vertices "
"across %zu frames.\n", "across %zu frames.\n",
generation, total_added, movie->frame_count); generation, total_added, movie->frame_count);
@@ -1792,7 +1793,7 @@ static void report_movie_timing_frame(const Settings *s, size_t frame_id,
const MovieFrameTiming *t) { const MovieFrameTiming *t) {
if (!s->verbose) if (!s->verbose)
return; return;
fprintf(stderr, fprintf(stdout,
"Movie frame %zu timing: catalog_mark=%.4f catalog_load=%.4f " "Movie frame %zu timing: catalog_mark=%.4f catalog_load=%.4f "
"fast_clear=%.4f splat=%.4f fftw=%.4f tone_map=%.4f output=%.4f " "fast_clear=%.4f splat=%.4f fftw=%.4f tone_map=%.4f output=%.4f "
"wait=%.4f total=%.4f\n", "wait=%.4f total=%.4f\n",
@@ -1805,19 +1806,19 @@ static void report_movie_timing_frame(const Settings *s, size_t frame_id,
static void report_movie_timing_summary(const MovieTimingAccumulator *acc) { static void report_movie_timing_summary(const MovieTimingAccumulator *acc) {
if (acc->frames == 0) if (acc->frames == 0)
return; return;
fprintf(stderr, "Movie timing total (%zu frames):", acc->frames); fprintf(stdout, "Movie timing total (%zu frames):", acc->frames);
for (size_t i = 0; i < MOVIE_TIMING_COUNT; ++i) for (size_t i = 0; i < MOVIE_TIMING_COUNT; ++i)
fprintf(stderr, " %s=%.4f", movie_timing_names[i], acc->sum[i]); fprintf(stdout, " %s=%.4f", movie_timing_names[i], acc->sum[i]);
fputc('\n', stderr); fputc('\n', stdout);
fprintf(stderr, "Movie timing avg (%zu frames):", acc->frames); fprintf(stdout, "Movie timing avg (%zu frames):", acc->frames);
for (size_t i = 0; i < MOVIE_TIMING_COUNT; ++i) for (size_t i = 0; i < MOVIE_TIMING_COUNT; ++i)
fprintf(stderr, " %s=%.4f", movie_timing_names[i], fprintf(stdout, " %s=%.4f", movie_timing_names[i],
acc->sum[i] / (double)acc->frames); acc->sum[i] / (double)acc->frames);
fputc('\n', stderr); fputc('\n', stdout);
fprintf(stderr, "Movie timing max (%zu frames):", acc->frames); fprintf(stdout, "Movie timing max (%zu frames):", acc->frames);
for (size_t i = 0; i < MOVIE_TIMING_COUNT; ++i) for (size_t i = 0; i < MOVIE_TIMING_COUNT; ++i)
fprintf(stderr, " %s=%.4f", movie_timing_names[i], acc->max[i]); fprintf(stdout, " %s=%.4f", movie_timing_names[i], acc->max[i]);
fputc('\n', stderr); fputc('\n', stdout);
} }
/* Producer half of the async movie output: finishes every HDR-side step /* Producer half of the async movie output: finishes every HDR-side step
@@ -1930,7 +1931,7 @@ static int render_movie(const Settings *s, StarCatalog *catalog,
fprintf(stderr, "Failed to write lens map: %s\n", s->lens_map_output_path); fprintf(stderr, "Failed to write lens map: %s\n", s->lens_map_output_path);
goto done; goto done;
} }
fprintf(stderr, "Wrote lens-map movie: %s (%zu frames)\n", fprintf(stdout, "Wrote lens-map movie: %s (%zu frames)\n",
s->lens_map_output_path, movie.frame_count); s->lens_map_output_path, movie.frame_count);
} }
/* An all-sky movie prefetches the union of every finalized frame's requested /* An all-sky movie prefetches the union of every finalized frame's requested
@@ -1953,7 +1954,7 @@ static int render_movie(const Settings *s, StarCatalog *catalog,
goto done; goto done;
} }
const double load_seconds = omp_get_wtime() - load_start; const double load_seconds = omp_get_wtime() - load_start;
fprintf(stderr, fprintf(stdout,
"Movie catalog prefetch: %zu unique requested, %zu newly loaded " "Movie catalog prefetch: %zu unique requested, %zu newly loaded "
"(%zu stars), %zu unavailable in %.3f s (mark %.3f, load+commit " "(%zu stars), %zu unavailable in %.3f s (mark %.3f, load+commit "
"%.3f); %d loader workers\n", "%.3f); %d loader workers\n",
@@ -2029,11 +2030,11 @@ static int render_movie(const Settings *s, StarCatalog *catalog,
result = movie_output_queue_finish(&output_queue) == 0 ? 0 : -1; result = movie_output_queue_finish(&output_queue) == 0 ? 0 : -1;
const double now = omp_get_wtime(); const double now = omp_get_wtime();
report_movie_timing_summary(&timing_acc); report_movie_timing_summary(&timing_acc);
movie_output_queue_report(&output_queue, stderr); movie_output_queue_report(&output_queue, stdout);
fprintf(stderr, fprintf(stdout,
"Movie output pipeline wall: %.4f s (producer frame-time sum %.4f s)\n", "Movie output pipeline wall: %.4f s (producer frame-time sum %.4f s)\n",
now - endpoint_start, timing_acc.sum[MOVIE_TIMING_COUNT - 1]); now - endpoint_start, timing_acc.sum[MOVIE_TIMING_COUNT - 1]);
fprintf(stderr, "Movie end-to-end wall: %.4f s\n", now - movie_wall_start); fprintf(stdout, "Movie end-to-end wall: %.4f s\n", now - movie_wall_start);
done: done:
if (output_queue_ready) if (output_queue_ready)
movie_output_queue_destroy(&output_queue); movie_output_queue_destroy(&output_queue);
@@ -2057,7 +2058,7 @@ static int render_lens_map(const Settings *s, StarCatalog *catalog) {
return -1; return -1;
} }
if (s->verbose) if (s->verbose)
fprintf(stderr, fprintf(stdout,
"Imported lens map v%u: integrator=%s step=%.8g max_steps=%u " "Imported lens map v%u: integrator=%s step=%.8g max_steps=%u "
"lookback=%.8g retry_lookback=%.8g max_total_lookback=%.8g\n", "lookback=%.8g retry_lookback=%.8g max_total_lookback=%.8g\n",
map.file_version, map.file_version,
@@ -2121,7 +2122,7 @@ static int render_lens_map(const Settings *s, StarCatalog *catalog) {
} }
if (s->fast_mode) { if (s->fast_mode) {
fast = &local_fast; fast = &local_fast;
fast_psf_accumulator_report(&local_fast, stderr); fast_psf_accumulator_report(&local_fast, stdout);
fast_psf_accumulator_set_verbose(&local_fast, s->verbose); fast_psf_accumulator_set_verbose(&local_fast, s->verbose);
} }
/* A multi-frame imported map runs the same movie-level union prefetch and /* A multi-frame imported map runs the same movie-level union prefetch and
@@ -2147,7 +2148,7 @@ static int render_lens_map(const Settings *s, StarCatalog *catalog) {
return -1; return -1;
} }
const double load_seconds = omp_get_wtime() - load_start; const double load_seconds = omp_get_wtime() - load_start;
fprintf(stderr, fprintf(stdout,
"Movie catalog prefetch: %zu unique requested, %zu newly loaded " "Movie catalog prefetch: %zu unique requested, %zu newly loaded "
"(%zu stars), %zu unavailable in %.3f s (mark %.3f, load+commit " "(%zu stars), %zu unavailable in %.3f s (mark %.3f, load+commit "
"%.3f); %d loader workers\n", "%.3f); %d loader workers\n",
@@ -2262,7 +2263,7 @@ static int render_lens_map(const Settings *s, StarCatalog *catalog) {
if (s->draw_mesh) if (s->draw_mesh)
fputs("Dummy PSF backend ignores --draw-mesh.\n", stderr); fputs("Dummy PSF backend ignores --draw-mesh.\n", stderr);
free(hdr); free(hdr);
fprintf(stderr, fprintf(stdout,
"Dummy PSF classified %zu images from %zu catalog stars; no HDR, PNG, or PPM was written.\n", "Dummy PSF classified %zu images from %zu catalog stars; no HDR, PNG, or PPM was written.\n",
images, catalog->count); images, catalog->count);
report_psf_splat(s, &psf_stats); report_psf_splat(s, &psf_stats);
@@ -2273,8 +2274,8 @@ static int render_lens_map(const Settings *s, StarCatalog *catalog) {
if (movie_output_queue_finish(&output_queue)) if (movie_output_queue_finish(&output_queue))
result = -1; result = -1;
report_movie_timing_summary(&timing_acc); report_movie_timing_summary(&timing_acc);
movie_output_queue_report(&output_queue, stderr); movie_output_queue_report(&output_queue, stdout);
fprintf(stderr, "Movie output pipeline wall: %.4f s\n", fprintf(stdout, "Movie output pipeline wall: %.4f s\n",
omp_get_wtime() - pipeline_start); omp_get_wtime() - pipeline_start);
movie_output_queue_destroy(&output_queue); movie_output_queue_destroy(&output_queue);
} }
@@ -2300,6 +2301,10 @@ static int write_minkowski_accel_track(const Settings *s) {
int main(int argc, char **argv) { int main(int argc, char **argv) {
Settings settings; Settings settings;
const char *write_path; const char *write_path;
/* Line-buffer stdout so redirected progress is visible promptly, matching
* stderr. This adds no new synchronization: the built-in stdout stream lock
* already serializes the render workers and the async movie writer. */
setvbuf(stdout, NULL, _IOLBF, 0);
if (argc == 2 && !strcmp(argv[1], "--help")) { if (argc == 2 && !strcmp(argv[1], "--help")) {
print_help(argv[0]); print_help(argv[0]);
return 0; return 0;
@@ -2342,7 +2347,7 @@ int main(int argc, char **argv) {
} }
#ifdef GR_DEBUG #ifdef GR_DEBUG
fputs("Debug build: low-frequency render progress is enabled; direct PSF " fputs("Debug build: low-frequency render progress is enabled; direct PSF "
"fallbacks log immediately from their splat worker.\n", stderr); "fallbacks log immediately from their splat worker.\n", stdout);
#endif #endif
if (write_path != NULL) if (write_path != NULL)
return catalog_write_octant_grid(write_path) == 0 ? 0 return catalog_write_octant_grid(write_path) == 0 ? 0
@@ -2491,10 +2496,10 @@ int main(int argc, char **argv) {
spacetime_destroy(&spacetime); spacetime_destroy(&spacetime);
return 1; return 1;
} }
fprintf(stderr, "Created test catalog: %s\n", settings.catalog_path); fprintf(stdout, "Created test catalog: %s\n", settings.catalog_path);
} }
if (blackbody_backend_init(settings.blackbody_table_path, if (blackbody_backend_init(settings.blackbody_table_path,
0, NAN, NAN, NULL, stderr)) { 0, NAN, NAN, NULL, stdout)) {
fprintf(stderr, fprintf(stderr,
"Blackbody backend '%s' initialization failed; the LUT loads the " "Blackbody backend '%s' initialization failed; the LUT loads the "
"repository CIE GRBBLUT3 table by default or a valid explicit " "repository CIE GRBBLUT3 table by default or a valid explicit "
@@ -2504,7 +2509,7 @@ int main(int argc, char **argv) {
spacetime_destroy(&spacetime); spacetime_destroy(&spacetime);
return 1; return 1;
} }
fprintf(stderr, "Blackbody backend: %s\n", blackbody_backend_name()); fprintf(stdout, "Blackbody backend: %s\n", blackbody_backend_name());
/* `reserve-one` must be applied before any fast-mode accumulator is built: /* `reserve-one` must be applied before any fast-mode accumulator is built:
* the FFTW plans in fast_psf_accumulator_init() snapshot omp_get_max_threads() * the FFTW plans in fast_psf_accumulator_init() snapshot omp_get_max_threads()
* at creation time, so shrinking the pool later would leave the plans (and * at creation time, so shrinking the pool later would leave the plans (and
@@ -2530,11 +2535,11 @@ int main(int argc, char **argv) {
return 1; return 1;
} }
settings.fast_psf = &fast_accumulator; settings.fast_psf = &fast_accumulator;
fast_psf_accumulator_report(&fast_accumulator, stderr); fast_psf_accumulator_report(&fast_accumulator, stdout);
fast_psf_accumulator_set_verbose(&fast_accumulator, settings.verbose); fast_psf_accumulator_set_verbose(&fast_accumulator, settings.verbose);
} else if (settings.fast_mode) { } else if (settings.fast_mode) {
fputs("Fast mode on an imported lens map uses the map's own dimensions.\n", fputs("Fast mode on an imported lens map uses the map's own dimensions.\n",
stderr); stdout);
} }
if (!settings.fast_mode && !settings.psf_direct && if (!settings.fast_mode && !settings.psf_direct &&
psf_kernel_cache_init(&settings.psf_cache, &settings.psf, psf_kernel_cache_init(&settings.psf_cache, &settings.psf,
@@ -2551,7 +2556,7 @@ int main(int argc, char **argv) {
#endif #endif
} }
if (!settings.fast_mode) if (!settings.fast_mode)
psf_kernel_cache_report_ready(&settings.psf_cache, stderr); psf_kernel_cache_report_ready(&settings.psf_cache, stdout);
if (settings.lens_map_input_path != NULL) { if (settings.lens_map_input_path != NULL) {
const int result = render_lens_map(&settings, &catalog); const int result = render_lens_map(&settings, &catalog);
catalog_destroy(&catalog); catalog_destroy(&catalog);
src/movie_output.c
+4 -4
View File
@@ -16,23 +16,23 @@ static int movie_output_default_write(void *context, const MovieOutputJob *job,
if (write_rgb8_image(job->output_path, job->clean_rgb8, job->width, if (write_rgb8_image(job->output_path, job->clean_rgb8, job->width,
job->height, settings)) job->height, settings))
return -1; return -1;
fprintf(stderr, "Rendered %zu images from %zu catalog stars to %s (ok%s)\n", fprintf(stdout, "Rendered %zu images from %zu catalog stars to %s (ok%s)\n",
job->images, job->catalog_stars, job->output_path, job->note); job->images, job->catalog_stars, job->output_path, job->note);
if (job->draw_mesh && job->mesh_rgb8 != NULL) { if (job->draw_mesh && job->mesh_rgb8 != NULL) {
if (write_rgb8_image(job->mesh_path, job->mesh_rgb8, job->width, if (write_rgb8_image(job->mesh_path, job->mesh_rgb8, job->width,
job->height, settings)) job->height, settings))
return -1; return -1;
fprintf(stderr, "Wrote mesh overlay image: %s\n", job->mesh_path); fprintf(stdout, "Wrote mesh overlay image: %s\n", job->mesh_path);
} }
if (job->has_psf_stats) { if (job->has_psf_stats) {
if (job->fast_mode) if (job->fast_mode)
fprintf(stderr, fprintf(stdout,
"Fast PSF splats: deposited %zu, wing-clipped %zu, discarded " "Fast PSF splats: deposited %zu, wing-clipped %zu, discarded "
"below min-Y %zu\n", "below min-Y %zu\n",
job->psf_stats.cached_splats, job->psf_stats.cached_wing_clipped, job->psf_stats.cached_splats, job->psf_stats.cached_wing_clipped,
job->psf_stats.discarded_below_min_y); job->psf_stats.discarded_below_min_y);
else else
psf_kernel_cache_report(NULL, &job->psf_stats, stderr); psf_kernel_cache_report(NULL, &job->psf_stats, stdout);
} }
return 0; return 0;
} }
src/optics.c
+2 -2
View File
@@ -251,7 +251,7 @@ void psf_kernel_cache_report(const PsfKernelCache *cache,
stats->gpu_upload_seconds, stats->gpu_kernel_seconds, stats->gpu_upload_seconds, stats->gpu_kernel_seconds,
stats->gpu_download_seconds); stats->gpu_download_seconds);
if (stats != NULL && stats->discarded_below_min_y != 0) if (stats != NULL && stats->discarded_below_min_y != 0)
fputs("Warning: --psf-min-y discarded one or more PSF events.\n", stream); fputs("Warning: --psf-min-y discarded one or more PSF events.\n", stderr);
#ifdef GR_DEBUG #ifdef GR_DEBUG
if (stats != NULL) if (stats != NULL)
fprintf(stream, "Debug: max raw magnification %.6g; magnification-clamped " fprintf(stream, "Debug: max raw magnification %.6g; magnification-clamped "
@@ -705,7 +705,7 @@ int fast_psf_accumulator_resolve(FastPsfAccumulator *accumulator,
accumulator->fftw_last_timing = timing; accumulator->fftw_last_timing = timing;
accumulator->fftw_frame_seconds = omp_get_wtime() - start; accumulator->fftw_frame_seconds = omp_get_wtime() - start;
if (accumulator->verbose) if (accumulator->verbose)
fprintf(stderr, fprintf(stdout,
"Fast FFTW frame: zero_pack=%.6f forward=%.6f " "Fast FFTW frame: zero_pack=%.6f forward=%.6f "
"multiply=%.6f inverse=%.6f crop_downsample=%.6f " "multiply=%.6f inverse=%.6f crop_downsample=%.6f "
"total=%.6f\n", "total=%.6f\n",
tests/test_adaptive_cli.py
+4 -4
View File
@@ -130,9 +130,9 @@ def endpoint_deviation(a, b):
return mismatches, worst return mismatches, worst
def trace_cost(stderr, label): def trace_cost(text, label):
match = re.search(label + r' trace cost: accepted=(\d+) rejected=(\d+) ' match = re.search(label + r' trace cost: accepted=(\d+) rejected=(\d+) '
r'rhs=(\d+)', stderr) r'rhs=(\d+)', text)
return None if match is None else match.groups() return None if match is None else match.groups()
@@ -263,8 +263,8 @@ with tempfile.TemporaryDirectory(prefix='gr-adaptive-cli-',
replay_hdr = replay_out.with_name(replay_out.stem + '_HDR.fits') replay_hdr = replay_out.with_name(replay_out.stem + '_HDR.fits')
assert dflt_out.with_name(dflt_out.stem + '_HDR.fits').read_bytes() \ assert dflt_out.with_name(dflt_out.stem + '_HDR.fits').read_bytes() \
== replay_hdr.read_bytes() == replay_hdr.read_bytes()
live_cost = trace_cost(dflt_run.stderr, 'Frame 0') live_cost = trace_cost(dflt_run.stdout, 'Frame 0')
replay_cost = trace_cost(replay_run.stderr, 'Imported map') replay_cost = trace_cost(replay_run.stdout, 'Imported map')
assert live_cost is not None and replay_cost is not None assert live_cost is not None and replay_cost is not None
assert live_cost == replay_cost, (live_cost, replay_cost) assert live_cost == replay_cost, (live_cost, replay_cost)
tests/test_camera_cli.py
+8 -8
View File
@@ -150,7 +150,7 @@ with tempfile.TemporaryDirectory(prefix='gr-camera-cli-', dir='/tmp/opencode') a
fast_path = tmp / f'minkowski_fast.{ext}' fast_path = tmp / f'minkowski_fast.{ext}'
fast = run(binary, *common, '--fast-mode', '--fast-supersample', 2, fast = run(binary, *common, '--fast-mode', '--fast-supersample', 2,
'--output', fast_path) '--output', fast_path)
assert 'Fast FFTW:' in fast.stderr, fast.stderr assert 'Fast FFTW:' in fast.stdout, fast.stdout
assert image_payload(fast_path) assert image_payload(fast_path)
# Equivalent independently specified and inferred camera geometry. # Equivalent independently specified and inferred camera geometry.
@@ -227,8 +227,8 @@ with tempfile.TemporaryDirectory(prefix='gr-camera-cli-', dir='/tmp/opencode') a
tmp / 'missing_catalog.csv', '--output', long_path, tmp / 'missing_catalog.csv', '--output', long_path,
ok=False) ok=False)
assert 'Mesh overlay output path is too long' in too_long.stderr, too_long.stderr assert 'Mesh overlay output path is too long' in too_long.stderr, too_long.stderr
assert 'Blackbody backend' not in too_long.stderr, too_long.stderr assert 'Blackbody backend' not in (too_long.stdout + too_long.stderr), too_long.stderr
assert 'PSF cache ready' not in too_long.stderr assert 'PSF cache ready' not in (too_long.stdout + too_long.stderr)
errors = [ errors = [
(['--observer-time'], None), (['--observer-time'], None),
@@ -294,7 +294,7 @@ with tempfile.TemporaryDirectory(prefix='gr-camera-cli-', dir='/tmp/opencode') a
if message: if message:
assert message in result.stderr, result.stderr assert message in result.stderr, result.stderr
assert not missing_catalog.exists(), result.stderr assert not missing_catalog.exists(), result.stderr
assert 'PSF cache ready' not in result.stderr assert 'PSF cache ready' not in (result.stdout + result.stderr)
track = tmp / f'{backend}.csv' track = tmp / f'{backend}.csv'
run(TESTDIR / f'test_observer_{backend}', track) run(TESTDIR / f'test_observer_{backend}', track)
@@ -397,8 +397,8 @@ with tempfile.TemporaryDirectory(prefix='gr-camera-cli-', dir='/tmp/opencode') a
'--sensor-bloom-transfer', 0.5, '--sensor-bloom-transfer', 0.5,
'--output', bloom_output) '--output', bloom_output)
assert image_payload(bloom_output) != baseline assert image_payload(bloom_output) != baseline
assert 'Sensor bloom:' in bloom_run.stderr, bloom_run.stderr assert 'Sensor bloom:' in bloom_run.stdout, bloom_run.stdout
report = bloom_run.stderr.split('Sensor bloom:', 1)[1].splitlines()[0] report = bloom_run.stdout.split('Sensor bloom:', 1)[1].splitlines()[0]
fields = dict(token.split('=', 1) for token in report.split() if '=' in token) fields = dict(token.split('=', 1) for token in report.split() if '=' in token)
assert int(fields['saturated']) > 0, report assert int(fields['saturated']) > 0, report
assert int(fields['iterations'].split('/')[0]) >= 1, report assert int(fields['iterations'].split('/')[0]) >= 1, report
@@ -443,8 +443,8 @@ with tempfile.TemporaryDirectory(prefix='gr-camera-cli-', dir='/tmp/opencode') a
'--movie-track-samples', '--frames-dir', tmp, '--movie-track-samples', '--frames-dir', tmp,
'--frames-prefix', 'mixed', '--verbose', '--frames-prefix', 'mixed', '--verbose',
'--lens-map-output', parallel_map) '--lens-map-output', parallel_map)
assert 'Ray trace generation 1: frame 0 added' in result.stderr assert 'Ray trace generation 1: frame 0 added' in result.stdout
assert 'Ray trace generation 0: frame 1 added' not in result.stderr assert 'Ray trace generation 0: frame 1 added' not in result.stdout
for frame in range(2): for frame in range(2):
image_payload(tmp / f'mixed_{frame:06d}.{ext}', image_payload(tmp / f'mixed_{frame:06d}.{ext}',
dimensions=(64, 36), allow_black=True) dimensions=(64, 36), allow_black=True)
tests/test_output_streams.py
+150
View File
@@ -0,0 +1,150 @@
#!/usr/bin/env python3
"""Regression test for the stdout/stderr split of the production CLI.
Normal progress, startup/backend configuration, successful file outputs,
timings and cache summaries are normal informational output and must go to
stdout. Genuine warnings, errors and the Debug per-event direct-fallback
diagnostic go to stderr. A mixed success/error line such as
``Rendered ... (ok|write failed)`` must follow its outcome.
The checks capture the two streams separately so that a future change which
silently moves a normal message to stderr (or an error to stdout) is caught.
Small deterministic Minkowski scenes keep the runtime short.
"""
import os
import subprocess
import sys
import tempfile
from pathlib import Path
# Keep scratch data inside the pre-approved OpenCode scratch directory.
TMP_ROOT = Path('/tmp/opencode')
TMP_ROOT.mkdir(parents=True, exist_ok=True)
BUILD = Path(sys.argv[1] if len(sys.argv) > 1 else 'build/Release').resolve()
ENV = dict(os.environ, OMP_NUM_THREADS='4')
COMMON = ['--catalog', 'assets/sky_grid_5deg.csv', '--width', 16, '--height', 8,
'--fov-deg', 80, '--exposure', 1e-3, '--coarse-cell-pixels', 8,
'--refine-max-level', 0, '--psf-relative-tail', 1e-4]
def run(binary, *args, env=ENV):
return subprocess.run([str(binary), *map(str, args)], env=env,
capture_output=True, text=True)
def stderr_errors(result):
"""Non-advisory stderr lines.
A Debug build deliberately logs each direct PSF fallback from the active
splat worker; those ``Debug:`` lines are real diagnostics, not a misplaced
normal message, so they are excluded when the Debug startup banner is
present on stdout.
"""
lines = [line for line in result.stderr.splitlines() if line.strip()]
if 'Debug build:' in result.stdout:
lines = [line for line in lines if not line.startswith('Debug:')]
return lines
binary = BUILD / 'minkowski_sky'
assert binary.exists(), f'missing {binary}'
# The image extension follows the build's compiled writer, exactly as
# tests/test_camera_cli.py detects it from --help (a libpng build advertises
# `.png`, a PNG-less build advertises `.ppm`).
help_text = run(binary, '--help').stdout
ext = 'png' if '.png' in help_text else 'ppm'
with tempfile.TemporaryDirectory(prefix='gr-output-streams-',
dir=str(TMP_ROOT)) as directory:
tmp = Path(directory)
# 1) --help is informational: complete usage on stdout, nothing on stderr.
help_result = run(binary, '--help')
assert help_result.returncode == 0, help_result.stderr
assert 'Usage:' in help_result.stdout, help_result.stdout
assert help_result.stderr == '', help_result.stderr
# 2) An unknown option is an error: usage diagnostic on stderr only.
bad_result = run(binary, '--not-an-option')
assert bad_result.returncode != 0, bad_result.stdout
assert bad_result.stdout == '', bad_result.stdout
assert bad_result.stderr != '', 'missing error diagnostic on stderr'
# 3) A successful non-verbose single-frame render puts every startup,
# statistics and success line on stdout with an empty stderr.
single_out = tmp / f'single.{ext}'
single = run(binary, *COMMON, '--output', single_out)
assert single.returncode == 0, single.stderr
assert single_out.exists(), single.stderr
assert 'Blackbody backend:' in single.stdout, single.stdout
assert 'PSF cache ready:' in single.stdout, single.stdout
assert 'Rendered' in single.stdout and '(ok)' in single.stdout, single.stdout
assert '(write failed)' not in single.stdout, single.stdout
assert not stderr_errors(single), single.stderr
# 4) Verbose progress (including the trace-cost line) is still stdout.
verbose_out = tmp / f'verbose.{ext}'
verbose = run(binary, *COMMON, '--verbose', '--output', verbose_out)
assert verbose.returncode == 0, verbose.stderr
assert 'Frame 0: tracing' in verbose.stdout, verbose.stdout
assert 'Frame 0 trace cost:' in verbose.stdout, verbose.stdout
assert not stderr_errors(verbose), verbose.stderr
# 5) A short movie exercises the asynchronous writer; its per-frame logs,
# timing summary and writer summary are stdout, stderr stays empty. The
# 2 s fixture track plus --duration 1 --fps 1 yields two frames, so the
# async producer/writer overlap is actually exercised.
track = tmp / 'track.csv'
track_run = run(binary, '--write-minkowski-accel-track', track,
'--duration', 2, '--fps', 30, '--proper-acceleration', 1.52)
assert track_run.returncode == 0, track_run.stderr
assert track.exists(), track_run.stderr
frames_dir = tmp / 'frames'
frames_dir.mkdir()
movie = run(binary, *COMMON, '--observer-track', track, '--frames-dir',
frames_dir, '--frames-prefix', 'frame', '--duration', 1,
'--fps', 1, '--verbose', '--output', tmp / f'movie.{ext}')
assert movie.returncode == 0, movie.stderr
assert (frames_dir / f'frame_000000.{ext}').exists(), movie.stderr
assert (frames_dir / f'frame_000001.{ext}').exists(), movie.stderr
assert 'Ray trace generation' in movie.stdout, movie.stdout
assert movie.stdout.count('Rendered') == 2, movie.stdout
assert movie.stdout.count('(ok)') == 2, movie.stdout
assert 'Movie timing total' in movie.stdout, movie.stdout
assert 'Movie writer summary:' in movie.stdout, movie.stdout
assert 'Movie end-to-end wall:' in movie.stdout, movie.stdout
assert not stderr_errors(movie), movie.stderr
# 6) A genuine warning goes to stderr and does not disturb the success line
# on stdout. The fast-mode preview advisory is deterministic in the CPU
# build.
fast_out = tmp / f'fast.{ext}'
fast = run(binary, *COMMON, '--fast-mode', '--output', fast_out)
assert fast.returncode == 0, fast.stderr
assert 'Fast mode is a preview approximation' in fast.stderr, fast.stderr
assert fast.stdout.count('Rendered') == 1, fast.stdout
assert '(ok)' in fast.stdout, fast.stdout
# The only stderr content is the advisory: no normal line leaked across.
assert len(stderr_errors(fast)) == 1, fast.stderr
# 7) A failed write must route the mixed success/error line to stderr and
# leave stdout free of the success wording.
missing_dir = tmp / 'missing_subdir' / f'out.{ext}'
failed = run(binary, *COMMON, '--output', missing_dir)
assert failed.returncode != 0, failed.stdout
assert '(write failed)' in failed.stderr, failed.stderr
assert '(write failed)' not in failed.stdout, failed.stdout
# 8) A rejected camera velocity is an error on stderr, not stdout.
velocity = run(binary, *COMMON, '--observer-velocity', 10, 0, 0,
'--output', tmp / f'velocity.{ext}')
assert velocity.returncode != 0, velocity.stdout
assert 'not timelike' in velocity.stderr, velocity.stderr
# stdout may hold only the Debug startup banner; no render ran.
assert 'Rendered' not in velocity.stdout, velocity.stdout
print('output-stream checks passed: normal success stdout / diagnostics '
'stderr', flush=True)
usage.md
+3
View File
@@ -622,6 +622,9 @@ overlay alpha-composites image-plane triangle edges as one-pixel-wide 0.5
linear-gray diagnostic lines at 0.5 opacity. The line rasterizer uses linear-gray diagnostic lines at 0.5 opacity. The line rasterizer uses
coverage-based antialiasing. coverage-based antialiasing.
Normal progress and summaries go to stdout; warnings, errors, and Debug
diagnostics go to stderr. Successful runs exit `0` even if warnings are emitted.
## HDR output ## HDR output
To preserve a single-frame render for later exposure and tone-mapping work, To preserve a single-frame render for later exposure and tone-mapping work,