wip: even more stats

This commit is contained in:
Vlad Lazar
2024-04-23 10:24:49 +01:00
parent 294a2b2d6f
commit bb2215ef0c
2 changed files with 81 additions and 1 deletions

View File

@@ -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);

View File

@@ -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());
}
}
}