feat: logs for debug prune cost

This commit is contained in:
evenyag
2024-11-07 22:10:35 +08:00
parent 8536a1ec6e
commit f11c5acb0f
5 changed files with 96 additions and 10 deletions

View File

@@ -62,6 +62,8 @@ impl IndexApplier for PredicatesIndexApplier {
break;
}
common_telemetry::info!("Predicate apply, apply name start, name: {}", name);
let Some(meta) = metadata.metas.get(name) else {
match context.index_not_found_strategy {
IndexNotFoundStrategy::ReturnEmpty => {
@@ -85,6 +87,8 @@ impl IndexApplier for PredicatesIndexApplier {
let bm = mapper.map_values(&values).await?;
bitmap &= bm;
common_telemetry::info!("Predicate apply, apply name end, name: {}", name);
}
output.matched_segment_ids = bitmap;

View File

@@ -87,7 +87,16 @@ impl<R: InvertedIndexReader> InvertedIndexReader for CachedInvertedIndexBlobRead
&mut self,
dest: &mut Vec<u8>,
) -> index::inverted_index::error::Result<usize> {
self.inner.read_all(dest).await
common_telemetry::debug!(
"Inverted index reader read_all start, file_id: {}",
self.file_id,
);
let res = self.inner.read_all(dest).await;
common_telemetry::debug!(
"Inverted index reader read_all end, file_id: {}",
self.file_id,
);
res
}
async fn seek_read(
@@ -95,7 +104,20 @@ impl<R: InvertedIndexReader> InvertedIndexReader for CachedInvertedIndexBlobRead
offset: u64,
size: u32,
) -> index::inverted_index::error::Result<Vec<u8>> {
self.inner.seek_read(offset, size).await
common_telemetry::debug!(
"Inverted index reader seek_read start, file_id: {}, offset: {}, size: {}",
self.file_id,
offset,
size,
);
let res = self.inner.seek_read(offset, size).await;
common_telemetry::debug!(
"Inverted index reader seek_read end, file_id: {}, offset: {}, size: {}",
self.file_id,
offset,
size,
);
res
}
async fn metadata(&mut self) -> index::inverted_index::error::Result<Arc<InvertedIndexMetas>> {
@@ -103,8 +125,16 @@ impl<R: InvertedIndexReader> InvertedIndexReader for CachedInvertedIndexBlobRead
CACHE_HIT.with_label_values(&[INDEX_METADATA_TYPE]).inc();
Ok(cached)
} else {
common_telemetry::debug!(
"Inverted index reader get metadata start, file_id: {}",
self.file_id,
);
let meta = self.inner.metadata().await?;
self.cache.put_index_metadata(self.file_id, meta.clone());
common_telemetry::debug!(
"Inverted index reader get metadata end, file_id: {}",
self.file_id,
);
CACHE_MISS.with_label_values(&[INDEX_METADATA_TYPE]).inc();
Ok(meta)
}
@@ -115,9 +145,23 @@ impl<R: InvertedIndexReader> InvertedIndexReader for CachedInvertedIndexBlobRead
offset: u64,
size: u32,
) -> index::inverted_index::error::Result<FstMap> {
self.get_or_load(offset, size)
common_telemetry::debug!(
"Inverted index reader fst start, file_id: {}, offset: {}, size: {}",
self.file_id,
offset,
size,
);
let res = self
.get_or_load(offset, size)
.await
.and_then(|r| FstMap::new(r).context(DecodeFstSnafu))
.and_then(|r| FstMap::new(r).context(DecodeFstSnafu));
common_telemetry::debug!(
"Inverted index reader fst end, file_id: {}, offset: {}, size: {}",
self.file_id,
offset,
size,
);
res
}
async fn bitmap(
@@ -125,7 +169,20 @@ impl<R: InvertedIndexReader> InvertedIndexReader for CachedInvertedIndexBlobRead
offset: u64,
size: u32,
) -> index::inverted_index::error::Result<BitVec> {
self.get_or_load(offset, size).await.map(BitVec::from_vec)
common_telemetry::debug!(
"Inverted index reader bitmap start, file_id: {}, offset: {}, size: {}",
self.file_id,
offset,
size,
);
let res = self.get_or_load(offset, size).await.map(BitVec::from_vec);
common_telemetry::debug!(
"Inverted index reader bitmap end, file_id: {}, offset: {}, size: {}",
self.file_id,
offset,
size,
);
res
}
}

View File

@@ -662,14 +662,16 @@ impl ScanInput {
/// Prunes a file to scan and returns the builder to build readers.
async fn prune_file(
&self,
row_group_index: RowGroupIndex,
file_index: usize,
reader_metrics: &mut ReaderMetrics,
) -> Result<FileRangeBuilder> {
let file = &self.files[file_index];
common_telemetry::info!(
"ScanInput prune file start, region_id: {}, file: {}",
"ScanInput prune file start, region_id: {}, file: {}, row_group_index: {:?}",
file.region_id(),
file.file_id()
file.file_id(),
row_group_index,
);
let res = self
.access_layer
@@ -707,10 +709,11 @@ impl ScanInput {
file_range_ctx.set_compat_batch(Some(compat));
}
common_telemetry::info!(
"ScanInput prune file end, region_id: {}, file: {}, row_groups_num: {}",
"ScanInput prune file end, region_id: {}, file: {}, row_groups_num: {}, row_group_index: {:?}",
file.region_id(),
file.file_id(),
row_groups.len()
row_groups.len(),
row_group_index,
);
Ok(FileRangeBuilder {
context: Some(Arc::new(file_range_ctx)),
@@ -915,7 +918,7 @@ impl RangeBuilderList {
match &mut *builder_opt {
Some(builder) => builder.build_ranges(index.row_group_index, ranges),
None => {
let builder = input.prune_file(file_index, reader_metrics).await?;
let builder = input.prune_file(index, file_index, reader_metrics).await?;
builder.build_ranges(index.row_group_index, ranges);
*builder_opt = Some(builder);
}

View File

@@ -106,6 +106,10 @@ impl InvertedIndexApplier {
if let Err(err) = other {
warn!(err; "An unexpected error occurred while reading the cached index file. Fallback to remote index file.")
}
common_telemetry::debug!(
"Inverted applier get from remote blob reader, file_id: {}",
file_id,
);
self.remote_blob_reader(file_id).await?
}
};

View File

@@ -193,6 +193,12 @@ impl ParquetReaderBuilder {
let file_size = self.file_handle.meta_ref().file_size;
// Loads parquet metadata of the file.
let parquet_meta = self.read_parquet_metadata(&file_path, file_size).await?;
common_telemetry::debug!(
"Parquet read metadata done, region_id: {}, file_id: {}, elapsed: {:?}",
self.file_handle.region_id(),
self.file_handle.file_id(),
start.elapsed(),
);
// Decodes region metadata.
let key_value_meta = parquet_meta.file_metadata().key_value_metadata();
// Gets the metadata stored in the SST.
@@ -476,6 +482,12 @@ impl ParquetReaderBuilder {
return false;
}
common_telemetry::debug!(
"Parquet prune by inverted index start, region_id: {}, file_id: {}",
self.file_handle.region_id(),
self.file_handle.file_id(),
);
let apply_output = match index_applier.apply(self.file_handle.file_id()).await {
Ok(output) => output,
Err(err) => {
@@ -497,6 +509,12 @@ impl ParquetReaderBuilder {
}
};
common_telemetry::debug!(
"Parquet prune by inverted index stop, region_id: {}, file_id: {}",
self.file_handle.region_id(),
self.file_handle.file_id(),
);
let segment_row_count = apply_output.segment_row_count;
let grouped_in_row_groups = apply_output
.matched_segment_ids