diff --git a/src/index/src/inverted_index/search/index_apply/predicates_apply.rs b/src/index/src/inverted_index/search/index_apply/predicates_apply.rs index bead0761d7..6173d5ec46 100644 --- a/src/index/src/inverted_index/search/index_apply/predicates_apply.rs +++ b/src/index/src/inverted_index/search/index_apply/predicates_apply.rs @@ -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; diff --git a/src/mito2/src/cache/index.rs b/src/mito2/src/cache/index.rs index 4e6e4deee2..2c42f163bf 100644 --- a/src/mito2/src/cache/index.rs +++ b/src/mito2/src/cache/index.rs @@ -87,7 +87,16 @@ impl InvertedIndexReader for CachedInvertedIndexBlobRead &mut self, dest: &mut Vec, ) -> index::inverted_index::error::Result { - 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 InvertedIndexReader for CachedInvertedIndexBlobRead offset: u64, size: u32, ) -> index::inverted_index::error::Result> { - 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> { @@ -103,8 +125,16 @@ impl 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 InvertedIndexReader for CachedInvertedIndexBlobRead offset: u64, size: u32, ) -> index::inverted_index::error::Result { - 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 InvertedIndexReader for CachedInvertedIndexBlobRead offset: u64, size: u32, ) -> index::inverted_index::error::Result { - 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 } } diff --git a/src/mito2/src/read/scan_region.rs b/src/mito2/src/read/scan_region.rs index 73e6510fb9..212b770fef 100644 --- a/src/mito2/src/read/scan_region.rs +++ b/src/mito2/src/read/scan_region.rs @@ -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 { 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); } diff --git a/src/mito2/src/sst/index/inverted_index/applier.rs b/src/mito2/src/sst/index/inverted_index/applier.rs index a3482cc075..a942e62ec7 100644 --- a/src/mito2/src/sst/index/inverted_index/applier.rs +++ b/src/mito2/src/sst/index/inverted_index/applier.rs @@ -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? } }; diff --git a/src/mito2/src/sst/parquet/reader.rs b/src/mito2/src/sst/parquet/reader.rs index b73026a7a6..11bface583 100644 --- a/src/mito2/src/sst/parquet/reader.rs +++ b/src/mito2/src/sst/parquet/reader.rs @@ -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