Debug-log graph data request timings

src/server/web/pages/graph.rs

@@ -1,6 +1,6 @@
 mod util;
 
-use std::collections::HashMap;
+use std::{collections::HashMap, time::Instant};
 
 use askama::Template;
 use axum::{extract::State, response::IntoResponse, Json};
@@ -9,6 +9,7 @@ use futures::{StreamExt, TryStreamExt};
 use serde::{Deserialize, Serialize};
 use sqlx::{Acquire, SqlitePool};
 use time::OffsetDateTime;
+use tracing::debug;
 
 use crate::{
     config::Config,
@@ -148,6 +149,12 @@ struct GraphData {
     measurements: HashMap<String, Vec<Option<f64>>>,
 }
 
+fn f(t0: &mut Instant, name: &str) {
+    let now = Instant::now();
+    debug!("{name:>20} {}", (now - *t0).as_millis());
+    *t0 = Instant::now();
+}
+
 pub async fn get_graph_data(
     _path: PathGraphData,
     State(db): State<SqlitePool>,
@@ -162,6 +169,9 @@ pub async fn get_graph_data(
     // TODO Limit by date or amount
     // TODO Limit to tracked commits
 
+    let mut t0 = Instant::now();
+    debug!("");
+
     let mut unsorted_hashes = Vec::<String>::new();
     let mut times_by_hash = HashMap::<String, i64>::new();
     let mut rows = sqlx::query!(
@@ -182,6 +192,8 @@ pub async fn get_graph_data(
     }
     drop(rows);
 
+    f(&mut t0, "hashes, times");
+
     let parent_child_pairs = sqlx::query!(
         "\
         SELECT parent, child \
@@ -196,9 +208,13 @@ pub async fn get_graph_data(
     .try_collect::<Vec<_>>()
     .await?;
 
+    f(&mut t0, "parent-child");
+
     let mut hashes = util::sort_topologically(&unsorted_hashes, &parent_child_pairs);
     hashes.sort_by_key(|hash| times_by_hash[hash]);
 
+    f(&mut t0, "sort");
+
     let sorted_hash_indices = hashes
         .iter()
         .cloned()
@@ -206,6 +222,8 @@ pub async fn get_graph_data(
         .map(|(i, hash)| (hash, i))
         .collect::<HashMap<_, _>>();
 
+    f(&mut t0, "hash indices");
+
     let mut parents = HashMap::<usize, Vec<usize>>::new();
     for (parent, child) in &parent_child_pairs {
         if let Some(parent_idx) = sorted_hash_indices.get(parent) {
@@ -215,18 +233,24 @@ pub async fn get_graph_data(
         }
     }
 
+    f(&mut t0, "parents");
+
     // Collect times
     let times = hashes
         .iter()
         .map(|hash| times_by_hash[hash])
         .collect::<Vec<_>>();
 
+    f(&mut t0, "times");
+
     // permutation[unsorted_index] = sorted_index
     let permutation = unsorted_hashes
         .iter()
         .map(|hash| sorted_hash_indices[hash])
         .collect::<Vec<_>>();
 
+    f(&mut t0, "permutation");
+
     // Collect and permutate measurements
     let mut measurements = HashMap::new();
     for metric in form.metric {
@@ -259,6 +283,9 @@ pub async fn get_graph_data(
         measurements.insert(metric, values);
     }
 
+    f(&mut t0, "measurements");
+    debug!("");
+
     Ok(Json(GraphData {
         hashes,
         parents,