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 <noreply@anthropic.com>
This commit is contained in:
@@ -22,6 +22,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
|
|||||||
|
|
||||||
### Added
|
### 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).
|
- 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
|
## [1.2.0] - 2026-10-15
|
||||||
|
|||||||
@@ -55,6 +55,9 @@ pub fn configured(cfg: &config::Config) -> bool {
|
|||||||
target(cfg).is_some()
|
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<T: DeserializeOwned>(ctx: &Ctx, method: reqwest::Method, path: &str, body: Option<&[SnapshotEntry]>) -> Result<T, DirError> {
|
async fn call<T: DeserializeOwned>(ctx: &Ctx, method: reqwest::Method, path: &str, body: Option<&[SnapshotEntry]>) -> Result<T, DirError> {
|
||||||
let (base, token) = target(&ctx.cfg()).ok_or(DirError::NotConfigured)?;
|
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));
|
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<T: DeserializeOwned>(ctx: &Ctx, method: reqwest::Method, path: &st
|
|||||||
}
|
}
|
||||||
// A removal or an unblock answers 204, with nothing to read: that reads as null, which is ().
|
// 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:#}")))?;
|
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:#}")))
|
serde_json::from_slice(if body.is_empty() { b"null" } else { &body }).map_err(|e| DirError::Unreachable(format!("its answer did not read: {e:#}")))
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -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
|
/// 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.
|
/// address, since the directory and this server name a feed differently.
|
||||||
async fn rows_for(state: &WebState, user_id: i64, listed: Vec<ipx_directory::Listing>) -> Result<Vec<PopularRow>> {
|
async fn rows_for(state: &WebState, user_id: i64, listed: Vec<ipx_directory::Listing>) -> Result<Vec<PopularRow>> {
|
||||||
|
// A step each, as the feed list has: a Directory page of 983 ms showed 19 under spans (#250).
|
||||||
let mine: std::collections::HashSet<String> =
|
let mine: std::collections::HashSet<String> =
|
||||||
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<String, String> = crate::subscriptions(&state.ctx)
|
let here: std::collections::HashMap<String, String> = crate::subscriptions(&state.ctx)
|
||||||
|
.instrument(step("catalogue"))
|
||||||
.await?
|
.await?
|
||||||
.into_iter()
|
.into_iter()
|
||||||
.filter(|s| mine.contains(&s.id))
|
.filter(|s| mine.contains(&s.id))
|
||||||
.filter_map(|s| ipx_directory::store::normalise(&s.cfg.url).map(|u| (u, s.id)))
|
.filter_map(|s| ipx_directory::store::normalise(&s.cfg.url).map(|u| (u, s.id)))
|
||||||
.collect();
|
.collect();
|
||||||
|
let _matching = step("match").entered();
|
||||||
Ok(listed
|
Ok(listed
|
||||||
.into_iter()
|
.into_iter()
|
||||||
.map(|l| {
|
.map(|l| {
|
||||||
|
|||||||
Reference in New Issue
Block a user