Halcyon Diagnostics

Apps/HalcyonDiagnostics follows a diagnostics session: a JSON Lines file a running program appends to. It draws the session’s counters, object censuses and profiled frames as they arrive. It is built from the Halcyon libraries alone: Halcyon.Diagnostics for the data and the file format, Halcyon.Diagnostics.Views for the views, and Halcyon.Sdl.Vulkan for the window. It knows nothing about the program it watches. Two programs write sessions today: the BONELAB mod and the engine. The engine’s Profiler window shows the same profiler view.

Opening a session

HalcyonDiagnostics <session.jsonl>      # one session
HalcyonDiagnostics <folder>             # the folder's newest session, switching when a newer one appears
HalcyonDiagnostics                      # the last folder it was given

A folder is the usual choice, such as BONELAB’s UserData\DigitalHeaven\diagnostics. A game started again writes a new session there, and the viewer moves to it within two seconds. The window’s size and place, the last folder and the log (latest.log) are kept in the per-user config directory, HalcyonDiagnostics.

What it shows

• Counters. Every counter, with its latest reading, its change over the session and a sparkline. Select one to chart it over the whole session, with the session’s marks (level starts, servers joined) drawn across it, so a bend in the line has a cause written beside it. A counter that only grows is drawn in amber, and Growing only lists those alone. The rule is ten readings, eight of whose steps rise, with no fall bigger than 2% of the peak.
• Censuses. Every object census the program took, by exact type. A and B pick two to compare; they default to the first and the latest. The types that only grew across the last six censuses are listed above the comparison, ranked by growth per hour. Then comes the comparison itself: every type, its count in B and its change from A, the most grown first.
• Profiler. Profiled frames, in the same view as the engine’s Profiler window: a frame-time graph, a timeline with one band per thread, and the scope tree. Every number takes the profiler’s defaults.

The status line says what was opened, and what was asked for.

Asking the program for something

There is no socket. The session file is the live channel, and the requests go the other way through a second file. Census now, Mark and Profile 10 s each append one line to <session>.requests beside the session. The three buttons are as large as the tabs under them, about 56 logical pixels tall with a 20 pixel label (ActionHeight and ActionFontSize on DiagnosticsStyle), so they can be hit from inside a headset or with a ray.

Line	What the program does
census #id	Takes a census when it next can. A program may wait, such as while a level loads, and writes a note saying so
mark #id <text>	Writes a mark at once
profile #id <seconds>	Turns its scope profiler on, streams the frames’ spans, then turns it off again

The #id is a number the viewer chose, which the program echoes back in an acknowledgment. A line without one is still carried out, and nothing answers it. A program reads the request file from where it last stopped. It starts after whatever the file held when the program started, so an old request is never carried out twice.

What the buttons say

Each request goes through SessionRequestTracker, which reads the ack records the program writes (received, started, done) against a clock the viewer passes in. Pressing a button while its request is in flight does nothing. The button of a request in flight is filled with the accent.

Button	While asked	While running	Finished	No answer
Profile 10 s	Waiting for game… until the program says it started	Profiling… 9 s, counting down each second	Profile ready for four seconds, and the viewer opens the Profiler tab on the new capture’s worst frame	Game did not answer after 8 s without a received; Profile did not finish after the length plus 8 s
Census now	Census requested…		Census #3 taken for four seconds	Game did not answer after 8 s; Census still pending after 60 s once the program read it, since it may be waiting for a level to settle
Mark	Marking…		Marked at 3m12s, the session time the program stamped; the mark is drawn across the counter charts	Game did not answer after 8 s

A failure stays on its button for eight seconds. The status line under the tabs keeps the last thing that happened.

Acknowledgments

ack field	Meaning
at, id, kind	When, the request’s id, and census, mark or profile
state	received when the program read the line; started when a profile began streaming; done when the census, the mark or the whole profile is in the file
n	For a finished census, how many censuses the program has written, which is its number in the Censuses tab

A profile’s done is written after its last batch, in the same order on disk, so a viewer that sees it has every span.

The viewer marker

While it follows a folder, the viewer writes viewer.lock into it, holding its process id, and deletes it on exit. A program that writes sessions there can read it to tell its folder is being watched: the marker counts only while its process is alive, since a crash leaves the file behind. ViewerMarker in Halcyon.Diagnostics writes, reads and checks it. The BONELAB overlay’s Diagnostics entry shows “connected” for a viewer it did not start only when the marker is live.

The session format

One JSON object per line, flushed as it is written, so a reader sees each record as soon as it exists and a crash keeps everything before it. Every record names its kind in "t". Times are seconds since the session started.

t	Fields
session	format (1), program, host, started, frequency (ticks per second of the profile timestamps). Always the first line
counters	at, v: every counter’s name and value, null for one that could not be read
mark, note	at, text. A mark is a moment worth finding again; a note is the program’s remark about the session
census	at, label, walkMs, ids, types: [type, kind, count, minId, maxId] per type
scopes	names: [id, name] for profile scopes, written before the first profile record that uses them
profile	frames: [start, end]; tracks: name, order, gpu, spans as [start, end, scope]. A stretch is written as several records of at most 1000 frames or spans of one track each, which a reader files one after the other
ack	at, id, kind, state, n: the program’s answer to a request that carried an id

SessionWriter writes this JSON by hand, on netstandard2.0 as well as net10.0, so the program being diagnosed takes no JSON library of its own. SessionTail reads it, and each poll reads only what was appended since the last. A line it does not understand is counted and skipped, so an older viewer reads a newer file.

The engine writes sessions too

The engine writes the same kind of session, through the same DiagnosticsRecorder (DigitalHeaven.Core.Profiling) the BONELAB mod uses, so the viewer follows a running client or an offscreen render with nothing engine-specific in it. Turn it on with client.diagnostics.session (off by default); it is read every frame, so a running client starts and ends a session when the preference changes. client.diagnostics.sessionSeconds is the gap between counter readings (1 s by default, at least 0.1 s). The folder is diagnostics under the engine’s user data (%LocalAppData%\DigitalHeaven\Engine\diagnostics, or under DH_ENGINE_DATA_ROOT), and the log names the file.

What	Contents
Counters	frame ms mean and frame ms worst over the interval, gpu ms <pass> for every pass and gpu ms total (where the queue writes timestamps), draws, triangles, culled, vram used MiB and vram budget MiB, deferred objects, object loads pending, object upload wait ms, the netcode (net round trip ms, net pending inputs, net corrections/s, net starved ticks/s, net held frames) in a client, gc heap MiB and gc gen2. A counter nothing can read is left out rather than written as zero
Marks	map '<name>' loaded, session joined and session left, third person entered and third person left in a client; rendering map '<barcode>' in a render
Profiles	On profile, the scope profiler’s frames for the asked length. While one streams, it takes the frames in place of the Profiler window’s own history
Census	The object cache’s books: ready, stand-in, pending, failed and deferred objects. The engine has no walkable heap of typed objects, so this is its census

The reading itself costs about 100 ns a frame and a short write once an interval; a profile request is the only thing that touches the frame loop more, as above.

Offscreen renders

DigitalHeaven.Engine.Host --render out --map core:maps/render-eval --gpuTimings \
  --set client.diagnostics.session=true --set client.diagnostics.sessionSeconds=0.1

Every frame the render draws counts, and a last reading is written when the run ends, so a short render still has rows. --gpuTimings is what makes a run long enough to chart.

Viewing a capture from the Steam Machine

A run on the cube writes its session there. Fetch it and open it here:

bun Engine/scripts/fetch-cube-diagnostics.ts [remote-folder] [local-folder]   # copies the newest .jsonl, prints its path
HalcyonDiagnostics <that file>

The remote folder defaults to the engine’s diagnostics folder under ~/.local/share; pass the folder under DH_ENGINE_DATA_ROOT when the run was given one. By hand it is scp deck@cube:<folder>/<file>.jsonl ..

What a profile costs the program

A profile is the one request that touches the program’s frame loop, so it is kept off it. With the scope profiler on, a scope is two timestamps and a write into the calling thread’s own ring, with no allocation (DiagnosticsRecorderTests asserts zero bytes over ten thousand scopes). Each frame the recorder drains the rings into the capture. Once a second it hands the batch to a thread of its own, which formats the JSON from the batch alone and writes it: the frame loop never formats a span, never writes to the file and never waits for it. The writer thread formats numbers by hand into a reused buffer, so a batch allocates no string per span, and it splits a long batch into records of 1000 items so no line becomes a big allocation. A profile’s end is queued behind its last batch.

Measured headlessly, 180 frames at 60 Hz with a profile streaming (the frame loop’s EndFrame call only):

Spans per frame	Before: mean / worst	After: mean / worst
500	0.32 ms / 14.4 ms	0.12 ms / 2.1 ms
2000	0.44 ms / 14.3 ms	0.26 ms / 1.5 ms
5000	1.03 ms / 30.1 ms	0.58 ms / 3.3 ms

The worst frame was the second-boundary batch, which formatted and wrote a megabyte or more on the main thread. What is left is the drain and the sort of each frame’s spans, which is proportional to what the program records.

A picture without a window

HalcyonDiagnostics <path> --capture out.png [--tab counters|censuses|profiler] [--size 1280x800]
HalcyonDiagnostics <path> --capture out.png --press census|mark|profile --state requested|running|done|timedOut

This renders the window once, headlessly, through UiCapture, and writes the PNG. It opens no window and changes neither the saved window nor the remembered folder. --press with --state shows a request button in that state, by filing the answers it would have waited for; it never writes to a request file.