Kina.ai

Specification

Phase 1, Section 4: Observability — Tracing, Logging, Diagnostics

Phase 1: Implementation — the shape-typed core compiled end-to-end. Section 4 of 8: Observability — Tracing, Logging, Diagnostics.

1. What this section commits to

The instrumentation infrastructure that makes Phase 1 debuggable from the first day rather than from the first crisis. Specifically:

This section retrofits a gap. Sections 2 and 3 didn't commit to observability infrastructure beyond basic error handling. This section corrects that, with explicit notes on what each earlier section needs to gain.

2. Why this belongs in Phase 1, not later

The discipline is the same as for the runtime FFI design (Section 3 §6.1) and the DLPack ABI prefix (Section 3 §5): architectural commitments that are cheap to make now and expensive to retrofit later.

Concrete consequences of not having observability from day one:

Concrete consequences of having observability from day one:

The cost of building this in from the start is small — a few weeks of milestone work spread across Phase 1's six months. The cost of retrofitting it later is much larger and tends to be lossy (some events happened too long ago to instrument retroactively).

3. The three pillars

3.1 Tracing

What: span-based timeline of operations. Each span has a name, a duration, a parent (forming a tree), and a set of attributes (key-value pairs).

Granularity:

Output: structured (JSON-lines or OpenTelemetry-compatible) when configured; human-readable text to stderr by default.

3.2 Logging

What: append-only records of events. Distinct from tracing in that logs don't have duration semantics — they're points in time.

Levels: trace, debug, info, warn, error. Configurable per-module; runtime-tunable via environment variables.

Discipline:

Format: structured key-value pairs. Not just text strings. Tools that consume logs (a future debugging dashboard, ad-hoc grep-and-jq pipelines, the eventual OTel integration) consume the structure.

3.3 Diagnostics

What: information designed for the user, not for machines. Compile-time error messages with locations and suggestions; runtime errors with context; performance reports; memory reports.

Discipline: every diagnostic answers three questions — what happened, where did it happen, what should the user do about it. The third is the most often skipped and the most valuable.

Section 2 §10 already committed to this for compile-time errors. This section extends it to runtime errors and to performance/memory diagnostics.

4. The compiler side (additions to Section 2)

Section 2 of Phase 1 committed to OCaml + Dune + Z3 + MLIR. Here are the explicit observability additions.

4.1 New library dependency

compiler/lib/
└── observ/
    ├── dune
    ├── trace.ml             — span management
    ├── logger.ml             — structured logging
    └── diagnostics.ml        — compile-time diagnostic infrastructure

The observ library wraps Logs (the standard OCaml logging library) for logging, and provides a Trace module for span management. Logs is a Phase 1 dependency added explicitly.

4.2 Trace integration

Every compilation phase wraps its work in a span:

let elaborate ast =
  Trace.span "elaborate" (fun () ->
    Logger.info "starting elaboration; %d top-level decls" (List.length ast);
    let result = Elab.process ast in
    Logger.info "elaboration complete; %d obligations generated" 
      (List.length result.obligations);
    result
  )

Sub-spans nest inside; an SMT discharge for a single obligation produces a span like elaborate.smt_discharge with attributes for the obligation, the result, and the time spent.

4.3 CLI flags

The compiler's CLI (per Section 2 §9) gains observability options:

compiler [options] -o output.so input.sexp

  -v, -vv, -vvv               increase log verbosity (info, debug, trace)
  --quiet                     errors only
  --trace-output=PATH         emit JSON-lines spans to PATH
  --trace-format=text|json|otlp   default text; json for tooling; otlp future
  --module-id=ID              override the auto-generated module ID
                              (used for cross-system correlation; see §6)

4.4 Error diagnostic improvements

Section 2 §10 committed to source locations and SMT counterexamples. This section adds three things:

  1. Trace context in errors. Every error captures the trace span it occurred in. When an error message is emitted, the surrounding trace context is shown:

    error: refinement obligation refuted
  --> example.sexp:5:7
...
  = trace context: elaborate > typecheck_function "matmul" > elaborate_call

  2. Warnings become structured. Phase 0 §3 §11 mentioned warnings would emerge later; this section commits the format. A warning is a Diagnostic.t with severity = Warning, with the same fields as errors.

  3. A --diagnostic-format flag (default: human; alternatives: gnu for IDE integration, json for tooling). Errors and warnings format consistently across modes.

4.5 What Section 2 needs to add

Practically, Section 2's existing commitments need these additions when Section 2 is updated (or when its addenda are written):

The compiler size budget (Section 2 §12.5) was 15K lines. Adding the observability infrastructure is maybe 500–800 LoC. Within budget.

5. The runtime side (additions to Section 3)

Section 3's runtime got a passing mention of LoggingMemoryResource. This section makes observability comprehensive.

5.1 New crate dependencies

[dependencies]
tracing = "0.1"                     # the dominant Rust tracing ecosystem
tracing-subscriber = "0.3"          # output formatting + filtering
tracing-appender = "0.2"            # rolling files, async writes
nvtx = "1"                          # NVIDIA NVTX integration (or nvtx-rs equivalent)
metrics = "0.22"                    # counters and gauges

tracing is the canonical Rust framework for structured, async-aware tracing. nvtx provides bindings to NVIDIA's profiling API. metrics covers counter / gauge / histogram types for the regression infrastructure.

5.2 FFI instrumentation

Every public extern "C" function gets #[tracing::instrument]:

#[no_mangle]
#[tracing::instrument(skip(out), fields(m, n, k, batch))]
pub extern "C" fn runtime_gpu_matmul(
    out: *mut Tensor,
    a: *const Tensor,
    b: *const Tensor,
    batch: i64,
    m: i64,
    k: i64,
    n: i64,
    dtype_code: i32,
) -> FfiErrorCode {
    let _enter = nvtx::range_push!("matmul {}x{}x{}", m, n, k);
    
    // ... actual implementation ...
    
    nvtx::range_pop!();
    code
}

The tracing::instrument macro creates a span automatically; the skip annotation excludes opaque pointer arguments from being recorded; fields(...) adds the relevant integer arguments. The nvtx::range_push/pop calls provide NVIDIA Nsight Systems / Nsight Compute visibility (see §7).

5.3 Memory allocation tracing

The LoggingMemoryResource from Section 3 §4.2 becomes a TracingMemoryResource:

pub struct TracingMemoryResource<Inner: MemoryResource> {
    inner: Inner,
}

impl<Inner: MemoryResource> MemoryResource for TracingMemoryResource<Inner> {
    fn allocate(&self, size: usize, stream: &Stream) 
        -> Result<DevicePtr, AllocError> 
    {
        let span = tracing::trace_span!("alloc", size, stream = ?stream);
        let _guard = span.enter();
        
        let ptr = self.inner.allocate(size, stream)?;
        
        metrics::counter!("runtime.alloc.bytes").increment(size as u64);
        metrics::counter!("runtime.alloc.count").increment(1);
        
        tracing::trace!(?ptr, "allocated");
        Ok(ptr)
    }
    // ... similar for deallocate ...
}

This wraps any underlying resource. In typical configuration:

let base = CudaAsyncMemoryResource::new(device);
let pooled = PoolMemoryResource::new(base, /* config */);
let traced = TracingMemoryResource::new(pooled);
runtime::set_default_resource(traced);

Three layers: trace wraps pool wraps base. Each adds behavior; the base is the actual driver.

5.4 Stream operation tracing

Stream synchronizations are spans of their own. Cross-stream waits (one stream waiting for an event on another) are recorded with parent-child context, so the trace shows which operation triggered the wait.

5.5 Kernel launch instrumentation

In addition to NVTX (§7), every kernel launch records:

This is the tracing layer that domain libraries built on the runtime will consume — e.g., a profiler showing "you spent 60% of your time in attention_softmax_f16."

5.6 What Section 3 needs to add

The runtime size budget (Section 3 §10) was 8K lines. Observability adds maybe 300–500 LoC. Within budget.

6. Cross-system correlation

A compilation produces a shared object (per Section 2). The runtime executes it (per Section 3). Without correlation, traces from compilation and traces from execution are disjoint timelines that the user has to manually reconcile.

The fix: every compilation produces a module ID, embedded in the artifact, propagated through every runtime span.

6.1 The module ID

A 128-bit UUID generated at compilation time (or supplied via --module-id). The compiler:

The runtime:

A user's trace can be filtered by module ID, joining compilation and execution traces seamlessly:

$ jq 'select(.attributes.module_id == "abc123...")' all-traces.jsonl

Shows only the trace events related to one specific compiled program.

6.2 Multi-module programs

Future programs may link multiple compiled .so files (e.g., a user program plus a domain library plus the standard library). Each has its own module ID. Spans from the runtime tag themselves with the module ID of the function being invoked. Cross-module calls naturally produce spans with different module IDs at the call boundary.

This is a future concern (Phase 5+), but the design is forward-compatible: the module ID is per-call, not per-process.

7. NVTX: NVIDIA-specific instrumentation

The single most valuable tool for debugging GPU work. NVIDIA's NVTX library lets the runtime annotate ranges that NVIDIA Nsight Systems and Nsight Compute display in their profiler UIs.

7.1 What this enables

Without NVTX, profiling a CUDA program shows kernel launches as opaque cuLaunchKernel calls. With NVTX:

For someone debugging a slow kernel, this is the difference between "your program spent 40% of its time in unidentified GPU work" and "your program's softmax kernel is taking 2.3ms when it should take 0.4ms."

7.2 Implementation

The runtime wraps every kernel launch and every memory operation with NVTX ranges:

#[inline]
pub fn launch_kernel<F: FnOnce()>(name: &str, f: F) {
    let _range = nvtx::Range::new(name);  // RAII; pops at scope exit
    f()
}

Used everywhere kernel launches happen:

launch_kernel(&format!("matmul {}x{}x{}", m, n, k), || {
    cublas::sgemm_async(/* ... */);
});

The cost is a few hundred nanoseconds per range; negligible compared to kernel time.

7.3 Acceptance criterion

Running a Phase 1 demo program (e.g., the transformer block from Section 1's exit criterion) under Nsight Systems should produce a timeline where every kernel is labeled with a meaningful name. No unknown ranges. No anonymous cuLaunchKernel calls.

8. Output format and consumption

8.1 Default: human-readable text to stderr

[2026-05-08T20:45:12.183Z INFO  runtime] starting matmul 128x256x64 on cuda:0
[2026-05-08T20:45:12.184Z DEBUG runtime] allocated 32768 bytes for output
[2026-05-08T20:45:12.187Z INFO  runtime] matmul completed in 2.8ms

Format: timestamp, level, module, message. Configurable via RUST_LOG (Rust runtime) and OCAMLRUNPARAM-style env vars (OCaml compiler). Standard practice.

8.2 Structured: JSON-lines

{"ts":"2026-05-08T20:45:12.183Z","level":"INFO","span":"matmul","module_id":"abc123","attributes":{"m":128,"n":256,"k":64,"device":"cuda:0"}}
{"ts":"2026-05-08T20:45:12.184Z","level":"DEBUG","span":"alloc","module_id":"abc123","attributes":{"bytes":32768}}
{"ts":"2026-05-08T20:45:12.187Z","level":"INFO","span":"matmul","module_id":"abc123","duration_ms":2.8,"event":"complete"}

JSON-lines is greppable, jq-able, and trivially convertible to other formats. Used when the consumer is a tool rather than a human.

8.3 Future: OpenTelemetry export

The Arrow / observability forward track flagged this connection. JSON-lines is structurally compatible with OTel; an explicit OTLP exporter is a Phase 5+ deliverable. The Phase 1 commitment is not breaking compatibility — span attribute names follow OTel conventions where applicable (http.*, db.*, etc. are reserved; ours use runtime.*, compiler.*).

8.4 Future: Nsight Systems direct integration

Beyond NVTX, Nsight Systems can ingest custom data formats. A future hook to pipe our structured traces directly into Nsight (rather than just NVTX ranges) would unify CPU and GPU views in one tool. Phase 5+ work; Phase 1 just doesn't preclude it.

9. Performance: zero-cost when disabled

The hard discipline. Observability that costs more than 5% in the default-enabled case is observability that gets disabled in production, which means the production code paths run untraced and undebuggable.

9.1 Compile-time elimination

Both tracing (Rust) and Logs (OCaml) support compile-time level filtering. Logs below the configured threshold compile to nothing — not even a function call. The macros expand to if false { ... } else { /* nothing */ }, which the compiler eliminates.

For our build:

9.2 Runtime filtering

When a level is compiled in but runtime-disabled (the user set RUST_LOG=info and a debug! call fires), the cost is one atomic load + one comparison + one branch — a few nanoseconds.

Tracing spans have a similar cost when no subscriber is attached: a few nanoseconds for the level check, then the span body executes without recording.

9.3 Hot paths: no tracing

Per-element kernel loops do not trace. A kernel that processes 10M elements doesn't add a span per element. It adds a single span at the kernel launch level, with attributes describing the work.

Same for memory copy operations within a kernel (these are hardware-level concerns), stream-internal scheduling (hardware), and any operation invoked from inside another instrumented operation (the parent span captures it).

9.4 Acceptance criterion

The trace overhead in default-enabled mode is < 5% on the transformer-block benchmark (Section 1's exit criterion). The trace overhead in fully-disabled mode is < 1%. Both verified by Section 7's regression infrastructure.

10. Implementation milestones (within Phase 1's three milestones)

The observability work spreads across Phase 1's existing milestones rather than being a separate fourth milestone:

10.1 Milestone 1 (months 1–2): bootstrap

10.2 Milestone 2 (months 3–4): GPU integration

10.3 Milestone 3 (months 5–6): polish and validation

11. Acceptance criteria specific to observability

Criterion Target
Every compiler phase emits a span All five: parse, elaborate, typecheck, lower, emit
Every public FFI function instruments All ~17 entry points from Section 3 §6.1
Cross-system correlation works Module ID propagates from --module-id through to runtime spans
NVTX integration Nsight Systems shows our kernels with names; no unknown ranges
Default-mode trace overhead < 5% on the transformer-block benchmark
Disabled-mode trace overhead < 1% on the transformer-block benchmark
Errors include trace context Every error message includes the spanning context where it occurred
Documented debugging guide At least one walked-through example bug with the trace artifacts
JSON-lines format follows OTel conventions Span attribute names compatible with OTel semantic conventions

The goal is operationalized: when Phase 1 ends, debugging a problem in the language is no harder than debugging a comparable problem in PyTorch — and in some respects easier, because we have type-system context that PyTorch doesn't.

12. Open issues introduced by this section

  1. OpenTelemetry export timing. Phase 1 emits OTel-compatible JSON-lines; an actual OTLP exporter that sends spans to an OTel collector is Phase 5+ work. Worth flagging that the gap exists; the Arrow/observability forward track may pull this earlier if the typed-dataframes work needs it.

  2. Trace storage and retention. The default is ephemeral (stderr or rotating file). For long-running workloads, traces accumulate fast. A Phase 5+ concern: integration with proper trace storage (Tempo, Jaeger, ClickHouse) per the observability stack.

  3. Privacy of trace contents. Span attributes can contain shape and dtype information, which is fine. They should not contain tensor values, model parameters, or user inputs. Discipline; needs a code-review checklist item.

  4. Cross-process correlation. When multiple compiled programs run in the same process (or across processes), traces should correlate. Per-call module IDs cover the same-process case. Cross-process correlation needs distributed-tracing primitives (W3C trace-context or similar). Phase 5+.

  5. Compiler trace replay. Captured compiler traces could replay a compilation deterministically for bug reproduction. Useful but not Phase 1; flagged as a debugging-tools direction.

  6. The Logs vs. tracing impedance mismatch. OCaml uses Logs; Rust uses tracing. They're philosophically aligned but have different APIs and output formats. The cross-system correlation papers over this for the user; for contributors, it's a small cognitive cost. Documented in the contribution guide.

13. Updates needed in earlier sections

This section retrofits a gap. To keep the spec internally consistent, three earlier documents need addenda when revisited:

Section 1 (Scope)

The deliverable list (§2 of Section 1) needs three additions:

The compiler size budget (15K LoC) and runtime size budget (8K LoC) accommodate the additions per the analyses in §4.5 and §5.6 of this section.

Section 2 (Compiler)

Section 3 (Runtime)

These additions don't invalidate the earlier sections' commitments; they add a layer of instrumentation discipline.

14. Section 5 preview

Section 5 (formerly Section 4) covers the operation set extensions identified during Phase 0:

Each gets a typing rule, CPU lowering, GPU lowering, and tests. These additions transform Phase 0's "can express forward passes with effort" into "can express forward passes idiomatically."

With Section 4 (this section, observability) and Section 5 (operations) in place, Phase 1's implementation work is fully specified. Sections 6–8 cover verification, testing/ABI, and exit.

End of Phase 1, Section 4.