From 65abfa2ed9943b21917fd20d537122c2c0704fa2 Mon Sep 17 00:00:00 2001 From: Jake Date: Wed, 13 May 2026 18:18:12 +0100 Subject: [PATCH] =?UTF-8?q?agent:=20code-atomiser-fix=20=E2=80=94=20span?= =?UTF-8?q?=20propagation=20across=20live=20+=20model-load=20spawns=20(Obs?= =?UTF-8?q?-3)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- crates/llm/src/lib.rs | 6 ++++++ src-tauri/src/commands/live.rs | 26 ++++++++++++++++++++++++++ src-tauri/src/commands/models.rs | 7 +++++++ 3 files changed, 39 insertions(+) diff --git a/crates/llm/src/lib.rs b/crates/llm/src/lib.rs index 26016f4..8ee6051 100644 --- a/crates/llm/src/lib.rs +++ b/crates/llm/src/lib.rs @@ -120,6 +120,12 @@ impl LlmEngine { 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( &self, model_id: LlmModelId, diff --git a/src-tauri/src/commands/live.rs b/src-tauri/src/commands/live.rs index 4f4d21a..69f4c77 100644 --- a/src-tauri/src/commands/live.rs +++ b/src-tauri/src/commands/live.rs @@ -884,6 +884,15 @@ fn pick_engine(state: &AppState, engine: &str) -> Result, 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( session_id: u64, engine: Arc, @@ -1090,7 +1099,24 @@ fn maybe_dispatch_chunk( // now `abort_flag` plumbed through whisper-rs's abort callback, not // a JoinHandle. On any early exit from the loop the per-task flag // 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 || { + 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 started = Instant::now(); let result = engine diff --git a/src-tauri/src/commands/models.rs b/src-tauri/src/commands/models.rs index df77c1f..f13ef8f 100644 --- a/src-tauri/src/commands/models.rs +++ b/src-tauri/src/commands/models.rs @@ -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( state: &AppState, engine_name: &str,