diff --git a/src/main.rs b/src/main.rs index 551d6ac..abd7258 100644 --- a/src/main.rs +++ b/src/main.rs @@ -511,13 +511,27 @@ fn read_password_hidden(prompt: &str) -> Result { } /// `RUST_LOG`-driven tracing, defaulting to `info` (crate table "logging"). +/// +/// Two layers over one registry rather than a bare `fmt()`: the statement +/// timings behind the `db` metric of `Server-Timing` ride in on sqlx's own +/// `DEBUG` events, and [`daily_epub::web::timing`] needs those enabled without +/// any of them reaching the log. Each layer carries its own filter, so the +/// `RUST_LOG` above still says exactly what gets printed. fn init_tracing() { + use tracing_subscriber::Layer as _; + use tracing_subscriber::layer::SubscriberExt as _; + use tracing_subscriber::util::SubscriberInitExt as _; + let filter = EnvFilter::try_from_default_env() .unwrap_or_else(|_| EnvFilter::new("info,sqlx=warn,hyper=warn,reqwest=warn")); - tracing_subscriber::fmt() - .with_env_filter(filter) - .with_target(false) - .with_writer(std::io::stderr) + tracing_subscriber::registry() + .with( + tracing_subscriber::fmt::layer() + .with_target(false) + .with_writer(std::io::stderr) + .with_filter(filter), + ) + .with(daily_epub::web::timing::sqlx_timing_layer()) .init(); } diff --git a/src/server.rs b/src/server.rs index a4ac41f..884c23f 100644 --- a/src/server.rs +++ b/src/server.rs @@ -177,6 +177,9 @@ pub fn router(state: AppState) -> Router { .layer(PropagateRequestIdLayer::x_request_id()) .layer(TraceLayer::new_for_http()) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)) + // Immediately inside the auth layer, so what is left outside it is the + // session load and save that `server_timing` reports as `sess`. + .layer(from_fn(crate::web::route_boundary)) .layer(auth_layer) .layer(from_fn_with_state( state.clone(), diff --git a/src/web/mod.rs b/src/web/mod.rs index 41d8d51..9daf497 100644 --- a/src/web/mod.rs +++ b/src/web/mod.rs @@ -3,6 +3,7 @@ pub mod issue; pub mod public; pub mod rate; pub mod session; +pub mod timing; pub mod users; use std::fmt; @@ -391,21 +392,11 @@ fn session_error(error: axum_login::tower_sessions::session::Error) -> WebError WebError::Internal(error.into()) } -/// `Server-Timing: app;dur=` on every response: the time this process -/// spent on the request, so the browser's DevTools (or `curl -sI`) can split -/// origin work from the network. Outermost layer, so it covers the session -/// load, auth and rendering. -pub async fn server_timing(request: Request, next: Next) -> Response { - let started = std::time::Instant::now(); - let mut response = next.run(request).await; - let millis = started.elapsed().as_secs_f64() * 1000.0; - if let Ok(value) = HeaderValue::from_str(&format!("app;dur={millis:.2}")) { - response - .headers_mut() - .insert(header::HeaderName::from_static("server-timing"), value); - } - response -} +/// `Server-Timing` on every response, so the browser's DevTools (or +/// `curl -sI`) can split origin work from the network and then split the +/// origin work up again. See [`timing`] for the metrics and how they are +/// collected. +pub use self::timing::{route_boundary, server_timing}; /// Refuse TLS 1.3 0-RTT data for anything but a safe method (RFC 8470 §5.2). /// @@ -433,7 +424,10 @@ pub struct Html(pub T); impl IntoResponse for Html { fn into_response(self) -> Response { - match self.0.render() { + let started = std::time::Instant::now(); + let rendered = self.0.render(); + timing::record_render(started.elapsed()); + match rendered { Ok(body) => ( StatusCode::OK, [(header::CONTENT_TYPE, "text/html; charset=utf-8")], @@ -794,6 +788,20 @@ mod tests { use crate::db::Db; use crate::server::{AppState, router}; + /// The `db` metric only fills in when [`timing::sqlx_timing_layer`] is + /// installed, and it has to be installed *globally*: sqlx times statements + /// on a worker thread, which sees no thread-local default. Global means + /// once per test binary, hence the `Once`; nothing is written anywhere, so + /// the tests that do not care never notice it. + fn install_timing_layer() { + use tracing_subscriber::layer::SubscriberExt as _; + static INSTALLED: std::sync::Once = std::sync::Once::new(); + INSTALLED.call_once(|| { + let subscriber = tracing_subscriber::registry().with(timing::sqlx_timing_layer()); + let _ = tracing::subscriber::set_global_default(subscriber); + }); + } + async fn test_state(config: Config) -> (tempfile::TempDir, AppState) { let dir = tempfile::tempdir().unwrap(); let db = Db::open_and_migrate(&dir.path().join("db.sqlite")) @@ -933,6 +941,10 @@ mod tests { .to_str() .unwrap(); assert!(timing.starts_with("app;dur="), "{timing}"); + // `/healthz` is routed but touches neither SQLite nor a template. + assert!(timing.contains("sess;dur="), "{timing}"); + assert!(!timing.contains("db;dur="), "{timing}"); + assert!(!timing.contains("tpl;dur="), "{timing}"); // A safe method may arrive as 0-RTT data; a POST may not. let response = app @@ -955,6 +967,79 @@ mod tests { assert_eq!(response.status(), StatusCode::TOO_EARLY); } + /// The `db` metric crosses a thread boundary to get here: sqlx runs the + /// statement on the connection's worker thread and only reports the + /// elapsed time there, inside the span this request handed it. This is the + /// test that the hand-off actually holds together. + #[tokio::test] + async fn server_timing_breaks_the_request_into_session_db_and_template() { + install_timing_layer(); + let (_dir, state) = test_state(Config::default()).await; + users::add(&state.db, "admin", "correct horse battery", true) + .await + .unwrap(); + let app = router(state); + let cookie = login_cookie(&app, "admin", "correct horse battery").await; + let response = app + .oneshot( + Request::builder() + .uri("/dashboard/articles") + .header(header::COOKIE, cookie) + .body(Body::empty()) + .unwrap(), + ) + .await + .unwrap(); + assert_eq!(response.status(), StatusCode::OK); + let timing = response + .headers() + .get("server-timing") + .unwrap() + .to_str() + .unwrap() + .to_string(); + + // Every metric is present, and each is a number the spec allows. + assert!(timing.starts_with("app;dur="), "{timing}"); + let mut durations = std::collections::HashMap::new(); + for metric in timing.split(", ") { + let (name, rest) = metric.split_once(";dur=").expect(&timing); + let number = rest.split(';').next().unwrap(); + durations.insert(name, number.parse::().expect(&timing)); + } + for name in ["app", "sess", "db", "tpl"] { + assert!(durations.contains_key(name), "{name} missing from {timing}"); + } + + // A dashboard page loads the session and renders, so each of those is + // inside the whole rather than beside it. `db` is left out: it is a + // sum of statement times, which a handler running queries concurrently + // could legitimately push past the wall clock. + let app_dur = durations["app"]; + for name in ["sess", "tpl"] { + assert!(durations[name] <= app_dur, "{name} exceeds app in {timing}"); + } + // `sess` is the session load and save; `db` includes those statements + // and the page's own, so neither is a subset of the other, but both + // had to have measured something. + assert!(durations["db"] > 0.0, "{timing}"); + + // The statement count rides along in `desc`, which is where DevTools + // shows it. A dashboard page runs several: session, user, articles. + let db = timing + .split(", ") + .find(|metric| metric.starts_with("db;")) + .expect(&timing); + let count: u32 = db + .split("desc=\"") + .nth(1) + .and_then(|desc| desc.split_whitespace().next()) + .and_then(|count| count.parse().ok()) + .unwrap_or_else(|| panic!("no statement count in {db}")); + assert!(count > 1, "{db}"); + assert!(db.ends_with(" queries\""), "{db}"); + } + #[tokio::test] async fn login_cookie_account_logout_and_anonymous_pages() { let mut config = Config::default(); diff --git a/src/web/public.rs b/src/web/public.rs index 055a5d1..65a0173 100644 --- a/src/web/public.rs +++ b/src/web/public.rs @@ -308,9 +308,12 @@ pub async fn feed(State(state): State) -> Result { }; updated = updated.max(view.issue.meta.generated_at); let issue = PublicIssue::from(&view.issue); - let content = FeedEntryTemplate { issue: &issue } - .render() - .map_err(|error| WebError::Internal(error.into()))?; + // Counted towards `tpl` by hand: the feed renders per entry rather + // than through `Html`, which is where every HTML page is measured. + let started = std::time::Instant::now(); + let content = FeedEntryTemplate { issue: &issue }.render(); + crate::web::timing::record_render(started.elapsed()); + let content = content.map_err(|error| WebError::Internal(error.into()))?; let href = format!( "{}/issues/{}", config.server.public_url.trim_end_matches('/'), diff --git a/src/web/timing.rs b/src/web/timing.rs new file mode 100644 index 0000000..44d3b0f --- /dev/null +++ b/src/web/timing.rs @@ -0,0 +1,343 @@ +//! Per-request `Server-Timing` metrics (§3.12). +//! +//! The header splits one request into the parts worth telling apart: +//! +//! | metric | what it covers | +//! |---|---| +//! | `app` | everything this process did, the outermost middleware inwards | +//! | `sess` | the session/auth layers: the cookie's `SELECT` on the way in, the save on the way out | +//! | `db` | SQLite statement time, with the statement count in `desc` | +//! | `tpl` | askama rendering | +//! +//! They overlap rather than partition: `sess` and `db` are both inside `app`, +//! and they share the session's own statements. Handler time is `app` − `sess`, +//! and `sess` − (the session's share of `db`) is what the auth layers cost +//! beyond SQLite — on a warm `/account` that gap has been most of the request, +//! which is the sort of thing these metrics exist to make visible. +//! +//! `db` is collected the only way that works for SQLite: sqlx runs statements +//! on a per-connection worker *thread*, so a task-local set by the middleware +//! is invisible there. What does cross over is the caller's [`tracing::Span`] — +//! `sqlx-sqlite` sends it alongside every command and enters it while the +//! statement runs — so the `sqlx::query` event it emits on finishing lands +//! inside this request's span. [`SqlxTimingLayer`] picks the elapsed time off +//! that event and adds it to the metrics hanging in the span's extensions. +//! Metrics recorded on the request task itself (`tpl`, the `sess` boundary) +//! take the shorter path through the task-local. +//! +//! Nothing here is load-bearing: without [`SqlxTimingLayer`] installed the `db` +//! metric is simply absent, and without a subscriber at all the span costs +//! nothing and `app` still reports. +//! +//! What installing it does cost is process-wide: the filter's `DEBUG` hint +//! lifts the global maximum level from `INFO`, so every `DEBUG` span in any +//! dependency (tower-http's per-request span, axum-login's instrumented user +//! loads) is now materialised in the registry, and sqlx builds a summary +//! string for each statement it reports. Microseconds per request, against +//! an origin measured in milliseconds; noted so it is not mistaken for free. + +use std::fmt::Write as _; +use std::sync::Arc; +use std::sync::atomic::{AtomicU32, AtomicU64, Ordering}; +use std::time::{Duration, Instant}; + +use axum::extract::Request; +use axum::http::{HeaderValue, header}; +use axum::middleware::Next; +use axum::response::Response; +use tracing::Instrument as _; +use tracing_subscriber::layer::{Context, Layer}; +use tracing_subscriber::registry::LookupSpan; + +/// Target of the per-request span. It is how [`SqlxTimingLayer`] recognises +/// the one span to hang metrics on, and being off the crate's module path also +/// keeps the span out of the log under the default `RUST_LOG` (`info`). +const REQUEST_TARGET: &str = "daily_epub::request"; + +/// The target sqlx logs every finished statement to. +const SQLX_TARGET: &str = "sqlx::query"; + +/// Sentinel for a boundary mark that was never reached. +const UNSET: u64 = u64::MAX; + +tokio::task_local! { + /// The metrics for the request running on this task. Set by + /// [`server_timing`], so it covers everything inside that middleware. + static CURRENT: Arc; +} + +/// One request's accumulated timings. +/// +/// Written from two places at once — the request task and a sqlx worker +/// thread — so every counter is atomic. `Relaxed` is enough: nothing here +/// orders anything else, and the totals are only read after the response is +/// complete and both writers are done. +#[derive(Debug)] +pub struct RequestMetrics { + started: Instant, + db_nanos: AtomicU64, + db_statements: AtomicU32, + tpl_nanos: AtomicU64, + tpl_renders: AtomicU32, + /// Nanoseconds after `started` at which the routed part of the stack was + /// entered and left; [`UNSET`] until [`route_boundary`] marks them. + route_entered: AtomicU64, + route_left: AtomicU64, +} + +impl RequestMetrics { + fn new() -> Self { + Self { + started: Instant::now(), + db_nanos: AtomicU64::new(0), + db_statements: AtomicU32::new(0), + tpl_nanos: AtomicU64::new(0), + tpl_renders: AtomicU32::new(0), + route_entered: AtomicU64::new(UNSET), + route_left: AtomicU64::new(UNSET), + } + } + + fn add_db(&self, elapsed: Duration) { + self.db_nanos.fetch_add(nanos(elapsed), Ordering::Relaxed); + self.db_statements.fetch_add(1, Ordering::Relaxed); + } + + fn add_render(&self, elapsed: Duration) { + self.tpl_nanos.fetch_add(nanos(elapsed), Ordering::Relaxed); + self.tpl_renders.fetch_add(1, Ordering::Relaxed); + } + + /// The `sess` metric: everything outside the routed stack, which is the + /// session load on the way in plus the session save on the way out. Absent + /// until both boundaries have been marked — a request rejected before it + /// reaches the router (a 425, a cross-origin 403) never gets there. + fn session_nanos(&self) -> Option { + let entered = self.route_entered.load(Ordering::Relaxed); + let left = self.route_left.load(Ordering::Relaxed); + if entered == UNSET || left == UNSET { + return None; + } + Some(entered + nanos(self.started.elapsed()).saturating_sub(left)) + } + + /// The header value: `app` always, the rest only where they were measured. + fn header(&self) -> String { + let mut value = String::with_capacity(72); + write!( + value, + "app;dur={:.2}", + millis(nanos(self.started.elapsed())) + ) + .expect("writing to a String cannot fail"); + if let Some(session) = self.session_nanos() { + write!(value, ", sess;dur={:.2}", millis(session)) + .expect("writing to a String cannot fail"); + } + let statements = self.db_statements.load(Ordering::Relaxed); + if statements > 0 { + let unit = if statements == 1 { "query" } else { "queries" }; + write!( + value, + ", db;dur={:.2};desc=\"{statements} {unit}\"", + millis(self.db_nanos.load(Ordering::Relaxed)) + ) + .expect("writing to a String cannot fail"); + } + if self.tpl_renders.load(Ordering::Relaxed) > 0 { + write!( + value, + ", tpl;dur={:.2}", + millis(self.tpl_nanos.load(Ordering::Relaxed)) + ) + .expect("writing to a String cannot fail"); + } + value + } +} + +/// Saturating, because a `Duration` holds more nanoseconds than a `u64` can. +fn nanos(elapsed: Duration) -> u64 { + u64::try_from(elapsed.as_nanos()).unwrap_or(u64::MAX) +} + +fn millis(nanos: u64) -> f64 { + nanos as f64 / 1_000_000.0 +} + +/// Run `f` against the metrics of the request on this task, if there is one. +fn with_metrics(f: impl FnOnce(&RequestMetrics)) { + let _ = CURRENT.try_with(|metrics| f(metrics)); +} + +/// Add one template render to the `tpl` metric. Called by +/// [`crate::web::Html`], which is how every HTML page is rendered. +pub fn record_render(elapsed: Duration) { + with_metrics(|metrics| metrics.add_render(elapsed)); +} + +/// `Server-Timing` on every response: see the module docs for the metrics. +/// +/// Outermost layer, so `app` covers the session load, auth and rendering. The +/// per-request span is opened *inside* the task-local scope so that +/// [`SqlxTimingLayer::on_new_span`] can hang these same metrics on it. +pub async fn server_timing(request: Request, next: Next) -> Response { + let metrics = Arc::new(RequestMetrics::new()); + let mut response = CURRENT + .scope(metrics.clone(), async move { + let span = tracing::debug_span!(target: REQUEST_TARGET, "http_request"); + next.run(request).instrument(span).await + }) + .await; + if let Ok(value) = HeaderValue::from_str(&metrics.header()) { + response + .headers_mut() + .insert(header::HeaderName::from_static("server-timing"), value); + } + response +} + +/// Marks where the routed part of the stack begins, so the time spent in the +/// session and auth layers wrapped around it can be reported as `sess`. +/// Belongs immediately inside the auth layer; anywhere else and the metric +/// quietly measures something other than its name. +pub async fn route_boundary(request: Request, next: Next) -> Response { + with_metrics(|metrics| { + metrics + .route_entered + .store(nanos(metrics.started.elapsed()), Ordering::Relaxed); + }); + let response = next.run(request).await; + with_metrics(|metrics| { + metrics + .route_left + .store(nanos(metrics.started.elapsed()), Ordering::Relaxed); + }); + response +} + +/// Adds every `sqlx::query` event's elapsed time to the request it ran for. +/// +/// Install it with [`sqlx_timing_layer`], which filters it down to the two +/// targets it needs; on its own it would be asked about every event in the +/// process. +pub struct SqlxTimingLayer; + +/// [`SqlxTimingLayer`] under the filter it needs. This is the form to install. +pub fn sqlx_timing_layer() -> impl Layer +where + S: tracing::Subscriber + for<'a> LookupSpan<'a>, +{ + SqlxTimingLayer.with_filter(SqlxTimingFilter) +} + +/// What [`SqlxTimingLayer`] is shown: the `sqlx::query` event, and every span. +/// +/// Asking for the event at `DEBUG` is also what makes sqlx emit it — it only +/// fires when some subscriber wants it — so this filter is what turns +/// statement timing on, whatever `RUST_LOG` says. +/// +/// Every *span*, though, is not over-reach; it is the whole thing working. +/// The event surfaces on a sqlx worker thread whose span stack holds exactly +/// one entry: the innermost span the calling task was inside, which in this +/// stack is `axum_login`'s `call`, not the request span two levels up. +/// `Context::lookup_current` will not hand back a span its own layer's filter +/// rejects, and its fallback re-walks that same one-entry thread stack rather +/// than the parent chain — so a single unseen span between the request span +/// and the query hides the request span completely, and the only symptom is a +/// `db` metric that quietly never appears. Naming the targets to expect would +/// mean re-learning that the next time a middleware is added. +/// +/// Being shown a span costs a target comparison, and changes nothing about +/// the log: the `fmt` layer still applies `RUST_LOG` to what it prints. +struct SqlxTimingFilter; + +impl tracing_subscriber::layer::Filter for SqlxTimingFilter { + /// Whether a callsite is a span, and what target it has, are both fixed at + /// compile time, so this is exact and the interest cache still applies. + fn callsite_enabled( + &self, + meta: &'static tracing::Metadata<'static>, + ) -> tracing::subscriber::Interest { + if Self::wanted(meta) { + tracing::subscriber::Interest::always() + } else { + tracing::subscriber::Interest::never() + } + } + + fn enabled(&self, meta: &tracing::Metadata<'_>, _: &Context<'_, S>) -> bool { + Self::wanted(meta) + } + + /// `DEBUG` is what this layer *needs*, not a ceiling on what it accepts: + /// no span above the process-wide maximum is ever created, so capping the + /// hint here keeps that maximum where sqlx's own event already puts it + /// rather than dragging it to `TRACE`. A `RUST_LOG` that asks for `TRACE` + /// raises the maximum itself, and those spans are then let through too. + fn max_level_hint(&self) -> Option { + Some(tracing_subscriber::filter::LevelFilter::DEBUG) + } +} + +impl SqlxTimingFilter { + fn wanted(meta: &tracing::Metadata<'_>) -> bool { + meta.is_span() || meta.target() == SQLX_TARGET + } +} + +impl Layer for SqlxTimingLayer +where + S: tracing::Subscriber + for<'a> LookupSpan<'a>, +{ + /// Hang the task's metrics on the request span as it opens. This runs + /// synchronously inside [`server_timing`]'s task-local scope, which is the + /// whole trick: from here on the metrics are reachable from any thread + /// that enters the span. + fn on_new_span( + &self, + _attrs: &tracing::span::Attributes<'_>, + id: &tracing::Id, + ctx: Context<'_, S>, + ) { + let Some(span) = ctx.span(id) else { return }; + if span.metadata().target() != REQUEST_TARGET { + return; + } + let _ = CURRENT.try_with(|metrics| { + span.extensions_mut().insert(metrics.clone()); + }); + } + + fn on_event(&self, event: &tracing::Event<'_>, ctx: Context<'_, S>) { + if event.metadata().target() != SQLX_TARGET { + return; + } + let mut elapsed = ElapsedSecs(None); + event.record(&mut elapsed); + let Some(elapsed) = elapsed.0 else { return }; + let Some(scope) = ctx.event_scope(event) else { + return; + }; + for span in scope { + if let Some(metrics) = span.extensions().get::>() { + metrics.add_db(Duration::from_secs_f64(elapsed)); + return; + } + } + } +} + +/// Pulls `elapsed_secs` off a `sqlx::query` event — the numeric field sqlx +/// emits next to the human-readable `elapsed`. +struct ElapsedSecs(Option); + +impl tracing::field::Visit for ElapsedSecs { + fn record_f64(&mut self, field: &tracing::field::Field, value: f64) { + if field.name() == "elapsed_secs" { + self.0 = Some(value); + } + } + + fn record_debug(&mut self, _: &tracing::field::Field, _: &dyn std::fmt::Debug) {} +}