From 6a69818ef06392f90d952c9eb9fa4b1fa01467f2 Mon Sep 17 00:00:00 2001 From: rays Date: Fri, 9 Oct 2026 02:04:45 +0000 Subject: [PATCH] Trace each step of the feed list (#164) GET /api/feeds took 250-300 ms in production with nothing under it in its trace but feed_summary spans of a millisecond, so there was no telling where the time went. feed_rows now wraps the catalogue, the person's subscriptions, the subscriber counts, the pins and feed_list in a step span each, and feed_list each of its five queries. db::step makes a span only inside one already: the healthcheck's status every 30 s and the page's live updates run the same code outside any trace, where each span would be a trace of its own, as feed_summary's already are. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 1 + src/db.rs | 26 ++++++++++++++++++-------- src/web.rs | 14 +++++++++----- 3 files changed, 28 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0baa262..0ef05b3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed +- The feed list's traces show each of its database queries, so it can be told where its time goes. - Saving a feed's settings asks the database for your subscription once, not twice. - `ipx add` and Add feed in the page add a feed the same way, through one piece of code. - Glass's top bar is solid on a phone, in the colour its glass showed, so the strip above it on an iPhone can match it. diff --git a/src/db.rs b/src/db.rs index 8f87dc3..cec95e9 100644 --- a/src/db.rs +++ b/src/db.rs @@ -390,26 +390,30 @@ impl Db { ) -> Result> { use std::collections::HashMap; let one = || sea_orm::Value::from(only.map(str::to_owned)); - let counts = |sql: &'static str, args: Vec| async move { - self.rows(sql, args) + // A step a query: the feed list's trace was 290 ms with nothing under it. + let counts = |of: &'static str, sql: &'static str, args: Vec| async move { + tracing::Instrument::instrument(self.rows(sql, args), step(of)) .await? .iter() .map(|r| Ok((r.try_get::("", "feed_id")?, r.try_get::("", "n")?))) .collect::>>() }; let entries = counts( + "entries", "SELECT feed_id, count(*) AS n FROM entries WHERE (CAST($1 AS TEXT) IS NULL OR feed_id = $1) GROUP BY feed_id", vec![one()], ) .await?; let downloaded = counts( + "downloaded", "SELECT feed_id, count(*) AS n FROM enclosures WHERE path IS NOT NULL AND (CAST($1 AS TEXT) IS NULL OR feed_id = $1) GROUP BY feed_id", vec![one()], ) .await?; let unread = counts( + "unread", "SELECT e.feed_id, count(*) AS n FROM entries e JOIN subscriptions sub ON sub.user_id = $1 AND sub.feed_id = e.feed_id LEFT JOIN entry_state s @@ -422,10 +426,11 @@ impl Db { vec![user_id.into(), one()], ) .await?; - let mut blocked: HashMap> = blocklists::Entity::find() - .filter(blocklists::Column::UserId.eq(user_id)) - .all(&self.orm) - .await? + let mut blocked: HashMap> = tracing::Instrument::instrument( + blocklists::Entity::find().filter(blocklists::Column::UserId.eq(user_id)).all(&self.orm), + step("blocked"), + ) + .await? .into_iter() .map(|b| (b.feed_id, keywords(Some(b.words)).unwrap_or_default())) .collect(); @@ -433,8 +438,7 @@ impl Db { if let Some(id) = only { rows = rows.filter(feeds::Column::Id.eq(id)); } - Ok(rows - .all(&self.orm) + Ok(tracing::Instrument::instrument(rows.all(&self.orm), step("feeds")) .await? .into_iter() .map(|f| { @@ -2173,6 +2177,12 @@ pub enum EntryFlag { Flagged, } +/// A span for one step of a request or a scan, and none outside one: the healthcheck and the page's +/// live updates run the same code, and every call there would be a trace of its own. +pub fn step(of: &'static str) -> tracing::Span { + if tracing::Span::current().is_none() { tracing::Span::none() } else { tracing::info_span!("step", of) } +} + /// Unix seconds. Everything time-shaped in the DB is stored this way. pub fn now() -> i64 { std::time::SystemTime::now() diff --git a/src/web.rs b/src/web.rs index 6d75737..dea8fb9 100644 --- a/src/web.rs +++ b/src/web.rs @@ -807,20 +807,24 @@ async fn feeds( /// The feed list as this person sees it, or with `only` the one row for that feed: what a live /// update sends after the feed changes, so the page redraws a row instead of reloading the list. async fn feed_rows(state: &WebState, user: &crate::db::User, only: Option<&str>) -> anyhow::Result> { + use crate::db::step; + use tracing::Instrument; let cfg = state.ctx.cfg(); // Config entries plus the feeds derived from OPML subscriptions -- the catalogue. // What comes back is only the part of it this person subscribes to. - let subs = crate::subscriptions(&state.ctx).await?; + let subs = crate::subscriptions(&state.ctx).instrument(step("catalogue")).await?; let mine: std::collections::HashMap = state .ctx .db - .subscriptions_for(user.id).await? + .subscriptions_for(user.id) + .instrument(step("subscriptions")) + .await? .into_iter() .map(|s| (s.feed_id.clone(), s)) .collect(); - let counts = state.ctx.db.subscriber_counts().await?; - let pinned = state.ctx.db.pinned_feeds(user.id).await?; - let mut listed = state.ctx.db.feed_list(user.id, only).await?; + let counts = state.ctx.db.subscriber_counts().instrument(step("subscriber_counts")).await?; + let pinned = state.ctx.db.pinned_feeds(user.id).instrument(step("pinned")).await?; + let mut listed = state.ctx.db.feed_list(user.id, only).instrument(step("feed_list")).await?; let mut out = Vec::with_capacity(mine.len()); for sub in subs.iter().filter(|s| only.is_none_or(|o| o == s.id)) { let (id, feed) = (&sub.id, &sub.cfg);