Skip to content

Instrument KV operation timing logs#270

Open
ChristianPavilonis wants to merge 2 commits into
mainfrom
kv-timing-logs
Open

Instrument KV operation timing logs#270
ChristianPavilonis wants to merge 2 commits into
mainfrom
kv-timing-logs

Conversation

@ChristianPavilonis

@ChristianPavilonis ChristianPavilonis commented May 26, 2026

Copy link
Copy Markdown
Contributor

Summary

  • Add debug-level timing logs for KvHandle backend operations across adapters.
  • Log only safe KV metadata so operation latency is observable without exposing raw keys, prefixes, cursors, or values.
  • Document KV operation timing behavior in the guide.

Related external tracking: IABTechLab/trusted-server#731

Changes

Crate / File Change
crates/edgezero-core/src/key_value_store.rs Times KvHandle backend calls with web_time::Instant and emits guarded log::debug! metadata for get/put/TTL/raw/list/delete/exists operations.
docs/guide/kv.md Adds an Operation Timing / Observability section describing debug logs, safe metadata, typed helper timing boundaries, and read_modify_write behavior.

Closes

Closes #271

Test plan

  • cargo test --workspace --all-targets
  • cargo clippy --workspace --all-targets --all-features -- -D warnings
  • cargo check --workspace --all-targets --features "fastly cloudflare spin"
  • WASM builds: wasm32-wasip1 Spin via cargo check -p edgezero-adapter-spin --target wasm32-wasip1 --features spin
  • Manual testing via edgezero-cli dev
  • Other: cargo test -p edgezero-core; cargo test -p edgezero-adapter-axum --all-targets; cargo fmt --all -- --check

Checklist

  • Changes follow CLAUDE.md conventions
  • No Tokio deps added to core or adapter crates
  • Route params use {id} syntax (not :id)
  • Types imported from edgezero_core (not http crate)
  • New code has tests
  • No secrets or credentials committed

@aram356 aram356 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PR Review — Instrument KV operation timing logs

Summary

Adds debug-level backend-timing instrumentation to every KvHandle operation, with a zero-overhead-when-disabled design (Instant::now() and the metadata closure are gated behind log_enabled!(Debug)) and safe metadata that logs only lengths/counts/hit-miss/ttl — never raw keys, values, prefixes, or cursors. The implementation is correct and all CI gates pass; the requested changes are about a stated-but-untested security guarantee and structured-log correctness.

Note: this PR is branched from main's older layout of key_value_store.rs; the in-flight feature/extensible-cli branch has independently refactored the same file (alphabetized methods, #[inline]), so expect merge conflicts at integration time.

Findings

Blocking

  • 🔧 Untested security guarantee (docs/guide/kv.md:95): the "never logged" promise has no test enforcing it. Add a capturing-logger regression test asserting raw keys/values never appear in output.
  • 🔧 Mixed-type metadata fields on error (crates/edgezero-core/src/key_value_store.rs:436, :595, :640): numeric/boolean fields are emitted as the string unknown on error paths, breaking logfmt/metrics ingestion. Omit them on error since status=error already signals failure.

Non-blocking

  • ♻️ DRY (key_value_store.rs:460, :546): get/get_bytes inline the same read-metadata format string; extract a kv_read_metadata helper to mirror kv_write_metadata.
  • 🤔 Cloudflare timer clamping (docs/guide/kv.md:93): performance.now() advances only across I/O and at reduced resolution on Workers; document that elapsed_ms is approximate there.
  • 📝 read_modify_write emits two logs (key_value_store.rs:526): RMW delegates to get+put, producing operation=get and operation=put lines (no read_modify_write line). Documented already — noted for operators reading logs.

CI Status (run in an isolated worktree at the PR head)

  • fmt: PASS
  • clippy (-p edgezero-core --all-targets --all-features -D warnings): PASS
  • tests (cargo test -p edgezero-core): PASS — 320 passed, 0 failed

Comment thread docs/guide/kv.md Outdated
Comment thread crates/edgezero-core/src/key_value_store.rs Outdated
Comment thread crates/edgezero-core/src/key_value_store.rs Outdated
Comment thread docs/guide/kv.md

@prk-Jr prk-Jr left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PR Review

Summary

Reviewed PR #270 at head 73a718b. The timing instrumentation is scoped to backend KV calls, uses web_time::Instant for WASM compatibility, and keeps log metadata derived rather than raw.

😃 Praise

  • The observability docs clearly call out the important boundaries: safe derived metadata only, the Cloudflare timing caveat, typed helper timing scope, and separate read_modify_write backend calls.
  • The metadata helpers consistently avoid raw keys, prefixes, cursors, and values, with regression coverage for sensitive key/value strings.

Non-blocking

  • 🤔 Timing emission coverage (crates/edgezero-core/src/key_value_store.rs:408): the new tests cover metadata formatting, but not actual public-method log emission. A focused recording-logger test for representative success/error paths could assert operation=..., status=..., elapsed_ms=..., and absence of raw key/value/cursor data.

CI Status

  • fmt: PASS
  • clippy: PASS
  • tests: PASS
  • all-feature check: PASS
  • Spin WASM check: PASS

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Track KV operation timing logs

3 participants