From bb2215ef0c8032a1dde6d710a9600bbbd1b8821f Mon Sep 17 00:00:00 2001 From: Vlad Lazar Date: Tue, 23 Apr 2024 10:24:49 +0100 Subject: [PATCH] wip: even more stats --- pageserver/src/context.rs | 38 +++++++++++++++++++++++++- pageserver/src/tenant/timeline.rs | 44 +++++++++++++++++++++++++++++++ 2 files changed, 81 insertions(+), 1 deletion(-) diff --git a/pageserver/src/context.rs b/pageserver/src/context.rs index 0751563364..dffa9d6d87 100644 --- a/pageserver/src/context.rs +++ b/pageserver/src/context.rs @@ -119,6 +119,9 @@ pub struct ReadPathStatsInner { pub sort_reconstruct_data_time: AtomicU32, pub layer_search_time: AtomicU32, pub keyspace_manipulation_time: AtomicU32, + pub in_mem_layer_find_time: AtomicU32, + pub fringe_fondle_time: AtomicU32, + pub layer_map_search_time: AtomicU32, pub buffer_cache_hits: AtomicU32, pub layers_visited: AtomicU32, } @@ -127,7 +130,7 @@ impl std::fmt::Display for ReadPathStatsInner { fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { write!( f, - "get_reconstruct_data_time={} plan_read_time={} read_time={} sort_time={} layer_search_time={} keyspace_manipulation_time={} buffer_cache_hits={} layers_visited={}", + "get_reconstruct_data_time={} plan_read_time={} read_time={} sort_time={} layer_search_time={} keyspace_manipulation_time={} in_mem_layer_find_time={} fringe_fondle_time={} layer_map_search_time={} buffer_cache_hits={} layers_visited={}", self.get_reconstruct_data_time.load(std::sync::atomic::Ordering::Relaxed), self.plan_read_time .load(std::sync::atomic::Ordering::Relaxed), @@ -138,6 +141,12 @@ impl std::fmt::Display for ReadPathStatsInner { .load(std::sync::atomic::Ordering::Relaxed), self.keyspace_manipulation_time .load(std::sync::atomic::Ordering::Relaxed), + self.in_mem_layer_find_time + .load(std::sync::atomic::Ordering::Relaxed), + self.fringe_fondle_time + .load(std::sync::atomic::Ordering::Relaxed), + self.layer_search_time + .load(std::sync::atomic::Ordering::Relaxed), self.buffer_cache_hits .load(std::sync::atomic::Ordering::Relaxed), self.layers_visited @@ -160,6 +169,12 @@ impl ReadPathStatsInner { .store(0, std::sync::atomic::Ordering::Relaxed); self.keyspace_manipulation_time .store(0, std::sync::atomic::Ordering::Relaxed); + self.in_mem_layer_find_time + .store(0, std::sync::atomic::Ordering::Relaxed); + self.fringe_fondle_time + .store(0, std::sync::atomic::Ordering::Relaxed); + self.layer_search_time + .store(0, std::sync::atomic::Ordering::Relaxed); self.buffer_cache_hits .store(0, std::sync::atomic::Ordering::Relaxed); self.layers_visited @@ -208,6 +223,27 @@ impl ReadPathStatsInner { ); } + pub fn add_in_mem_layer_find_timer(&self, dur: Duration) { + self.in_mem_layer_find_time.fetch_add( + dur.as_micros().try_into().unwrap(), + std::sync::atomic::Ordering::Relaxed, + ); + } + + pub fn add_fringe_fondle_time(&self, dur: Duration) { + self.fringe_fondle_time.fetch_add( + dur.as_micros().try_into().unwrap(), + std::sync::atomic::Ordering::Relaxed, + ); + } + + pub fn add_layer_map_search_time(&self, dur: Duration) { + self.layer_map_search_time.fetch_add( + dur.as_micros().try_into().unwrap(), + std::sync::atomic::Ordering::Relaxed, + ); + } + pub fn inc_layer_visited(&self) { self.layers_visited .fetch_add(1, std::sync::atomic::Ordering::Relaxed); diff --git a/pageserver/src/tenant/timeline.rs b/pageserver/src/tenant/timeline.rs index 4c9edc679f..c35bb59cb5 100644 --- a/pageserver/src/tenant/timeline.rs +++ b/pageserver/src/tenant/timeline.rs @@ -2969,6 +2969,7 @@ impl Timeline { // Check the open and frozen in-memory layers first, in order from newest // to oldest. + let in_mem_layer_find_timer = Instant::now(); if let Some(open_layer) = &layers.open_layer { let start_lsn = open_layer.get_lsn_range().start; if cont_lsn > start_lsn { @@ -2980,6 +2981,10 @@ impl Timeline { let open_layer = open_layer.clone(); drop(guard); + ctx.read_path_stats + .inner + .add_in_mem_layer_find_timer(in_mem_layer_find_timer.elapsed()); + result = match open_layer .get_value_reconstruct_data( key, @@ -3011,6 +3016,10 @@ impl Timeline { let frozen_layer = frozen_layer.clone(); drop(guard); + ctx.read_path_stats + .inner + .add_in_mem_layer_find_timer(in_mem_layer_find_timer.elapsed()); + result = match frozen_layer .get_value_reconstruct_data( key, @@ -3034,7 +3043,12 @@ impl Timeline { } } + let layer_map_search_timer = Instant::now(); if let Some(SearchResult { lsn_floor, layer }) = layers.search(key, cont_lsn) { + ctx.read_path_stats + .inner + .add_layer_map_search_time(layer_map_search_timer.elapsed()); + let layer = guard.get_from_desc(&layer); drop(guard); @@ -3060,11 +3074,19 @@ impl Timeline { )); continue 'outer; } else if timeline.ancestor_timeline.is_some() { + ctx.read_path_stats + .inner + .add_layer_map_search_time(layer_map_search_timer.elapsed()); + // Nothing on this timeline. Traverse to parent result = ValueReconstructResult::Continue; cont_lsn = Lsn(timeline.ancestor_lsn.0 + 1); continue 'outer; } else { + ctx.read_path_stats + .inner + .add_layer_map_search_time(layer_map_search_timer.elapsed()); + // Nothing found result = ValueReconstructResult::Missing; continue 'outer; @@ -3200,22 +3222,34 @@ impl Timeline { let guard = timeline.layers.read().await; let layers = guard.layer_map(); + let in_mem_layer_find_timer = Instant::now(); let in_memory_layer = layers.find_in_memory_layer(|l| { let start_lsn = l.get_lsn_range().start; cont_lsn > start_lsn }); + ctx.read_path_stats + .inner + .add_in_mem_layer_find_timer(in_mem_layer_find_timer.elapsed()); match in_memory_layer { Some(l) => { let lsn_range = l.get_lsn_range().start..cont_lsn; + + let fringe_fondle_timer = Instant::now(); + fringe.update( ReadableLayer::InMemoryLayer(l), unmapped_keyspace.clone(), lsn_range, ); + ctx.read_path_stats + .inner + .add_fringe_fondle_time(fringe_fondle_timer.elapsed()); } None => { for range in unmapped_keyspace.ranges.iter() { + let layer_map_search_timer = Instant::now(); + let results = layers.range_search(range.clone(), cont_lsn); tracing::info!( "Range search at {} found {:?}", @@ -3223,6 +3257,12 @@ impl Timeline { results.found ); + ctx.read_path_stats + .inner + .add_layer_map_search_time(layer_map_search_timer.elapsed()); + + let fringe_fondle_timer = Instant::now(); + results .found .into_iter() @@ -3236,6 +3276,10 @@ impl Timeline { .for_each(|(layer, keyspace, lsn_range)| { fringe.update(layer, keyspace, lsn_range) }); + + ctx.read_path_stats + .inner + .add_fringe_fondle_time(fringe_fondle_timer.elapsed()); } } }