simple-web-app

commit 5017be83a04bca5a146a3d5ddf4640661748e1f7
parent de9c24459a1e2f9d348f3bb56270473444b27f52
Author: Silas Brack <silasbrack@gmail.com>
Date:   Thu, 11 Jun 2026 19:43:37 +0200

perf: add timing instrumentation to story and feed handlers

Logs per-call timing breakdown for each TrailBase API call to
identify performance bottlenecks.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Diffstat:
M
src/handlers/feed.rs
 | 
17
+++++++++++++++++
M
src/handlers/story.rs
 | 
24
+++++++++++++++++++++++-

2 files changed, 40 insertions(+), 1 deletion(-)
diff --git a/src/handlers/feed.rs b/src/handlers/feed.rs
@@ -41,6 +41,7 @@ async fn fetch_feed(
     query: &FeedQuery,
     sort: FeedSort,
 ) -> Result<(Vec<StoryWithMeta>, Vec<Category>, bool), AppError> {
+    let request_start = std::time::Instant::now();
     let offset = query.page * PAGE_LIMIT;
 
     // Create client (with auth if available)
@@ -51,9 +52,12 @@ async fn fetch_feed(
     };
 
     // Fetch categories/tags
+    let t = std::time::Instant::now();
     let categories = trailbase::get_categories(&client, 20).await?;
+    let categories_ms = t.elapsed().as_millis();
 
     // Fetch stories based on sort and optional tag filter
+    let t = std::time::Instant::now();
     let stories = match query.tag {
         Some(tag_id) => {
             trailbase::get_stories_by_tag(&state.http_client, &state.trailbase_url, &client, tag_id, PAGE_LIMIT + 1, offset).await?
@@ -71,6 +75,8 @@ async fn fetch_feed(
         },
     };
 
+    let stories_ms = t.elapsed().as_millis();
+
     let reached_end = stories.len() <= PAGE_LIMIT;
     let stories: Vec<_> = stories.into_iter().take(PAGE_LIMIT).collect();
 
@@ -78,6 +84,7 @@ async fn fetch_feed(
     let story_ids: Vec<i64> = stories.iter().map(|s| s.id).collect();
 
     // Check which stories the user has voted on
+    let t = std::time::Instant::now();
     let voted_ids = if tokens.is_some() {
         trailbase::get_user_votes(&client, TARGET_TYPE_STORY, &story_ids)
             .await
@@ -86,12 +93,15 @@ async fn fetch_feed(
     } else {
         vec![]
     };
+    let votes_ms = t.elapsed().as_millis();
 
     // Batch fetch tags and authors in 2 SQL queries instead of N+1
+    let t = std::time::Instant::now();
     let meta = trailbase::enrich_stories(&state.http_client, &state.trailbase_url, &story_ids)
         .await
         .inspect_err(|e| tracing::error!("Failed to enrich stories: {}", e))
         .unwrap_or_default();
+    let enrich_ms = t.elapsed().as_millis();
 
     let mut enriched_stories = Vec::with_capacity(stories.len());
     let base_rank = query.page * PAGE_LIMIT;
@@ -117,6 +127,13 @@ async fn fetch_feed(
         ));
     }
 
+    tracing::info!(
+        "fetch_feed sort={:?} total={}ms categories={}ms stories={}ms votes={}ms enrich={}ms",
+        sort,
+        request_start.elapsed().as_millis(),
+        categories_ms, stories_ms, votes_ms, enrich_ms
+    );
+
     Ok((enriched_stories, categories, reached_end))
 }
 
diff --git a/src/handlers/story.rs b/src/handlers/story.rs
@@ -76,6 +76,7 @@ pub async fn show_story(
     jar: CookieJar,
     Path(id): Path<i64>,
 ) -> Result<Html<String>, AppError> {
+    let request_start = std::time::Instant::now();
     let tokens = get_tokens_from_cookies(&jar);
     let client = match &tokens {
         Some(t) => trailbase::client_with_tokens(&state.trailbase_url, t)?,
@@ -83,16 +84,21 @@ pub async fn show_story(
     };
 
     // Fetch the story
+    let t = std::time::Instant::now();
     let story = trailbase::get_story(&client, id)
         .await?
         .ok_or_else(|| AppError::NotFound("Story not found".to_string()))?;
+    let get_story_ms = t.elapsed().as_millis();
 
     // Get tags for the story
+    let t = std::time::Instant::now();
     let tags = trailbase::get_categories_for_story(&client, id)
         .await
         .inspect_err(|e| tracing::error!("Failed to get tags for story {}: {}", id, e))
         .unwrap_or_default();
+    let get_tags_ms = t.elapsed().as_millis();
 
+    let t = std::time::Instant::now();
     let author_username = if let Some(ref created_by) = story.created_by {
         trailbase::get_user_profile_by_id(&client, created_by)
             .await
@@ -103,7 +109,9 @@ pub async fn show_story(
     } else {
         None
     };
+    let get_author_ms = t.elapsed().as_millis();
 
+    let t = std::time::Instant::now();
     let story_voted = if tokens.is_some() {
         trailbase::get_user_votes(&client, TARGET_TYPE_STORY, &[id])
             .await
@@ -113,18 +121,22 @@ pub async fn show_story(
     } else {
         false
     };
+    let get_votes_ms = t.elapsed().as_millis();
 
     // Enrich story
     let time_ago = trailbase::time_ago(&story.published);
     let story_with_meta = StoryWithMeta::from_story(story, tags, author_username, time_ago, story_voted, 0);
 
+    let t = std::time::Instant::now();
     let enriched_comments = fetch_enriched_comments(&state, &tokens, &client, id).await?;
+    let get_comments_ms = t.elapsed().as_millis();
 
     let is_logged_in = tokens.is_some();
     let current_user_id = tokens
         .as_ref()
         .and_then(|t| trailbase::extract_user_id_from_token(&t.auth_token));
 
+    let t = std::time::Instant::now();
     let story_template = StoryTemplate {
         story: story_with_meta,
         comments: enriched_comments,
@@ -135,7 +147,17 @@ pub async fn show_story(
     let app = ApplicationTemplate {
         content: story_template.render()?,
     };
-    Ok(Html(app.render()?))
+    let html = app.render()?;
+    let render_ms = t.elapsed().as_millis();
+
+    tracing::info!(
+        "show_story id={} total={}ms story={}ms tags={}ms author={}ms votes={}ms comments={}ms render={}ms",
+        id,
+        request_start.elapsed().as_millis(),
+        get_story_ms, get_tags_ms, get_author_ms, get_votes_ms, get_comments_ms, render_ms
+    );
+
+    Ok(Html(html))
 }
 
 pub async fn show_submit(