Merge pull request #8256 from BohuTANG/dev-more-logs

chore: add more debug log to measure the time cost

src/query/storages/fuse/src/fuse_table.rs

@@ -353,14 +353,14 @@ impl Table for FuseTable {
         self.do_read_partitions(ctx, push_downs).await
     }
 
-    #[tracing::instrument(level = "debug", name = "fuse_table_read2", skip(self, ctx, pipeline), fields(ctx.id = ctx.get_id().as_str()))]
+    #[tracing::instrument(level = "debug", name = "fuse_table_read_data", skip(self, ctx, pipeline), fields(ctx.id = ctx.get_id().as_str()))]
     fn read_data(
         &self,
         ctx: Arc<dyn TableContext>,
         plan: &ReadDataSourcePlan,
         pipeline: &mut Pipeline,
     ) -> Result<()> {
-        self.do_read2(ctx, plan, pipeline)
+        self.do_read_data(ctx, plan, pipeline)
     }
 
     fn append_data(
@@ -370,7 +370,7 @@ impl Table for FuseTable {
         need_output: bool,
     ) -> Result<()> {
         self.check_mutable()?;
-        self.do_append2(ctx, pipeline, need_output)
+        self.do_append_data(ctx, pipeline, need_output)
     }
 
     #[tracing::instrument(level = "debug", name = "fuse_table_commit_insertion", skip(self, ctx, operations), fields(ctx.id = ctx.get_id().as_str()))]

src/query/storages/fuse/src/operations/append.rs

@@ -36,7 +36,7 @@ use crate::DEFAULT_BLOCK_PER_SEGMENT;
 use crate::FUSE_OPT_KEY_BLOCK_PER_SEGMENT;
 
 impl FuseTable {
-    pub fn do_append2(
+    pub fn do_append_data(
         &self,
         ctx: Arc<dyn TableContext>,
         pipeline: &mut Pipeline,

src/query/storages/fuse/src/operations/compact.rs

@@ -90,7 +90,7 @@ impl FuseTable {
         };
 
         ctx.try_set_partitions(plan.parts.clone())?;
-        self.do_read2(ctx.clone(), &plan, pipeline)?;
+        self.do_read_data(ctx.clone(), &plan, pipeline)?;
 
         pipeline.add_transform(|transform_input_port, transform_output_port| {
             TransformCompact::try_create(

src/query/storages/fuse/src/operations/read.rs

@@ -72,7 +72,7 @@ impl FuseTable {
     }
 
     #[inline]
-    pub fn do_read2(
+    pub fn do_read_data(
         &self,
         ctx: Arc<dyn TableContext>,
         plan: &ReadDataSourcePlan,

src/query/storages/fuse/src/operations/read_partitions.rs

@@ -14,6 +14,7 @@
 
 use std::collections::HashMap;
 use std::sync::Arc;
+use std::time::Instant;
 
 use common_catalog::table_context::TableContext;
 use common_datavalues::DataSchemaRef;
@@ -28,6 +29,7 @@ use common_legacy_planners::Projection;
 use common_legacy_planners::Statistics;
 use common_meta_app::schema::TableInfo;
 use opendal::Operator;
+use tracing::debug;
 
 use crate::fuse_lazy_part::FuseLazyPartInfo;
 use crate::fuse_part::ColumnLeaves;
@@ -43,6 +45,8 @@ impl FuseTable {
         ctx: Arc<dyn TableContext>,
         push_downs: Option<Extras>,
     ) -> Result<(Statistics, Partitions)> {
+        debug!("fuse table do read partitions, push downs:{:?}", push_downs);
+
         let snapshot = self.read_table_snapshot(ctx.clone()).await?;
         match snapshot {
             Some(snapshot) => {
@@ -95,6 +99,12 @@ impl FuseTable {
         segments_location: Vec<Location>,
         summary: usize,
     ) -> Result<(Statistics, Partitions)> {
+        let start = Instant::now();
+        debug!(
+            "prune snapshot block start, segment numbers:{}",
+            segments_location.len()
+        );
+
         let block_metas = BlockPruner::prune(
             &ctx,
             dal,
@@ -106,6 +116,13 @@ impl FuseTable {
         .into_iter()
         .map(|(_, v)| v)
         .collect::<Vec<_>>();
+
+        debug!(
+            "prune snapshot block end, final block numbers:{}, cost:{}",
+            block_metas.len(),
+            start.elapsed().as_secs()
+        );
+
         Self::read_partitions_with_metas(ctx, table_info.schema(), push_downs, block_metas, summary)
     }
 

src/query/storages/fuse/src/operations/recluster.rs

@@ -134,7 +134,7 @@ impl FuseTable {
         };
 
         ctx.try_set_partitions(plan.parts.clone())?;
-        self.do_read2(ctx.clone(), &plan, pipeline)?;
+        self.do_read_data(ctx.clone(), &plan, pipeline)?;
 
         let cluster_stats_gen = self.get_cluster_stats_gen(
             ctx.clone(),