diff --git a/parakeet/src/loaders/post.rs b/parakeet/src/loaders/post.rs index fc2a7e85..f34aedb3 100644 --- a/parakeet/src/loaders/post.rs +++ b/parakeet/src/loaders/post.rs @@ -505,12 +505,17 @@ impl BatchFn for PostLoader { // PostWithComputed struct is now defined at module level for reuse in tests let posts_query_start = std::time::Instant::now(); + let query_build_start = std::time::Instant::now(); + let bound_query = diesel::sql_query(query) + .bind::, _>(&actor_ids) + .bind::, _>(&rkeys) + .bind::(min_rkey) + .bind::(max_rkey); + let query_build_time = query_build_start.elapsed().as_secs_f64() * 1000.0; + + let query_exec_start = std::time::Instant::now(); let posts_with_computed: Vec = diesel_async::RunQueryDsl::load( - diesel::sql_query(query) - .bind::, _>(&actor_ids) - .bind::, _>(&rkeys) - .bind::(min_rkey) - .bind::(max_rkey), + bound_query, &mut conn, ) .await @@ -518,15 +523,22 @@ impl BatchFn for PostLoader { tracing::error!("post load failed: {e}"); vec![] }); + let query_exec_time = query_exec_start.elapsed().as_secs_f64() * 1000.0; let posts_query_time = posts_query_start.elapsed().as_secs_f64() * 1000.0; + // Track time between query and post_processing + let pre_processing_start = std::time::Instant::now(); + // Filter out non-complete posts (application-level filtering for better chunk skipping) + let filter_start = std::time::Instant::now(); let posts_with_computed: Vec = posts_with_computed .into_iter() .filter(|p| p.status == parakeet_db::types::PostStatus::Complete) .collect(); + let filter_time = filter_start.elapsed().as_secs_f64() * 1000.0; // Collect all post natural keys that need to be looked up (parent/root/embedded) + let collect_keys_start = std::time::Instant::now(); let mut post_keys_to_lookup: Vec<(i32, i64)> = Vec::new(); for p in &posts_with_computed { if let (Some(parent_actor_id), Some(parent_rkey)) = (p.parent_post_actor_id, p.parent_post_rkey) { @@ -541,6 +553,7 @@ impl BatchFn for PostLoader { } post_keys_to_lookup.sort_unstable(); post_keys_to_lookup.dedup(); + let collect_keys_time = collect_keys_start.elapsed().as_secs_f64() * 1000.0; // Try cache first using natural keys let cache_lookup_start = std::time::Instant::now(); @@ -583,6 +596,7 @@ impl BatchFn for PostLoader { // Batch fetch missing post data from database // Declare actor_did_map outside the block so it's available to the closure below let mut actor_did_map: HashMap = HashMap::new(); + let mut parent_post_fetch_time = 0.0; if !cache_misses.is_empty() { @@ -702,6 +716,7 @@ impl BatchFn for PostLoader { let actors_query_time = actors_query_start.elapsed().as_secs_f64() * 1000.0; let db_fetch_time = db_fetch_start.elapsed().as_secs_f64() * 1000.0; + parent_post_fetch_time = db_fetch_time; // Log query timings when > 1ms if posts_query_time > 1.0 { @@ -771,13 +786,16 @@ impl BatchFn for PostLoader { } // Create lookup map from (actor_id, rkey) to DID + let did_map_start = std::time::Instant::now(); let post_key_to_did: StdHashMap<(i32, i64), String> = posts_with_keys .iter() .map(|(actor_id, rkey, did)| ((*actor_id, *rkey), did.clone())) .collect(); + let did_map_time = did_map_start.elapsed().as_secs_f64() * 1000.0; // Convert to HydratedPost (will reconstruct records after loading facets) // Encode TIDs and CIDs in Rust instead of SQL + let pre_processing_time = pre_processing_start.elapsed().as_secs_f64() * 1000.0; let post_processing_start = std::time::Instant::now(); let posts_with_computed_data: Vec<_> = posts_with_computed .into_iter() @@ -1282,8 +1300,8 @@ impl BatchFn for PostLoader { if overall_time > 15.0 || posts_query_time > 10.0 { tracing::info!( - " → PostLoader: {:.1}ms total ({} posts requested, {} returned) | main_query: {:.1}ms, post_processing: {:.1}ms, facets: {:.1}ms, threadgates: {:.1}ms, record_building: {:.1}ms", - overall_time, key_count, result_count, posts_query_time, post_processing_time, facets_time, threadgates_time, record_building_time + " → PostLoader: {:.1}ms total ({} posts requested, {} returned) | main_query: {:.1}ms (build: {:.1}ms, exec: {:.1}ms), pre_proc: {:.1}ms (filter: {:.1}ms, keys: {:.1}ms, parent: {:.1}ms, did_map: {:.1}ms), post_proc: {:.1}ms, facets: {:.1}ms, threadgates: {:.1}ms, record: {:.1}ms", + overall_time, key_count, result_count, posts_query_time, query_build_time, query_exec_time, pre_processing_time, filter_time, collect_keys_time, parent_post_fetch_time, did_map_time, post_processing_time, facets_time, threadgates_time, record_building_time ); }