More step spans where flame graphs showed time with nothing under it (#350)

A week of traces folded with query.py flame left whole requests opaque:
entries_in at 46-82 ms a request with the page's query and its enclosures
together, /api/art 37 ms, /api/status 95 ms, PATCH /api/feeds/{id} 72 ms and
DELETE 45 ms. Each now has a step around what it waits on: the page and its
enclosures; the artwork cache, the check that a feed names it, the fetch and the
write; the status counts; and in changing or leaving a feed, each database call,
the wait for the catalogue's lock and storing it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

crates/ipx/CHANGELOG.md

@@ -12,6 +12,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Changed
+
+- Traces show more of where a request's time goes: a page of items' query and its files apart, artwork's cache, check and fetch, the status counts, and each part of changing or leaving a feed (#350).
+
 ### Fixed
 
 - A WordPress.com site that answers its feed with a browser check (HTTP 403, "Checking your browser...") is read from WordPress.com's API instead, so Pelgrane Press's feed no longer fails for hours at a time. The items are the ones the feed gave: same ids (#317).

crates/ipx/src/db.rs

@@ -1468,8 +1468,7 @@ impl Db {
              LEFT JOIN entry_state s ON s.user_id = {user} AND s.feed_id = e.feed_id AND s.guid = e.guid
              ORDER BY {order}"
         );
-        let mut rows = self
+        let mut rows = tracing::Instrument::instrument(self.rows(&sql, a.0), step("page"))
-            .rows(&sql, a.0)
             .await?
             .iter()
             .map(|r| {
@@ -1499,11 +1498,14 @@ impl Db {
 
         // Only the guids on this page, so a feed with thousands of entries stays cheap. A page
         // can span feeds, so each file is matched to its row by feed as well as guid, below.
-        let encs = enclosures::Entity::find()
+        let encs = tracing::Instrument::instrument(
-            .filter(enclosures::Column::Guid.is_in(rows.iter().map(|r| r.guid.clone())))
+            enclosures::Entity::find()
-            .order_by_asc(enclosures::Column::Id)
+                .filter(enclosures::Column::Guid.is_in(rows.iter().map(|r| r.guid.clone())))
-            .all(&self.orm)
+                .order_by_asc(enclosures::Column::Id)
-            .await?;
+                .all(&self.orm),
+            step("enclosures"),
+        )
+        .await?;
         for enc in encs {
             if let Some(row) = rows.iter_mut().find(|r| r.guid == enc.guid && r.feed_id == enc.feed_id) {
                 row.enclosures.push(EncRow::from(enc));

crates/ipx/src/main.rs

@@ -235,14 +235,15 @@ impl Ctx {
     /// The config as it stands, to change and then keep with `store_cfg`; any other change waits
     /// until then.
     pub async fn edit_cfg(&self) -> CfgEdit<'_> {
-        let held = self.cfg_write.lock().await;
+        // A step of its own: waiting here is waiting on another change to the catalogue.
+        let held = tracing::Instrument::instrument(self.cfg_write.lock(), db::step("cfg_lock")).await;
         CfgEdit { cfg: (*self.cfg()).clone(), _held: held }
     }
 
     /// Keeps a changed catalogue or server settings: in the database, and for everything running
     /// here from now on. What config.toml's save and reload did, before the database held them.
     pub async fn store_cfg(&self, edit: CfgEdit<'_>) -> Result<()> {
-        self.db.store_config(&edit.cfg).await?;
+        tracing::Instrument::instrument(self.db.store_config(&edit.cfg), db::step("store_config")).await?;
         self.set_cfg(edit.cfg);
         Ok(())
     }
@@ -568,9 +569,12 @@ async fn reload(ctx: &Ctx) -> Result<()> {
 /// The counts `ipx status` prints, and /api/status serves. A running daemon's socket answers with
 /// this directly rather than through the job queue.
 pub(crate) async fn status(ctx: &Ctx) -> Event {
-    match ctx.db.counts().await {
+    match tracing::Instrument::instrument(ctx.db.counts(), db::step("counts")).await {
         Ok((pending, downloaded)) => {
-            let feeds = subscriptions(ctx).await.map(|s| s.len()).unwrap_or(0);
+            let feeds = tracing::Instrument::instrument(subscriptions(ctx), db::step("subscriptions"))
+                .await
+                .map(|s| s.len())
+                .unwrap_or(0);
             // Kept for /metrics, which asks the database nothing (#195); the daemon counts every 30 s.
             use std::sync::atomic::Ordering::Relaxed;
             let st = &metrics::STATS;
@@ -1413,15 +1417,19 @@ pub async fn subscriptions(ctx: &Ctx) -> Result<Vec<Sub>> {
 /// Takes a feed off one person's list, and the feeds in it if it is a group. Everyone else's
 /// lists are left alone.
 pub async fn leave(ctx: &Ctx, user_id: i64, id: &str) -> Result<()> {
-    ctx.db.unsubscribe(user_id, id).await?;
+    use tracing::Instrument;
+    ctx.db.unsubscribe(user_id, id).instrument(db::step("unsubscribe")).await?;
     // What they kept stays on their list, a feed of its own once nobody reads the list (#280).
-    let kept = ctx.db.kept_feeds(user_id).await?;
+    let kept = ctx.db.kept_feeds(user_id).instrument(db::step("kept")).await?;
-    for child in
+    for child in subscriptions(ctx)
-        subscriptions(ctx).await?.iter().filter(|s| s.cfg.group.as_deref() == Some(id) && !kept.contains(&s.id))
+        .instrument(db::step("subscriptions"))
+        .await?
+        .iter()
+        .filter(|s| s.cfg.group.as_deref() == Some(id) && !kept.contains(&s.id))
     {
-        ctx.db.unsubscribe(user_id, &child.id).await?;
+        ctx.db.unsubscribe(user_id, &child.id).instrument(db::step("unsubscribe")).await?;
     }
-    if ctx.db.subscriber_counts().await?.contains_key(id) {
+    if ctx.db.subscriber_counts().instrument(db::step("subscriber_counts")).await?.contains_key(id) {
         return Ok(());
     }
 

crates/ipx/src/web.rs

@@ -1717,22 +1717,22 @@ async fn patch_feed(
 ) -> Result<StatusCode, ApiError> {
     // Pinning is yours alone too, and means nothing for a feed you do not subscribe to.
     if let Some(on) = body.pinned
-        && !state.ctx.db.set_pinned(user.id, &id, on).await?
+        && !state.ctx.db.set_pinned(user.id, &id, on).instrument(step("set_pinned")).await?
     {
         return Err(ApiError::not_found("you do not subscribe to that feed"));
     }
     if let Some(on) = body.kept
-        && !state.ctx.db.set_kept(user.id, &id, on).await?
+        && !state.ctx.db.set_kept(user.id, &id, on).instrument(step("set_kept")).await?
     {
         return Err(ApiError::not_found("you do not subscribe to that feed"));
     }
     if let Some(on) = body.hide_from_all
-        && !state.ctx.db.set_hide_from_all(user.id, &id, on).await?
+        && !state.ctx.db.set_hide_from_all(user.id, &id, on).instrument(step("set_hide_from_all")).await?
     {
         return Err(ApiError::not_found("you do not subscribe to that feed"));
     }
     if let Some(on) = body.hide_from_signals
-        && !state.ctx.db.set_hide_from_signals(user.id, &id, on).await?
+        && !state.ctx.db.set_hide_from_signals(user.id, &id, on).instrument(step("set_hide_from_signals")).await?
     {
         return Err(ApiError::not_found("you do not subscribe to that feed"));
     }
@@ -1742,15 +1742,15 @@ async fn patch_feed(
         return Err(ApiError::bad_request("DeadAir's pause is 200, 300, 400 or 500 ms"));
     }
     if let Some(wanted) = body.deadair {
-        state.ctx.db.set_deadair(user.id, &id, wanted).await?;
+        state.ctx.db.set_deadair(user.id, &id, wanted).instrument(step("set_deadair")).await?;
         state.ctx.deadair.notify_one();
     }
     if let Some(p) = body.deadair_pause {
-        state.ctx.db.set_deadair_pause(user.id, &id, p).await?;
+        state.ctx.db.set_deadair_pause(user.id, &id, p).instrument(step("set_deadair_pause")).await?;
     }
     // What one person wants -- which items, whether to fetch them, how many at a time --
     // is theirs. It goes on their subscription and nobody else sees the change.
-    if let Some(mut mine) = state.ctx.db.subscription(user.id, &id).await? {
+    if let Some(mut mine) = state.ctx.db.subscription(user.id, &id).instrument(step("subscription")).await? {
         let mut touched = false;
         if let Some(v) = body.keywords.clone() {
             mine.keywords = Some(v.into_iter().filter(|k| !k.trim().is_empty()).collect());
@@ -1769,10 +1769,10 @@ async fn patch_feed(
             touched = true;
         }
         if touched {
-            state.ctx.db.set_subscription(user.id, &mine).await?;
+            state.ctx.db.set_subscription(user.id, &mine).instrument(step("set_subscription")).await?;
         }
         if let Some(v) = body.blocked.clone() {
-            state.ctx.db.set_blocklist(user.id, &id, &clean_words(v)?).await?;
+            state.ctx.db.set_blocklist(user.id, &id, &clean_words(v)?).instrument(step("set_blocklist")).await?;
         }
     }
 
@@ -1796,7 +1796,7 @@ async fn patch_feed(
     // Derived feeds have no config entry. Editing one is the moment it earns a real
     // entry: promote it, so the config holds your decisions and nothing else.
     if !cfg.feeds.contains_key(&id) {
-        let subs = crate::subscriptions(&state.ctx).await?;
+        let subs = crate::subscriptions(&state.ctx).instrument(step("subscriptions")).await?;
         let found =
             subs.iter().find(|s| s.id == id).ok_or_else(|| ApiError::bad_request(format!("no feed with id {id:?}")))?;
         cfg.feeds.insert(id.clone(), found.cfg.clone());
@@ -1840,7 +1840,7 @@ async fn patch_feed(
     if url_changed {
         // Refreshing a rotated auth token is the common case; entries and download history
         // are keyed by feed id, so they survive the change.
-        state.ctx.db.clear_validators(&id).await?;
+        state.ctx.db.clear_validators(&id).instrument(step("clear_validators")).await?;
     }
     Ok(StatusCode::NO_CONTENT)
 }
@@ -2161,13 +2161,15 @@ async fn art(State(state): State<WebState>, Query(q): Query<ArtQuery>) -> Respon
     // Kept only once it was let through below, so a kept image needs no asking again (#272).
     let keep = state.ctx.cfg().general.art_cache_mb > 0;
     let file = crate::art::path(&q.u);
-    if keep && let Some((kind, body)) = crate::art::read(&file) {
+    if keep && let Some((kind, body)) = step("art_cached").in_scope(|| crate::art::read(&file)) {
         crate::metrics::STATS.art_hits.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
         return art_response(kind, body);
     }
     // Only what a feed here or the directory names: anything else would make ipx fetch any
     // address it is given. The Directory shows podcasts nobody here subscribes to (#273).
-    if !crate::directory::listed_art(&q.u) && !state.ctx.db.names_image(&q.u).await.unwrap_or(false) {
+    if !crate::directory::listed_art(&q.u)
+        && !state.ctx.db.names_image(&q.u).instrument(step("names_image")).await.unwrap_or(false)
+    {
         return (StatusCode::NOT_FOUND, "no feed names that artwork").into_response();
     }
     if let Some(why) = crate::art::failed(&q.u) {
@@ -2186,9 +2188,9 @@ async fn art(State(state): State<WebState>, Query(q): Query<ArtQuery>) -> Respon
         let kind = image_kind(&said, &body).ok_or_else(|| anyhow::anyhow!("not an image: {said}"))?;
         anyhow::Ok((kind, body))
     };
-    match got.await {
+    match got.instrument(step("art_fetch")).await {
         Ok((kind, body)) => {
-            if keep && let Err(e) = crate::art::write(&file, &kind, &body) {
+            if keep && let Err(e) = step("art_keep").in_scope(|| crate::art::write(&file, &kind, &body)) {
                 tracing::debug!(error = %e, "could not keep the artwork");
             }
             art_response(kind, body)