agent: code-atomiser-fix — span propagation across live + model-load spawns (Obs-3)
Some checks failed
check / cargo check (macos-latest) (push) Has been cancelled
check / cargo check (ubuntu-22.04) (push) Has been cancelled
check / cargo check (windows-latest) (push) Has been cancelled
check / svelte build + lint (push) Has been cancelled

Before this commit `grep -rIn '#\[instrument\|.instrument(\|in_current_span()'`
returned zero matches across the entire workspace. Every tokio::spawn
and thread::spawn lost its parent span, so structured fields recorded
at the call site (session_id, chunk_id, model_id) did not propagate to
log lines emitted inside the spawn. During concurrent-session incidents
the operator could not correlate a runaway log line back to the request
that started it.

Targeted four highest-value join points:

  * src-tauri/src/commands/live.rs::run_live_session
    #[tracing::instrument(skip_all, fields(session_id, engine, language))]
    Attaches the span to the spawn_blocking worker so every per-chunk
    warning carries the session id that owns it.

  * src-tauri/src/commands/live.rs::maybe_dispatch_chunk
    Manual span attach pattern (#[instrument] can't decorate a closure):
    capture the parent span before thread::spawn, .enter() it on the new
    OS thread, then open an "inference" child span with chunk_id +
    duration_secs. Without this, whisper backend warnings appear
    unparented and a runaway chunk can't be traced back to its session.

  * src-tauri/src/commands/models.rs::ensure_model_loaded
    #[instrument(skip_all, fields(model_id, engine, concurrent))]
    Multi-second load + sequential-GPU guard logs now carry the model
    in flight as a structured field.

  * crates/llm/src/lib.rs::load_model
    #[instrument(skip_all, fields(model_id, use_gpu))]
    Same rationale for LLM loads. Tags llama-backend init lines and
    GPU sequential-guard events with the model identifier.

Storage/audio/hotkey/MCP crates left uninstrumented in this commit —
future sweep. The four sites above are the canonical concurrent-load
correlation points; everything else fans out from them.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
2026-05-13 18:18:12 +01:00
parent d1391b34ac
commit 65abfa2ed9
3 changed files with 39 additions and 0 deletions

View File

@@ -120,6 +120,12 @@ impl LlmEngine {
self.load_model(LlmModelId::default_tier(), model_path, true) self.load_model(LlmModelId::default_tier(), model_path, true)
} }
// instrument: the load is multi-second (`LlamaBackend::init` +
// mmap + GPU layer init). Tagging events with `model_id` and
// `use_gpu` lets the operator separate the GPU sequential-guard
// logs and llama-backend init lines from the LLM transcription
// pipeline by structured field rather than by adjacency.
#[tracing::instrument(skip_all, fields(model_id = %model_id.as_str(), use_gpu = use_gpu))]
pub fn load_model( pub fn load_model(
&self, &self,
model_id: LlmModelId, model_id: LlmModelId,

View File

@@ -884,6 +884,15 @@ fn pick_engine(state: &AppState, engine: &str) -> Result<Arc<LocalEngine>, Strin
} }
} }
// instrument: attaches a `run_live_session` span carrying `session_id`
// to every emit inside the `spawn_blocking` worker. Without this the
// worker's tracing events landed in the runtime's root span and the
// operator could not correlate per-chunk warnings back to the start
// call that owned them.
#[tracing::instrument(
skip_all,
fields(session_id = %session_id, engine = %config.engine, language = ?config.language)
)]
fn run_live_session( fn run_live_session(
session_id: u64, session_id: u64,
engine: Arc<LocalEngine>, engine: Arc<LocalEngine>,
@@ -1090,7 +1099,24 @@ fn maybe_dispatch_chunk(
// now `abort_flag` plumbed through whisper-rs's abort callback, not // now `abort_flag` plumbed through whisper-rs's abort callback, not
// a JoinHandle. On any early exit from the loop the per-task flag // a JoinHandle. On any early exit from the loop the per-task flag
// is set and whisper-rs returns cleanly on its next poll. // is set and whisper-rs returns cleanly on its next poll.
//
// instrument: capture the parent `run_live_session` span (so
// `session_id` propagates) and open an `inference` child span
// carrying `chunk_id` on the new OS thread. `#[instrument]` can't
// be applied to a closure, so we attach the span manually after
// crossing the thread boundary. Without this, every tracing event
// emitted by `LocalEngine::transcribe_sync_with_abort` lands in
// an unparented span and the operator cannot correlate a runaway
// chunk back to its session.
let parent_span = tracing::Span::current();
thread::spawn(move || { thread::spawn(move || {
let _parent = parent_span.enter();
let inference_span = tracing::info_span!(
"inference",
chunk_id = current_chunk_id,
duration_secs,
);
let _enter = inference_span.enter();
let audio = AudioSamples::mono_16khz(chunk_samples); let audio = AudioSamples::mono_16khz(chunk_samples);
let started = Instant::now(); let started = Instant::now();
let result = engine let result = engine

View File

@@ -115,6 +115,13 @@ pub fn default_model_id_for_engine(engine: &str) -> ModelId {
} }
} }
// instrument: a model load can take 5-15 s on cold launch + cold GPU
// init. Attaching `model_id` + `engine` to every event emitted inside
// the load chain (status polls, GPU sequential-guard logs, llama
// backend init lines) lets the operator correlate "the app froze for
// 12 seconds at startup" back to the exact model in flight without
// having to read the surrounding lines for a session/model identifier.
#[tracing::instrument(skip_all, fields(model_id = %model_id, engine = %engine_name, concurrent = ?concurrent))]
pub async fn ensure_model_loaded( pub async fn ensure_model_loaded(
state: &AppState, state: &AppState,
engine_name: &str, engine_name: &str,