[wan9chi]

Motivation

When a cached run is slower than expected, especially in CI with the remote cache, vp run's output doesn't say where a task's time went. It could be waiting for a concurrency slot, hashing inputs, the local lookup, the remote fetch, checking each fetched entry, downloading or extracting the archive, the process itself, fingerprinting and archiving after a run, or the upload.

With VP_LOG=vt=debug,vt_remote_cache=debug, each of these steps is now traced with its duration, and with sizes and counts where they matter. The traces run in the task's span, so a CI log can be turned into a per-task timeline. Per-input fingerprinting and validation are traced at trace level. Nothing changes unless VP_LOG is set. Token requests log their status and timing, never the request URL or a token.

We used these traces on a CI replay of a monorepo's history, about 600 jobs. They showed remote fetches queueing behind the backend's per-isolate read limit, entry checks running one after another on the scheduler thread (fixed by the next PR in this stack), and archive downloads on the critical path.

🤖 Generated with Claude Code

---

Note

Low Risk
Observability-only: tracing and timing logs gated on VP_LOG, with careful avoidance of logging credentials or tokens.

Overview
Adds opt-in tracing instrumentation (via VP_LOG) across task execution and cache paths so CI logs can show per-step durations and useful sizes/counts without changing normal behavior.

Local and remote cache: debug events for local/remote lookup outcomes, remote fetch resolution, per-entry validation, archive download/extract/restore, local record, upload prepare/finish/wait, and output archiving—with a small file_size helper for archive byte counts.

Execution path: timing for glob input hashing, spawn/fspy, child exit, DAG concurrency waits, and leaf item completion; fingerprint create/validate get debug summaries plus trace-level per-input events parented under the task span (Rayon-safe).

vt_remote_cache: tracing dependency, #[tracing::instrument] on fetch/download/store, response logging (status/content-length, not URLs), store prep metrics including blob size; GitHub OIDC logs status and timing only (no tokens/URLs).

Remote upload tasks run .in_current_span() so background uploads stay tied to the task timeline.

^{Reviewed by Cursor Bugbot for commit 42bda18. Bugbot is set up for automated code reviews on this repo. Configure here.}

[github-actions]

fspy benchmark

linux

dynamic/launch             change  +0.11%  [ -2.54% ..  +3.15%]  overhead   +54.14%
dynamic/access             change  -0.40%  [ -3.91% ..  +4.38%]  overhead   +21.95%
dynamic/access-relative    change  -0.30%  [ -2.41% ..  +3.13%]  overhead   +70.22%
dynamic/access-contended   change  +3.32%  [ -4.54% ..  +9.77%]  overhead    +7.50%
static/launch              change  +0.59%  [ -3.66% ..  +4.12%]  overhead  +201.22%
static/access              change  -0.30%  [ -1.36% ..  +0.71%]  overhead +1459.02%
static/access-relative     change  +0.67%  [ -0.42% ..  +1.51%]  overhead +1965.48%
static/access-contended    change  -0.50%  [ -1.46% ..  +0.80%]  overhead +1876.51%

macos

dynamic/launch             change  -0.30%  [ -5.17% ..  +4.97%]  overhead  +239.71%
dynamic/access             change  -0.69%  [ -4.26% ..  +2.88%]  overhead    +3.99%
dynamic/access-relative    change  +0.10%  [ -2.74% ..  +4.63%]  overhead  +262.15%
dynamic/access-contended   change  +0.89%  [ -6.38% .. +14.32%]  overhead    +1.56%

windows

dynamic/launch             change  +0.37%  [ -1.44% ..  +2.19%]  overhead   +30.76%
dynamic/access             change  +0.00%  [ -0.42% ..  +0.42%]  overhead    +1.51%
dynamic/access-relative    change  +0.00%  [ -0.41% ..  +0.41%]  overhead    +1.26%
dynamic/access-contended   change  +0.00%  [ -0.41% ..  +0.41%]  overhead    +1.46%