feat(perf): opt-in performance diagnostics with turn timelines and an environment probe - #408
Open
pjdoland wants to merge 8 commits into
Open
feat(perf): opt-in performance diagnostics with turn timelines and an environment probe#408pjdoland wants to merge 8 commits into
pjdoland wants to merge 8 commits into
Conversation
Enterprise deployments (internal LLM gateways, EFS-mounted homes, intercepting proxies) see much worse latency than desktop installs with no way to tell where a turn's time goes. This adds the foundation: a turn recorder and an on-demand environment probe, both inert until enabled. The recorder keys turns by message id in a locked registry rather than a ContextVar because a turn crosses three threads that share no contextvars context (tornado loop, per-request asyncio.run thread, SDK client thread). Spans carry a fixed name vocabulary and a schema-checked attribute allowlist enforced in the recorder itself, so the privacy guarantee cannot erode when a later change passes a new kwarg. In the default redacted mode, file basenames and model/tool/server names are hashed, including external tool names embedded in span names. Disabled cost is one boolean test per call. Finished turns land in a ring buffer and, optionally, a JSONL sink on a dedicated writer thread that batches, tolerates write failures, self-disables rather than blocking on the slow filesystem it may be diagnosing, and creates its directory and files 0700/0600. The probe measures the usual suspects directly: per-directory stat, read, and write+fsync latency with cold-vs-warm first iteration and a sustained-throughput pass, filesystem type and mount options, node vs CLI cold-start cost, contention signals, and an opt-in network leg that is proxy-aware, sends one request to the configured base URL only, captures the presented TLS chain (interception shows up as the issuer), and reports unauthenticated TTFB with an honest caption. Checks run on abandonable worker threads because a hung NFS stat is uninterruptible; the pool is recreated per run so abandoned workers cannot poison later probes. Output is scrubbed of home paths (including the resolved real home), usernames, and hostname fields. Config follows the repo's policy conventions: a perf_diagnostics section, NBI_PERF_DIAGNOSTICS value lock, a policy triad with force-on for fleet-wide baselining (which pins redacted mode), and a separate NBI_PERF_PROBE_NETWORK policy so admins can keep the probe while disabling its network leg.
Wires the recorder through the turn lifecycle in all three modes. The turn opens at websocket ingress (ChatRequest branch only), covers the real per-turn prep work in a context_prep span, and is force-closed in the request thread's finally so cancellation and errors cannot leak it; a guard around the pre-thread stretch closes the turn as errored if a malformed request raises before the worker starts, since one leaked turn would otherwise disable the single-open-turn tool guard for the process lifetime. Cancelled turns are recorded as cancelled, not as fast successes that poison the percentiles. first_token is an event recorded on the first content-bearing chunk; the locally generated "Thinking" spinner previously triggered it and made time-to-first-token read ~0 on every turn, exactly in the slow deployments the feature targets, while pulling the connect phase inside the stream span. Stall events start from the first SDK message rather than the loop entry (the gap before the first message is TTFT, not a stall) and are tagged with the preceding message kind so a gap after tool use is distinguishable from a gateway stall. Token counts sum cache reads and writes the same way the usage footer does, so the two surfaces agree on cached turns. Tool timing uses the three real hook points: the Copilot/base dispatch loop, the Claude in-process tool wrappers, and the ACP session-update events (those tools run in a separate process). MCP calls annotate the enclosing dispatch span with the server name instead of nesting a duplicate, which had double-counted every MCP call in the aggregates. The report endpoint serves the ring snapshot plus a probe_target reduced to scheme and host (never netloc, which preserves embedded credentials); the probe endpoint accepts only the network boolean and enforces the NBI_PERF_PROBE_NETWORK policy server-side. Both are authenticated and 404 while diagnostics is disabled. Each closed turn also logs one INFO summary line with the per-phase breakdown so headless installs get the signal from the server log alone.
A new tab in NBI Settings hosting the diagnostics controls (enabled, log to file, attribute detail), a last-N-turns table, and the probe. Controls respect both the settingLocks value-locks and the perf_diagnostics policy, so force-on and force-off render as locked rather than as a toggle that silently reverts. The first-token column reads the event mark the backend actually records instead of a span that never exists. The network check is behind an explicit inline confirmation that shows the exact URL the probe will contact, taken from the report's probe_target. Report and probe output can be copied as JSON for support tickets. The capabilities payload now carries the perf_diagnostics section; without it the panel rendered defaults and a save clobbered stored settings.
README gets the user-facing section: what a turn records, what is never recorded, the probe, the env vars. The admin guide covers the operator knobs: the policy triad including fleet-wide force-on, redirecting the JSONL log off network homes with NBI_PERF_LOG_DIR, how to read total-vs-api and the EFS signatures, the probe's SOC-relevant behavior, and the new endpoints in the HTTP API table.
…anel Follow-ups from the post-implementation review pass on the performance diagnostics feature. Recorder: - run the whole compare-dir/teardown/reassign/recreate sequence in configure() as one critical section under _sink_lock, so a concurrent TurnHandle.close() cannot recreate a sink pinned to the old log dir - recreate a self-disabled sink on the next configure(), so a settings save retries the sink after an operator fixes the filesystem - add set_current_span_attr() for callees that only annotate one attr Instrumentation: - exclude Progress chunks from every stream perf signal (span open, first_token, chunk and byte counters), not just the span open - stop running asdict + json.dumps on every stream chunk purely to count bytes; estimate from the content field and write the final counts once in finish() - attribute in-process tool spans via get_current_response() first, so concurrent turns do not fall back to the process-wide single-open-turn guess - collapse input_tokens to None only when no usage token key is present, so a payload that legitimately reports zero still records 0 - apply the perf_diagnostics value lock on the config POST write path, so a scripted POST cannot persist enabled:true under NBI_PERF_DIAGNOSTICS - log perf turn close failures at warning, not debug Probe: - submit every independent check before blocking on any result, so wall time is roughly the slowest check rather than the sum of the timeouts - give the claude_home session scan an outer budget above its own internal bound, so a scan that runs to that bound is not abandoned with its samples discarded - return partial results plus tls_error on a sub-timeout TLS handshake failure instead of discarding the dns/tcp timings - close the raw socket when the handshake never produced an SSLSocket - report process RSS as max_rss_kb, which is what ru_maxrss actually is - skip, rather than error, when the resource module is unavailable - fall back to a top-level base_url for openai-compatible providers Panel: - read the perf_diagnostics lock from the feature policy entry instead of comparing a policy object against policy-name strings, which never matched; register perf_diagnostics in the api.ts policy name list - gate the network checkbox on perf_probe_network_allowed - exclude probe_target from the copied report JSON - correct IPerfTurn.t_wall to a number and add the skipped check status Docs: describe the probe's network leg as the several connections it actually makes, and note that only the HTTP legs carry the probe User-Agent.
Second review pass on the performance diagnostics feature. - The stream byte estimator read a flat "content" key, which no chunk actually has: raw LLM chunks are OpenAI-shaped, so the stream span's "bytes" attribute and the egress event's byte count both read exactly 0 for the whole of Copilot chat mode. Read through choices[0].delta.content, and make the test fixtures use the shape the providers really emit instead of a synthetic flat dict. - The probe submitted every check up front onto a shared pool, so the filesystem latency loop timed individual stat and fsync operations while the sustained-IO check was writing a 4 MB file into the same directory. That makes the probe measure its own contention, and it is worst on the network-mounted homes the probe exists to diagnose. Run the filesystem, subprocess, and contention groups strictly one at a time, and overlap only the network check, which touches neither disk nor CPU and is the long pole anyway. - TurnHandle.close reads _log_to_file outside _sink_lock, so a configure() that turns file logging off could land between that read and the sink lookup, and the close would then build a fresh sink and leave a live writer thread behind. Re-check _log_to_file inside the locked factory. - The in-process tool span comment claimed the current-response lookup disambiguates concurrent sessions. It does not: _current_response is a module global, not a contextvar. What it does provide is the query actually running on the client thread, which is what makes it better than giving up whenever a second turn merely sits open. Say that.
Collaborator
Author
|
Review pass on my own branch, posted as a comment since GitHub does not let an author formally review their own PR. Two remediation commits are pushed ( Real defects found and fixed
Documentation corrections. The README and admin guide described the probe's network leg as "exactly one request". It is actually several connections to the single configured host: a raw connection to time DNS/TCP/TLS, a second to verify the certificate against the default trust store, and an HTTP HEAD with a GET retry on 405. Only the HTTP legs carry the Known and deliberate. The in-process tool span lookup uses |
The recorder and probe collected the right data, but the panel showed twelve numeric columns and a raw JSON dump, and the knowledge needed to interpret either lived in one paragraph of the admin guide. This adds the part between "the data exists" and "the user reaches a conclusion". Turns table: - a Verdict column naming the phase that dominated the turn (model or gateway, tool execution, agent cold start, context preparation, mid-stream stalls), derived from the columns already present rather than from any new recorded field - Time and Stalls columns, both from data that was already transmitted and dropped on the floor - a tooltip on every column, including what Active excludes and why Active against API ms is the comparison that matters - expandable rows showing that turn's spans as proportional bars with their attributes, then its events with offsets, and a warning when the per-turn caps truncated the record - an empty state that says to run a turn, instead of an empty table Probe: - checks are grouped and banded rather than dumped as JSON, with check ids translated into what they measure and a plain-language note on anything that trips a threshold (network filesystem, EFS burst-credit exhaustion, cgroup throttling, TLS interception, clock skew) - skipped and timed-out checks read differently from healthy ones - the raw JSON is still there, behind a toggle, since that is what gets pasted into a ticket - sub-millisecond latencies keep two decimals instead of rounding to "0 ms", which read as "not measured" rather than "fast" Two probe bugs the new rendering made visible: - macOS firmlinks: /Users is presented at /Users but lives on the Data volume, and Path.resolve does not follow the firmlink, so the mount match landed on "/" and reported every home directory as sealed read-only apfs. Re-match through /System/Volumes/Data when that mount exists. - the panel labelled the config-directory checks "config" while the probe emits "nbi_user_dir", so that group rendered with a raw id. Model name: - the Claude connect span now carries the model, which is the only place the turn header can learn it. Before this the Model column was empty on every Claude turn. - TurnHandle captures it through the same redaction the span attr gets. It was being stored in the clear while the span copy was hashed, which disagreed with itself and put the model name into reports and the JSONL sink that document it as hashed. Copy: a one-paragraph description at the top of each section, and an explanation of what redacted and full actually trade off, at the point where that choice is made. Docs: new docs/performance-diagnostics.md with the column and verdict reference, the span and event vocabulary, the probe thresholds, worked diagnoses for a slow gateway, a slow home directory, and an intercepting proxy, the JSONL schema, and what to attach to a support ticket. The README section is restructured around that and the admin guide keeps only the operator-owned knobs, pointing at the new document for the rest.
…panel Findings from a full-PR review pass, plus one the live check turned up. Probe, TLS. The network check could not detect interception, which is its headline capability. The timing leg used a verifying context, so an untrusted certificate failed that handshake and the function returned early with only a tls_error and no certificate at all; a trusted one made the second leg's identical verifying handshake succeed too. There was no input for which verified_against_default_bundle came back false, so the panel branch and the documented diagnosis were both dead code. The capture leg now deliberately does not verify (it sends nothing, and the certificate you need to see is exactly the one a verifying handshake refuses), issuer and subject are parsed from the DER because getpeercert() returns an empty dict for an unvalidated peer, and a separate verifying leg produces the verdict. Both legs, and the HTTP request, now go through the configured proxy: the verification leg used to connect directly, which in a proxy-only egress environment is refused, so the field silently stayed null in precisely the deployments that intercept. A live check against a self-signed server then showed the HTTP leg raising through and discarding every one of those findings, so its failure is reported as a field instead. Covered by a test that stands up a TLS server with an untrusted certificate. Probe, other: - the ~/.claude presence stat ran inline on the caller's thread with no timeout, so a hung mount (the condition this exists to diagnose) hung run_probe forever and burned a Jupyter executor thread - mount options were copied verbatim out of /proc/mounts, where CIFS/SMB carries addr= and username=, into a document that promises no hostnames and no credentials. Bare flags are kept, key=value only on a safe list, and the withheld count is shown rather than silently dropped - the subprocess and mount checks had an outer budget equal to their own inner timeout, so the outer timer always won and the documented slow-but-completing band could never be produced Recorder: - get_turn is gated on _enabled, so a turn in flight when diagnostics were switched off never closed and leaked in the registry for the process lifetime, which also poisons the single-open-turn lookup and silently disables tool spans from then on. Added take_turn for the close path; a turn closed after disabling is released but not recorded - the JSONL writer caught only OSError, so an unserializable document killed the thread while enqueue kept filling an unbounded queue with no consumer. Documents are now serialized individually, any failure counts toward the documented self-disable, and the thread cannot die silently - span_id and parent_id were computed on every span, at the cost of a lock acquisition, and then discarded. They are emitted now, which is what lets a reader tell a phase from the wrapper containing it - _detect_fs_type re-implemented mount resolution with a bare-prefix match and no firmlink handling, so it named the wrong filesystem for the one thing it exists to reveal. It delegates to perf_probe - SPAN_NAMES and the attr allowlist advertised names and fields no producer sets, including a gateway_host that would have put a hostname in a document promising none Instrumentation: - the stream byte counter counted characters for an attribute named bytes, undercounting CJK and emoji three to four times - stream() called get_turn per chunk, taking the global registry lock on the hottest path in the product. The handle is resolved once - the tool-dispatch loop never marked tools builtin, so every NBI tool was recorded with a hashed name in the default mode, the opposite of what the docs say. MCPTool revokes the flag for itself - the turns report embedded the gateway host, contradicting the README, the guide, and the panel's own copy. It moved to capabilities, which already carries the base URL for the settings UI Panel: - fmtMs only guarded undefined, so a null duration_api_ms rendered as "0 ms" on every non-Claude turn, in the column the docs call the most useful comparison - nested spans are indented - the network checkbox handler did not check the policy it renders - the directory-level claude_home row no longer renders a dangling colon - the Performance tab is hidden under force-off, where both endpoints 404
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Enterprise deployments running NBI in constrained environments (an internal Claude endpoint,
~/.claudeand the Jupyter home on mounted EFS, TLS-intercepting proxies) see much worse latency than desktop installs, with no way to tell whether the time goes to the model gateway, subprocess startup, filesystem I/O, tool execution, or NBI itself. This adds an opt-in performance diagnostics mode that answers "where did this turn's time go," plus an on-demand environment probe that measures the usual suspects directly. Off by default; when off, the cost is one boolean check per instrumentation site.Solution
Three pieces, all gated behind a
perf_diagnosticsconfig section following the repo's policy conventions (value lockNBI_PERF_DIAGNOSTICS, policy triad withforce-onfor fleet-wide baselining, and a separateNBI_PERF_PROBE_NETWORKpolicy for just the probe's network leg):Turn timeline. Every chat turn records a span tree (context prep, connect/spawn with a cold flag, first token, stream with stall events tagged by what preceded them, per-tool spans, time waiting on the user) plus token counts and the SDK-reported
duration_api_ms. Wall total vsapi_msis the single best gateway-vs-local discriminator and comes free from theResultMessage. Turns are keyed by message id in a locked registry because a turn crosses three threads that share no contextvars context; close is guaranteed in the request thread'sfinally, and cancelled turns are recorded as cancelled rather than as fast successes. The report is served atGET /notebook-intelligence/perf/report, a per-turn INFO summary line goes to the server log (headless installs get the signal with zero UI), and turns can optionally append to a JSONL sink that batches, tolerates failures, self-disables rather than blocking on a slow filesystem, and writes 0700/0600.Environment probe.
POST /notebook-intelligence/perf/proberuns filesystem latency/throughput (with fs type and mount options, cold-vs-warm first iteration), node-vs-CLI cold start, and contention checks on abandonable worker threads (a hung NFS stat is uninterruptible; the pool is recreated per run). The network leg is opt-in per run behind a confirmation showing the exact URL, is proxy-aware, sends one request to the configured base URL only, and captures the presented TLS chain, which makes interception visible as the issuer CN. Output is scrubbed (home paths incl. resolved real home, usernames, no hostname fields).Surfacing. A Performance tab in NBI Settings with the controls (policy- and lock-aware), a recent-turns table, the probe, and copy-as-JSON for support tickets. The table carries a Verdict column naming the phase that dominated each turn (model or gateway, tool execution, agent cold start, context preparation, mid-stream stalls), derived from the recorded columns rather than from any new field, and rows expand into that turn's spans as proportional bars followed by its events. Probe checks are grouped and banded, with a plain-language note on anything that trips a threshold (network filesystem, EFS burst-credit exhaustion, cgroup throttling, TLS interception, clock skew); the raw JSON stays available behind a toggle. Every column carries a tooltip, and the docs the interpretation came from now live in
docs/performance-diagnostics.mdrather than in one paragraph of the admin guide.Privacy is enforced structurally: the recorder schema-checks every attribute against a fixed allowlist, and the default
redactedmode hashes file basenames and model/tool/server names, including tool names embedded in span names. Never recorded: prompt/response text, absolute paths, env values, exception messages, hostnames.Testing
test_perf.py48,test_perf_instrumentation.py32,test_perf_probe.py23) covering the disabled fast path, concurrent turns, span caps, redaction, ring/sink behavior, the finally-close and cancelled-status paths, REST gating, probe timeouts and scrubbing, macOS firmlink mount resolution, mount-option redaction, disabling mid-turn, sink robustness against an unserializable document, and TLS interception detected against a self-signed serverReview provenance
The plan was reviewed pre-implementation by three expert personas (observability architect, JupyterLab extension architect, enterprise bank platform engineer); their MUST items are all reflected above. The implementation then went through two xhigh-effort multi-angle reviews plus a combined concurrency/security pass. The second review is why the network check can detect TLS interception at all: the timing leg used a verifying context, so an untrusted certificate failed that handshake and no certificate was ever captured, and
verified_against_default_bundle: falsewas unreachable for any input. Alongside it: a turn-registry leak when diagnostics are disabled mid-turn, a JSONL writer thread that a single unserializable document could kill while its queue kept growing, mount options carrying CIFS addresses and credentials into a document promising neither, the gateway host embedded in the exportable report, a byte counter counting characters, and a per-chunk global lock on the streaming path. Earlier findings (a probe request-body contract break, a Windows-breakingimport resource, a settings-clobbering capabilities gap, first-token misattribution, MCP double-counting, redaction gaps, JSONL permissions, TLS-verification and probe-budget bugs, and several races) were all fixed and are covered by the tests above.Risks / follow-ups
[otel]extra will honor standardOTEL_EXPORTER_OTLP_*env vars; no config field ships for it now