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 <noreply@anthropic.com>

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.

src/db.rs

@@ -390,26 +390,30 @@ impl Db {
     ) -> Result<std::collections::HashMap<String, FeedListing>> {
         use std::collections::HashMap;
         let one = || sea_orm::Value::from(only.map(str::to_owned));
-        let counts = |sql: &'static str, args: Vec<sea_orm::Value>| 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<sea_orm::Value>| async move {
+            tracing::Instrument::instrument(self.rows(sql, args), step(of))
                 .await?
                 .iter()
                 .map(|r| Ok((r.try_get::<String>("", "feed_id")?, r.try_get::<i64>("", "n")?)))
                 .collect::<Result<HashMap<_, _>>>()
         };
         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,9 +426,10 @@ impl Db {
             vec![user_id.into(), one()],
         )
         .await?;
-        let mut blocked: HashMap<String, Vec<String>> = blocklists::Entity::find()
-            .filter(blocklists::Column::UserId.eq(user_id))
-            .all(&self.orm)
+        let mut blocked: HashMap<String, Vec<String>> = 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()))
@@ -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()

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<Vec<FeedRow>> {
+    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<String, crate::db::Sub> = 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);