Diagnostics and Telemetry - limztudio/NWBLot GitHub Wiki
NWBLot diagnostics cover logging, crash packaging, GPU crash reports, telemetry capture, frame graph capture, and smoke/regression output. Diagnostics are runtime features, not just test helpers.
Engine tools and runtime executables use the logger client/server system where available. Standalone logger support exists for tools and non-server runs.
The shared logging contracts belong to NWB::Core::Common in core/common/log.h: ILogger, LoggerRegistrationGuard, and LogType. Logger clients and servers consume these owners directly. Current logger-domain LogArena, LogString, and BreakPolicy aliases continue to express its allocation, text, and diagnostic policies.
Important expectations:
- tools should use
NWB_LOGGER_*APIs where practical - non-interactive tools should avoid ad hoc console output for engine diagnostics
- logger macros support format-checked formatted calls
- logger macros also support single-argument raw message calls
The loader can attach telemetry upload through the logger client. Smoke tests may launch a log server when the target exists, or run with --no-logserver.
The Windows log-server frame waits for native messages through GetMessage instead of polling an empty update hook. WM_CLOSE destroys the window; WM_DESTROY releases the font, clears the window handles, and ends the message loop. Linux retains signal-driven exit with its existing sleep cadence. Concrete logger workers supply their actual initialization/update/shutdown behavior; queued workers still wake, drain, and join before client resources and files are closed, while the server stops its daemon and crash-ingest worker before joining the log worker.
The server enqueues its listening message after successful frame initialization, so the worker cannot consume it before the message store and native list exist. The Windows logger smoke sends real HTTP log messages before and after an active idle interval and requires an HTTP 200 empty response, fresh file output, additional visible rows, and painted glyphs in the captures. It also checks idle process CPU and clean WM_CLOSE shutdown; file output alone cannot satisfy the display check.
If application startup fails, the launcher closes the profile logserver it created for that run. This includes a requested process-stop failure before application creation, even when detach was requested.
Processed log-file writes are checked. The standalone client reports write failure to stderr; the server reports it through the log frame and, on Windows, stderr. Linux emits one console diagnostic through the frame. Failure reporting does not enqueue another message into the failing file.
The FBX converter routes semantic argument rejection through the existing CLI validation-error/exit contract. Required invalid-argument explanations go to stderr even when ordinary warning/error logger output is compiled out in fin. Retired asset-type spellings remain rejected, and argument rejection preserves an existing destination.
Smoke-contract route/dispatch logs are NWB_LOGGER_ESSENTIAL_INFO (not plain INFO) so capture smokes can assert them in fin/NWB_FINAL builds, where NWB_OCCUR_INFO is false and ordinary INFO lines compile out. GraphicsRuntime: Back buffer resized to WxH is likewise ESSENTIAL so the stress-resize smoke can poll for it in fin.
The loader exposes --gpudbg only in dbg and opt; fin rejects the option. CSG, caustic, and UI capture wrappers default validation on; use --no-gpu-validation with a fin executable. The generic window_capture_smoke.py defaults validation off and accepts --gpu-validation for dbg/opt. Verify requested validation through Loader: GPU debug validation enabled. Continue rejecting warnings, errors, assertions, and native validation diagnostics; external loader/layer environment configuration remains part of runtime admission.
Optimized and final builds can emit .namesym sidecars so hash-style Name debug tokens can be decoded back to readable strings. NWB_BUILDMODE installs the runtime name-symbol registry and writes a sidecar on normal executable shutdown. The on-demand nwb_namesym target drives a separate build-mode preset, runs a headless pipeline cook (pipeline/launch.py over impl/assets and tests/smoke/assets) and selected graceful window-capture workloads, then copies sidecars such as dependency_computer.namesym, asset_builder.namesym, asset_gatherer.namesym, and testbed.namesym next to the normal configuration outputs. Build-mode symbol export includes retained arena owner names. Before new capture workloads run, old sidecars must be removed successfully; a cleanup failure aborts capture and publication, preserving the previously published destination sidecars.
Name-symbol resolution is server-owned in the current logger flow. The log server loads sidecars from its executable directory at startup and decodes hash tokens as it formats incoming log lines. The logger client should not load or upload its own name-symbol table in normal operation; if a client cannot see a sidecar, Name::c_str() falls back to hash text in optimized/final builds.
The loader installs crash capture before command-line parsing and logging setup. Early install means failures during startup can still produce a package.
Crash packages can include:
- process crash data
- runtime metadata
- GPU debug metadata
- GPU crash text report
- AMD Radeon GPU Detective dump
- NVIDIA Aftermath dump
- Vulkan device fault details
The crash path should always emit at least a minimal gpu_crash.txt when GPU crash capture is invoked, even if richer vendor diagnostics are unavailable.
After each crash upload, the log server applies independent retention to the extracted packages, raw uploaded archives, and invalid archives. The defaults retain 256 extracted packages, 256 raw archives, and 64 invalid archives. Operators can override those caps with --crash-retain-packages, --crash-retain-raw, and --crash-retain-invalid; setting an individual cap to 0 disables pruning for that category.
Vendor dump package names:
- AMD RGD/device-fault bytes:
gpu_crash.rgd - NVIDIA Aftermath:
gpu_crash.nv-gpudmp - text report:
gpu_crash.txt
Device-lost handling captures the crash before debug-trapping error logs.
The Vulkan backend emits one authored nested marker path through:
- NVIDIA diagnostic checkpoints
- AMD buffer-marker breadcrumbs
- internal marker tracking
Each CommandList owns only its active marker text and nesting offsets. The Device owns the marker dictionary for its complete lifetime. That concurrent dictionary is append-only: an exact repeated path reuses its id, a real hash collision probes to another nonzero id, and a published string never moves or disappears. Resolved string views therefore remain valid while other command lists insert markers and after the command list that authored a marker is destroyed. Resetting a command-list marker stack does not erase device history needed by in-flight crash reports.
Every marker owner receives an exact token containing the command-list recording lease serial, native recording id, and marker serial. Ending or abandoning a stale or mismatched token cannot pop another owner's marker, including after command-list reuse. Command-list exception/destruction cleanup closes native labels where possible and clears active nesting without logging, allocation, callbacks, or GPU polling; the device history remains available to NVIDIA, AMD, and internal report resolution.
The frame owns telemetry capture and upload plumbing. ProjectRuntimeContext exposes:
setTelemetryCaptureflushTelemetryUpload
Telemetry capture options can include:
- disabled capture
- frame graph only
- perf only
- all events
Telemetry events include text logs, diagnostics, frame graph frames, perf frames, and memory frames depending on capture flags. Payload parsers return Expected<Payload> from the existing telemetry arena. DecodeEvent returns Expected<DecodedEvent, DecodeResult> with the event and consumed byte count; DecodeEventStream returns the consumed count while mutating the caller-owned Recorder. Failures preserve decoder status and offsets. BuildTelemetryReport returns its owning report after admission, while encoding/build helpers preserve reusable byte capacity. Check results before reading or moving them; see Diagnostics and Invariants. Telemetry::Recorder reuses event slots and payload capacity across enabled frames; clear() while capture is disabled releases them.
The current memory payload uses version 1 with a 192-byte header. Readers accept only this version. Each memory record names its source as arena, heapBacking, or explicitScope, reports reserved/used/peak bytes plus allocation counts, and includes a peakBasis of largestArena, sampledHeap, or scope. Arena owners are aggregated by canonical Name for the process lifetime; heapBacking is the inclusive CoreAlloc total and must not be added to arena usage. Allocation hot paths update per-arena atomics and a thread-local heap shard; they do not format text, walk stacks, or look up the owner registry. The named CPU-task arena identity is core/task/cpu/scheduler (TaskArenaScope::s_CpuTaskScheduler); the former core/task/cpu/dependencies identity is gone at current main. Perf scope creation follows the same setup/consume split as the renderer: Session::ensureMemoryScopes registers arena scopes once per published frame while the record loop only consumes them, TimingRecorder::recordSample(Name) and MemoryRecorder::recordSnapshot(Name) are consume-only (they find an existing scope and skip if missing), and per-frame update/render paths must use the scope-id overloads with a scope registered during setup. See docs/allocation_perf_telemetry.md and docs/large_source_domain_review.md.
The logger-side telemetry report emits a stable events map for the contiguous core event kinds through memoryFrame, including zero-count kinds. Unrecognized kinds are bucketed as unknown. When adding a telemetry event kind, update the report mapping and its final counted kind so uploaded JSON stays complete and forward-compatible.
Perf capture can be enabled independently from telemetry upload. ProjectRuntimeContext::setPerfCapture(Core::Perf::CaptureOptions::GpuTimingOnly()) enables the perf-session sink and the graphics GPU query recorder, and ProjectRuntimeContext::gpuTimingView() exposes the read-only timing view to project code.
When CPU timing is active, Frame enables CpuTaskScheduler profiling for that frame and Perf::CollectCpuTaskProfile() drains events on the timing-sink owner thread before publication. Worker threads never call the non-thread-safe timing recorder. Named execution scopes cover graphics setup/frame work, ECS worlds, and project work; other events use cpu.task.queue_delay, cpu.task.execution, cpu.task.handle_join, cpu.task.scope_join, cpu.task.scheduler_join, and cpu.worker.idle. Disabled profiling allocates no event buffers and reads no clocks on the scheduling hot path. Failed or quit frames discard unpublished CPU profiling data. See CPU Task Scheduler.
Renderer command recording publishes per-pass GPU scopes such as shadow visibility, caustic photons, caustic resolve, surfel GI spawn/age-free/hash-build/trace/resolve/upsample, deferred lighting, material draws, CSG work, AVBOIT passes, and reflection classify/tracing/filtering. GPU timing is asynchronous: the visible timing window reflects previously collected query results rather than the work submitted later in the same project update. Published windows can mix samples from several source frames or contain only part of one frame; the current sidecar fields window_avg_ms, window_min_ms, window_max_ms, and published_windows describe those publication-window totals and their count. The parser rejects the retired avg_ms, min_ms, max_ms, and samples names. The file sink also exports total_ms, gpu_samples, and sample_avg_ms so benchmarks normalize by actual dispatches instead of publication cadence; a multi-dispatch pass must account for its known dispatches per frame.
The compiled GPU task graph owns a timing ticket for every timed packet. Packet count and physical-queue placement are compiler results: compatible work may serialize on Graphics when no dedicated queue exists, while a dedicated topology can expose independent Graphics/Compute work and AVBOIT packet boundaries. The render.frame transaction begins with the graph's frame work and publishes only after the terminal presentation packet is accepted, so it measures a critical path rather than a sum of queue durations. Stage envelopes include render.async_prefix, render.async_shadow, render.async_surfel_gi, and render.async_final. Where queue timestamp domains support comparison, render.deferred_graph.queue_overlap measures overlap among the compiled timed packets rather than estimating it from the schedule.
A timestamp-capable Transfer-only queue can record timestamp writes but cannot perform the engine's inline query reset. Available query pools are reset on a Graphics- or Compute-capable frame-preamble command list outside rendering. Its accepted physical-queue token becomes an exact prerequisite of the timing ticket, is merged with the packet's other waits, and is preserved when the timed packet records on Transfer or another physical queue. This keeps reset and timestamp writes ordered on the Vulkan device timeline without a host reset or an illegal transfer-queue reset command.
GpuTimingMeasure owns both its query scope and the exact command-marker token that opened with it. Normal destruction closes the already reserved query claim without growing persistent storage. If recording fails or an exception is unwinding, it abandons the query and exact marker callback-free; it cannot close a foreign top marker or a marker from a reused recording. Submission-attempt unwind similarly abandons unresolved timing tickets without observers, while accepted tickets publish only against their exact accepted queue token.
Submission validates both endpoints of every timing scope: the begin and end command lists must be present in order, must still own the captured recording-lease serials, and must still carry the exact Vulkan query incarnation and generation claimed during recording. A producer-only, reversed, stale, or replaced endpoint is rejected before native submission. Non-terminal ordering mistakes leave the ticket unchanged so the caller can submit the complete ordered batch; stale native ownership is discarded terminally rather than attributed to a different recording.
If a begin endpoint is accepted but the matching end is later discarded, that exact native query is quarantined and can never become Available. The following frame excludes the quarantined slot and allocates or resets a replacement through the normal queue-valid preamble. This avoids publishing an incomplete duration or host-resetting a query that may still be referenced by accepted GPU work.
If a later frame packet is rejected after a frame begin was accepted, a frame-recovery submission retires the begun timestamp without publishing a partial render.frame sample. If that recovery cannot be accepted, the renderer requests device recreation rather than reusing incomplete state. This makes timing match the accepted-submission boundary and prevents query leakage.
GPU timing ownership follows the packet transaction. GpuTimingSubmissionTicket prepares scopes before native submission, confirms them only after a valid queue token, and discards or quarantines affected query ownership when the submission path fails. This remains safe when independent packets enter native submission concurrently because timing resolution is part of the serialized graph-publication tail. The implementation is separated into recorder/public API (gpu_timing.*), accumulation (gpu_timing_accumulator.cpp), listener delivery (gpu_timing_listener.cpp), and submission-token handling (gpu_timing_submission.cpp).
RendererSystem prewarms query reservations for its common GPU timing scopes during resource validation. Failure to prepare a reservation is non-fatal and is reported as a warning, but that scope may skip samples until query storage is available.
Smoke projects use GpuPassTimingProbe to fold per-pass GPU timing over short intervals and log average/min/max milliseconds per scope. When NWB_GPU_TIMING_FILE is set, the probe reads it through the shared smoke environment helper and appends the same interval report to that file so GUI smoke runs can be profiled by an automated harness without scraping the log-server window. Transparent multi, skinned caustic, GI, and stress smoke projects opt into this path so caustic photon, caustic resolve, surfel GI, shadow, and skinning costs are visible in runtime logs or the optional timing file.
Readable optimized/final GPU timing scope names depend on the log server having the matching .namesym sidecars loaded. Without those sidecars, the timing report still exists but scope tokens remain hash text.
For small shader-side A/B changes, compare the target scope against unrelated control scopes in the same run and treat changes within the control drift band as below the measurement floor.
The CPU TimingStats accumulator (core/perf/timing.*) keeps inclusive source-frame bounds as the minimum and maximum source frames: asynchronous samples can arrive out of frame order (for example reused GPU query slots publishing source frame 51 before frame 50 in one batch), so arrival endpoints must not define the bounds. The accumulator also retains duration totals, minimum/maximum durations, last-arrival duration, and publication index.
The reusable frozen A/B benchmark is tests/smoke/renderer_ab_benchmark.py (analysis in tests/integration/renderer_ab_benchmark_tests.py). It uses explicit frozen baseline/candidate executables, separate runtime directories, SHA256 physical-source manifests, a shared logserver, matched transparent-multi and reflection workloads, independent balanced AB/BA blocks, warm-up discard, retained-report and completed-GPU-frame minimums, the two-range-or-2% publication-skew bound, timings normalized by actual completed samples, identity checks around every trial, and paired full-frame inference with separate control-equivalence checks. Incomplete or unfavorable runs retain their actual status and evidence in the result report.
Reproducible renderer experiments live under tests/ab/, separate from the CTest suite. Keep only independently runnable launcher workflows in the tree; captures, logs, timing tables, diff images, and result summaries stay local under .cozter/out/ab-results/. Capture both arms from the same source revision and compare the changed scope with unrelated controls. Harnesses decode their known required scopes in normal optimized/final builds; matching optional namesym sidecars decode additional names. A fold-decimated zero sample is not a performance result; report it separately instead of treating a sparse whole-frame number as confirmation.
The async-shadow M4 harness pairs nwb_async_shadow_m4_sync_benchmark with nwb_async_shadow_m4_async_benchmark on a fixed-yaw stress scene. It checks public primary Graphics/Compute queue IDs and current device generations, and accepts an async result only for a requested, distinct, dedicated Compute-capable queue without Graphics capability. It requires render.frame, render.async_shadow, and render.async_final samples and measurable graph-owned shadow work, compares the render.frame median critical path, captures pixel parity, centers the pointer in the client rectangle before the held-frame marker (missing or nonpositive geometry and a failed SetCursorPos call fail the acquisition), and rejects native validation and ownership diagnostics. Measured overlap is diagnostic rather than a rollout threshold. It writes JSON and Markdown evidence; exit code 77 means the target lacks a distinct dedicated compute-only queue and is an environmental skip.
After wall-clock warmup, M4 snapshots timing-file EOF and waits for two valid, fully newline-terminated interval headers beginning at or after that cutoff. It discards the first potentially warmup-straddling report, starts the requested measurement duration, and parses from the second header's byte offset, retained as measurement_start_byte_offset. The timing gate uses publication windows admitted after this boundary; delayed GPU readback prevents a strict source-frame wall-time claim. Missing, malformed, or truncated output, process exit, and boundary timeout fail instead of admitting warmup reports. See the M4 harness guide for invocation.
For a separate M4 pixel-freeze diagnostic launch, NWB_STRESS_FRAME_GRAPH_FILE names the readable frame-graph JSON output, with the encoded public telemetry stream beside it at <path>.nwbs. The request requires NWB_M4_PIXEL_CAPTURE_FREEZE_FRAME and is excluded from presentation measurements; keep it unset for ordinary paired timing runs. The snapshot records one completed frame's task assignments, packets, barrier counts, and accepted submission waits. Submission counters distinguish emitted timeline waits, same-queue elisions, duplicate merges, and inherited elisions covered by prior accepted waits; planned tokens still conserve exactly. Its edges are public analysis edges: compiled state-seed IDs and extra compiler dependency IDs are not exported, so they cannot be reconstructed from those edges alone. Capture statistics are diagnostic evidence, not a timing qualification.
With ReflectionSettings::diagnosticsEnabled, the reflection readback chain publishes one completed-frame statistics record per accepted sequence, polled without waiting through RendererSystem::tryGetLatestReflectionStatistics. A record carries its source frame, requested mode, dimensions, requested and effective budgets, queue capacity, resource generation, and the accepted submission token including physical queue/device generation, plus eligible opaque/glass pixels, hardware candidates/rays/hits, screen attempts/accepted hits, fallback pixels, and optical-path counters (unsupported-path and exterior-eligible ratios, queries per admitted ray) that expose open-geometry terminations in stress diagnostics. Outcomes satisfy opaquePixels + glassPixels = screenHits + hardwareHits + fallbackPixels, and hardware rays never exceed either the effective budget or the candidate count. The reflection smoke logs each new completed sequence once and rejects stale, out-of-order, or mixed-generation samples. See Reflections.
Core::Telemetry::FrameGraphRegistry owns frame graph contributors. RendererSystem implements IFrameGraphContributor, and Testbed registers it with the context frame graph registry after creating the world.
On world destruction, Testbed unregisters the renderer contributor before clearing the world.
Window capture smoke tests can validate:
- captured image exists
- expected output dimensions
- expected visible content
- expected transparent content
- expected CSG content
- expected caustic content
- expected log message
- rejected log message
Examples:
- compute-emulated CSG smoke expects a log message indicating
CS + PSwas selected by compiling a mesh shader for compute emulation - transparent CSG smoke uses a project-owned unlit green center receiver with reflection/refraction disabled for the clipping and coverage check (so facet lighting and optical background transport cannot obscure the geometry), selects its actual frozen pose (early, mid, or late yaw), derives inset oracle regions from the projected receiver and retained geometry, requires retained pixels to identify the green receiver, and rejects
[ERROR]and shader resolution failures - caustic smoke tests reject
[ERROR]and shader resolution failures while reporting per-pass GPU timing when perf capture is enabled - GI and stress smoke tests report surfel GI timing scopes; the stress scene uses a moving mixed transparent/opaque skinned crowd inside colored walls to exercise motion, shadow, and surfel convergence together
- Testbed smoke captures
testbed_window_capture.bmp
Each Testbed run writes a timestamped startup log under the runtime output directory:
__exec/<platform>/<arch>/full/<config>/testbed_<timestamp>.log
These logs are local, per-run, untracked artifacts, so the exact filename changes every run. The startup log records the selected Vulkan adapter and the renderer feature paths active for that run. See Testbed and Platform and GPU Support.