From 3d94bce4f5ad23ec42fb4d9a71806669ad632be1 Mon Sep 17 00:00:00 2001 From: rays Date: Fri, 16 Oct 2026 13:50:30 +0000 Subject: [PATCH] Directory requests traced whole: the call, its answer's size, the matching (#250) A Directory page took 983 ms during a scan with 19 ms under spans: the directory's own span ends when it has answered, and ipx's reading of the 458 KB answer, its subscriptions and catalogue, and the matching of 1,471 listings had none. call() is a span now, directory_call, with the answer's size; rows_for has subscriptions, catalogue and match steps. Co-Authored-By: Claude Opus 5.5 --- crates/ipx/CHANGELOG.md | 1 + crates/ipx/src/directory.rs | 4 ++++ crates/ipx/src/web.rs | 5 ++++- 3 files changed, 9 insertions(+), 1 deletion(-) diff --git a/crates/ipx/CHANGELOG.md b/crates/ipx/CHANGELOG.md index c043fc6..8139189 100644 --- a/crates/ipx/CHANGELOG.md +++ b/crates/ipx/CHANGELOG.md @@ -22,6 +22,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- A Directory request's trace shows the call to the directory whole, with the size of its answer, and the steps that match it against your subscriptions (#250). - The page's report of how long a list took to show after a click (`list_shown`, with the view and filter) is logged under that click's trace (#246). ## [1.2.0] - 2026-10-15 diff --git a/crates/ipx/src/directory.rs b/crates/ipx/src/directory.rs index ad3a840..9521950 100644 --- a/crates/ipx/src/directory.rs +++ b/crates/ipx/src/directory.rs @@ -55,6 +55,9 @@ pub fn configured(cfg: &config::Config) -> bool { target(cfg).is_some() } +/// A span the whole call, its answer read and parsed included: the directory's own span ends when it +/// has answered, so a slow read of a large answer showed under no span (#250). +#[tracing::instrument(name = "directory_call", skip_all, fields(http.request.method = %method, url.path = %path.split('?').next().unwrap_or(path), http.response.body.size))] async fn call(ctx: &Ctx, method: reqwest::Method, path: &str, body: Option<&[SnapshotEntry]>) -> Result { let (base, token) = target(&ctx.cfg()).ok_or(DirError::NotConfigured)?; let mut req = ctx.client.request(method, format!("{base}{path}")).bearer_auth(token).timeout(std::time::Duration::from_secs(20)); @@ -73,6 +76,7 @@ async fn call(ctx: &Ctx, method: reqwest::Method, path: &st } // A removal or an unblock answers 204, with nothing to read: that reads as null, which is (). let body = resp.bytes().await.map_err(|e| DirError::Unreachable(format!("{e:#}")))?; + tracing::Span::current().record("http.response.body.size", body.len()); serde_json::from_slice(if body.is_empty() { b"null" } else { &body }).map_err(|e| DirError::Unreachable(format!("its answer did not read: {e:#}"))) } diff --git a/crates/ipx/src/web.rs b/crates/ipx/src/web.rs index 49ad738..c44725c 100644 --- a/crates/ipx/src/web.rs +++ b/crates/ipx/src/web.rs @@ -831,14 +831,17 @@ fn dir_error(e: crate::directory::DirError) -> ApiError { /// The directory's listings as this person sees them: which are theirs already, matched by /// address, since the directory and this server name a feed differently. async fn rows_for(state: &WebState, user_id: i64, listed: Vec) -> Result> { + // A step each, as the feed list has: a Directory page of 983 ms showed 19 under spans (#250). let mine: std::collections::HashSet = - state.ctx.db.subscriptions_for(user_id).await?.into_iter().map(|s| s.feed_id).collect(); + state.ctx.db.subscriptions_for(user_id).instrument(step("subscriptions")).await?.into_iter().map(|s| s.feed_id).collect(); let here: std::collections::HashMap = crate::subscriptions(&state.ctx) + .instrument(step("catalogue")) .await? .into_iter() .filter(|s| mine.contains(&s.id)) .filter_map(|s| ipx_directory::store::normalise(&s.cfg.url).map(|u| (u, s.id))) .collect(); + let _matching = step("match").entered(); Ok(listed .into_iter() .map(|l| {