Files
buzz/crates/buzz-datastore-tracing/src/lib.rs
Luke Tornquist 113a33b7e4 Add database pressure observability (#6700)
## Why

Database pressure currently collapses several distinct delays into one
symptom. This adds the evidence layer needed to distinguish pool
acquisition wait, logical database operation time, advisory-lock wait,
and selected transaction duration before changing timeout or retry
policy.

This is the phase 2 Lane A observability bundle for
[#26](https://github.com/TheSentinel454/buzz/issues/26),
[#28](https://github.com/TheSentinel454/buzz/issues/28), and
[#33](https://github.com/TheSentinel454/buzz/issues/33). It is stacked
on #6668.

## What

- Record explicit reader/writer checkout wait and acquisition outcomes
with `buzz_db_pool_acquire_wait_seconds` and
`buzz_db_pool_acquisitions_total`.
- Extend the compile-time `#[datastore_span(name = "...")]` seam with
`buzz_db_operation_duration_seconds`, so operation labels remain static
source literals instead of request data.
- Route correctness-critical replacement, membership, push-gate,
deletion, and migration/schema-safety advisory locks through one
observer without changing their SQL, order, scope, or blocking behavior.
- Measure six internally owned transaction lifetimes with
`buzz_db_transaction_duration_seconds`, starting after `BEGIN` succeeds
and ending after explicit commit/rollback or scope exit.
- Emit root slow-operation warnings at 500 ms, logging the first slow
completion and then 1/100 per call site with only `operation`,
`outcome`, and `elapsed_ms`.
- Document names, units, fixed label vocabularies, measurement
boundaries, and blind spots in this PR description.

Fixed labels are deliberately small:

- `pool_role`: `writer`, `reader`
- `lock_type`: `replacement`, `membership`, `push_gate`, `deletion`,
`migration_schema_safety`
- `outcome`: `success`, `error`, `timeout` where SQLx/PostgreSQL can
distinguish it accurately
- `operation`: compile-time datastore names plus the six closed
transaction operation names documented in the runbook

No metric or slow warning contains community IDs, event IDs, event
kinds, coordinates, d-tags, SQL/query text, query IDs, returned errors,
or event content.

## Coverage boundaries

- Operation duration is the complete annotated logical function body,
not pure SQL execution; it may include implicit checkout, lock wait,
nested operations, and application work. Cancelled futures do not reach
its completion hook.
- Pool timing covers explicit helper checkouts, including proved-reader
routing and selected writer-owned transactions. Implicit SQLx checkout
through `&PgPool` remains folded into operation duration.
- Lock timing covers application-side blocking locks in the five named
families. Trigger/stored-procedure locks, channel-TTL locking, the usage
try-lock, and the audit service session lock remain outside this slice.
- Transaction timing covers only the six wholly owned boundaries
documented in the runbook. It excludes pool wait, `BEGIN`, asynchronous
rollback cleanup after an early return, and caller-owned
`Db::begin_transaction` lifetime.

## Relationship to #6229

#6229 is the incident-driven timeout precursor. This PR does not add or
change `statement_timeout`, `lock_timeout`,
`idle_in_transaction_session_timeout`, retries, audit durability, or
client-visible conflicts. It provides the missing distributions needed
to evaluate those policies later and intentionally leaves #6229's open
audit retry/durability finding untouched.

The branches overlap in `crates/buzz-db/src/lib.rs` and
`crates/buzz-db/src/migration.rs`, so a later rebase may need textual
conflict resolution, but the behavior is complementary rather than
duplicated.

## Risk assessment

Moderate-low. The primary risk is instrumentation overhead and added
static series. Cardinality is source-bounded, slow logs are
sampled/redacted root events, and the lock/transaction changes wrap
existing awaits without changing policy or ordering.

## Verification

Author workstation: `buzz-tornquist-db-pressure-observability`
(`2010927`), exact head `d7cf833e26c528adfcde3917ded80daf6f4ddac9`,
parent `6f50e6b2b2a996349149af61d35bdd6a355f77fd`.

- `cargo fmt --all --check` — passed
- `cargo clippy -p buzz-datastore-tracing -p buzz-db -p buzz-audit -p
buzz-search -p buzz-relay --all-targets -- -D warnings` — passed
- `cargo test -p buzz-datastore-tracing --quiet` — 4 passed
- `cargo test -p buzz-db --quiet` — 109 passed, 200 ignored
- `cargo test -p buzz-audit -p buzz-search --quiet` — 16 passed, 25
ignored
- `cargo test -p buzz-relay --lib --quiet -- --test-threads=1` — 906
passed, 48 ignored
- Native PostgreSQL focused tests for pool success/timeout/error, lock
success/contention/timeout/error, replacement, membership serialization,
push ordering, deletion fencing, migration/schema exclusion, and reader
fallback — 8 passed

The default-parallel relay run passed once; subsequent runs exposed the
existing load-sensitive
`api::mesh_demo::tests::demo_join_forwarded_arm_round_trips_echo` 504 at
the end of the suite. That test passes in isolation and the full relay
suite passes serially.

Independent exact-head review workstation:
`buzz-tornquist-db-pressure-observability-review` (`2013067`).
Formatting, the same all-target clippy command, datastore
instrumentation tests, DB unit tests, source privacy guards, and
diff/non-goal audits passed; no review findings.

Generated with Codex

---------

Signed-off-by: tornquist <tornquist@squareup.com>
2026-08-25 13:00:22 -04:00

209 lines
7.3 KiB
Rust

//! Policy-enforcing instrumentation for logical datastore operations.
use proc_macro::TokenStream;
use proc_macro2::TokenStream as TokenStream2;
use quote::{format_ident, quote};
use syn::parse::{Parse, ParseStream};
use syn::{
parenthesized, parse_macro_input, Error, Ident, ItemFn, LitStr, Result, ReturnType, Token, Type,
};
struct DatastoreArgs {
name: LitStr,
system: LitStr,
fields: Option<TokenStream2>,
}
impl Parse for DatastoreArgs {
fn parse(input: ParseStream<'_>) -> Result<Self> {
let mut name = None;
let mut system = None;
let mut fields = None;
while !input.is_empty() {
let key: Ident = input.parse()?;
match key.to_string().as_str() {
"name" => {
if name.is_some() {
return Err(Error::new(key.span(), "duplicate `name` argument"));
}
input.parse::<Token![=]>()?;
name = Some(input.parse()?);
}
"system" => {
if system.is_some() {
return Err(Error::new(key.span(), "duplicate `system` argument"));
}
input.parse::<Token![=]>()?;
system = Some(input.parse()?);
}
"fields" => {
if fields.is_some() {
return Err(Error::new(key.span(), "duplicate `fields` argument"));
}
let content;
parenthesized!(content in input);
fields = Some(content.parse()?);
}
_ => {
return Err(Error::new(
key.span(),
"expected `name`, `system`, or `fields`",
))
}
}
if !input.is_empty() {
input.parse::<Token![,]>()?;
}
}
Ok(Self {
name: name.ok_or_else(|| Error::new(input.span(), "missing `name`"))?,
system: system.ok_or_else(|| Error::new(input.span(), "missing `system`"))?,
fields,
})
}
}
/// Instruments an async logical datastore operation according to Buzz policy.
///
/// PostgreSQL spans always omit function arguments, use the `buzz_datastore`
/// target, and expose only canonical semantic fields plus explicitly supplied
/// safe fields. An `Err` sets `otel.status_code` without inspecting the error.
/// The literal `name` also labels a logical-operation duration histogram. Slow
/// completions are sampled and logged with only that name, outcome, and elapsed
/// time; arguments, error values, and return values are never formatted.
#[proc_macro_attribute]
pub fn datastore_span(args: TokenStream, item: TokenStream) -> TokenStream {
let args = parse_macro_input!(args as DatastoreArgs);
let mut function = parse_macro_input!(item as ItemFn);
if function.sig.asyncness.is_none() {
return Error::new_spanned(
function.sig.fn_token,
"`datastore_span` requires an async function",
)
.into_compile_error()
.into();
}
if args.system.value() != "postgresql" {
return Error::new_spanned(
args.system,
"unsupported datastore system; only `postgresql` is currently supported",
)
.into_compile_error()
.into();
}
let name = args.name;
let extra_fields = args.fields.map(|tokens| quote!(, #tokens));
function.attrs.push(syn::parse_quote!(
#[::tracing::instrument(
target = "buzz_datastore",
name = #name,
skip_all,
fields(
otel.kind = "client",
db.system.name = "postgresql",
otel.status_code = ::tracing::field::Empty
#extra_fields
)
)]
));
let return_type: Type = match &function.sig.output {
ReturnType::Type(_, ty) => *ty.clone(),
ReturnType::Default => syn::parse_quote!(()),
};
let returns_result = match &return_type {
Type::Path(path) => path
.path
.segments
.last()
.is_some_and(|segment| segment.ident == "Result"),
_ => false,
};
let original_body = function.block;
let result = format_ident!("__buzz_datastore_result_7f3a9c");
let record_error = returns_result.then(|| {
quote! {
if #result.is_err() {
::tracing::Span::current().record("otel.status_code", "ERROR");
}
}
});
let outcome = if returns_result {
quote! {
if #result.is_err() { "error" } else { "success" }
}
} else {
quote!("success")
};
function.block = Box::new(syn::parse_quote!({
let __buzz_datastore_started_7f3a9c = ::std::time::Instant::now();
let #result: #return_type = (async #original_body).await;
#record_error
let __buzz_datastore_outcome_7f3a9c = #outcome;
let __buzz_datastore_elapsed_7f3a9c = __buzz_datastore_started_7f3a9c.elapsed();
::metrics::histogram!(
"buzz_db_operation_duration_seconds",
"operation" => #name,
"outcome" => __buzz_datastore_outcome_7f3a9c,
)
.record(__buzz_datastore_elapsed_7f3a9c.as_secs_f64());
if __buzz_datastore_elapsed_7f3a9c >= ::std::time::Duration::from_millis(500) {
static __BUZZ_DATASTORE_SLOW_SAMPLE_7F3A9C:
::std::sync::atomic::AtomicU64 = ::std::sync::atomic::AtomicU64::new(0);
if __BUZZ_DATASTORE_SLOW_SAMPLE_7F3A9C.fetch_add(
1,
::std::sync::atomic::Ordering::Relaxed,
) % 100 == 0 {
let __buzz_datastore_elapsed_ms_7f3a9c =
__buzz_datastore_elapsed_7f3a9c
.as_millis()
.min(::std::primitive::u64::MAX as u128) as u64;
::tracing::warn!(
target: "buzz_datastore",
parent: None,
operation = #name,
outcome = __buzz_datastore_outcome_7f3a9c,
elapsed_ms = __buzz_datastore_elapsed_ms_7f3a9c,
"slow datastore operation"
);
}
}
#result
}));
quote!(#function).into()
}
#[cfg(test)]
mod tests {
use super::DatastoreArgs;
#[test]
fn parses_safe_tracing_fields() {
let args: DatastoreArgs = syn::parse_str(
r#"name = "audit", system = "postgresql", fields(action = %entry.action, from_seq = from_seq, limit = limit)"#,
)
.expect("valid arguments");
assert!(args.fields.is_some());
}
#[test]
fn rejects_duplicate_arguments() {
for args in [
r#"name = "one", name = "two", system = "postgresql""#,
r#"name = "one", system = "postgresql", system = "postgresql""#,
r#"name = "one", system = "postgresql", fields(a = 1), fields(b = 2)"#,
] {
let error = match syn::parse_str::<DatastoreArgs>(args) {
Ok(_) => panic!("duplicate accepted"),
Err(error) => error,
};
assert!(error.to_string().starts_with("duplicate `"));
}
}
}