diff --git a/crates/ipx/CHANGELOG.md b/crates/ipx/CHANGELOG.md index bc54f98..5098cba 100644 --- a/crates/ipx/CHANGELOG.md +++ b/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). diff --git a/crates/ipx/src/db.rs b/crates/ipx/src/db.rs index 3a15eff..d95caac 100644 --- a/crates/ipx/src/db.rs +++ b/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 - .rows(&sql, a.0) + let mut rows = tracing::Instrument::instrument(self.rows(&sql, a.0), step("page")) .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() - .filter(enclosures::Column::Guid.is_in(rows.iter().map(|r| r.guid.clone()))) - .order_by_asc(enclosures::Column::Id) - .all(&self.orm) - .await?; + let encs = tracing::Instrument::instrument( + enclosures::Entity::find() + .filter(enclosures::Column::Guid.is_in(rows.iter().map(|r| r.guid.clone()))) + .order_by_asc(enclosures::Column::Id) + .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)); diff --git a/crates/ipx/src/main.rs b/crates/ipx/src/main.rs index 38c1fc2..e7d7979 100644 --- a/crates/ipx/src/main.rs +++ b/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> { /// 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?; - for child in - subscriptions(ctx).await?.iter().filter(|s| s.cfg.group.as_deref() == Some(id) && !kept.contains(&s.id)) + let kept = ctx.db.kept_feeds(user_id).instrument(db::step("kept")).await?; + for child in subscriptions(ctx) + .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(()); } diff --git a/crates/ipx/src/web.rs b/crates/ipx/src/web.rs index dc0dbb8..4302bbe 100644 --- a/crates/ipx/src/web.rs +++ b/crates/ipx/src/web.rs @@ -1717,22 +1717,22 @@ async fn patch_feed( ) -> Result { // 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, Query(q): Query) -> 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, Query(q): Query) -> 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)