chore: adjust elapsed time of various log messages (#15517)

* chore: adjust eplased times of various logs

Adjust the time part in the log to use Duration instead of specific
precision time (e.g., seconds), to avoid imprecise log information such
as '0s'.

* chore: add timing log for some schema api

- update_table_meta
- update_multi_table_meta

Author: dantengsky

src/query/ee/src/storages/fuse/io/snapshots.rs

@@ -78,11 +78,11 @@ where
         {
             count += chunk.len();
             let status = format!(
-                "gc orphan: read snapshot files:{}/{}, segment files: {}, cost:{} sec",
+                "gc orphan: read snapshot files:{}/{}, segment files: {}, cost:{:?}",
                 count,
                 snapshot_files.len(),
                 segments.len(),
-                start.elapsed().as_secs()
+                start.elapsed()
             );
             info!("{}", status);
             (status_callback)(status);

src/query/ee/src/storages/fuse/operations/vacuum_drop_tables.rs

@@ -74,10 +74,10 @@ pub async fn do_vacuum_drop_table(
         };
 
         info!(
-            "vacuum drop table {:?} dir {:?}, cost:{} sec",
+            "vacuum drop table {:?} dir {:?}, cost:{:?}",
             table_info.name,
             dir,
-            start.elapsed().as_secs()
+            start.elapsed()
         );
     }
     Ok(if dry_run_limit.is_some() {
@@ -150,9 +150,9 @@ pub async fn do_vacuum_drop_tables(
     };
 
     info!(
-        "do_vacuum_drop_tables {} tables, cost:{} sec",
+        "do_vacuum_drop_tables {} tables, cost:{:?}",
         tables_len,
-        start.elapsed().as_secs()
+        start.elapsed()
     );
 
     Ok(result)

src/query/ee/src/storages/fuse/operations/vacuum_table.rs

@@ -177,11 +177,11 @@ pub async fn do_gc_orphan_files(
         None => return Ok(()),
     };
     let status = format!(
-        "gc orphan: read referenced files:{},{},{}, cost:{} sec",
+        "gc orphan: read referenced files:{},{},{}, cost:{:?}",
         referenced_files.segments.len(),
         referenced_files.blocks.len(),
         referenced_files.blocks_index.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -191,9 +191,9 @@ pub async fn do_gc_orphan_files(
         get_orphan_files_to_be_purged(fuse_table, referenced_files.segments, retention_time)
             .await?;
     let status = format!(
-        "gc orphan: read segment_locations_to_be_purged:{}, cost:{} sec, retention_time: {}",
+        "gc orphan: read segment_locations_to_be_purged:{}, cost:{:?}, retention_time: {}",
         segment_locations_to_be_purged.len(),
-        start.elapsed().as_secs(),
+        start.elapsed(),
         retention_time
     );
     ctx.set_status_info(&status);
@@ -207,9 +207,9 @@ pub async fn do_gc_orphan_files(
         )
         .await?;
     let status = format!(
-        "gc orphan: purged segment files:{}, cost:{} sec",
+        "gc orphan: purged segment files:{}, cost:{:?}",
         purged_file_num,
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -218,9 +218,9 @@ pub async fn do_gc_orphan_files(
     let block_locations_to_be_purged =
         get_orphan_files_to_be_purged(fuse_table, referenced_files.blocks, retention_time).await?;
     let status = format!(
-        "gc orphan: read block_locations_to_be_purged:{}, cost:{} sec",
+        "gc orphan: read block_locations_to_be_purged:{}, cost:{:?}",
         block_locations_to_be_purged.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -233,9 +233,9 @@ pub async fn do_gc_orphan_files(
         )
         .await?;
     let status = format!(
-        "gc orphan: purged block files:{}, cost:{} sec",
+        "gc orphan: purged block files:{}, cost:{:?}",
         purged_file_num,
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -245,9 +245,9 @@ pub async fn do_gc_orphan_files(
         get_orphan_files_to_be_purged(fuse_table, referenced_files.blocks_index, retention_time)
             .await?;
     let status = format!(
-        "gc orphan: read index_locations_to_be_purged:{}, cost:{} sec",
+        "gc orphan: read index_locations_to_be_purged:{}, cost:{:?}",
         index_locations_to_be_purged.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -260,9 +260,9 @@ pub async fn do_gc_orphan_files(
         )
         .await?;
     let status = format!(
-        "gc orphan: purged block index files:{}, cost:{} sec",
+        "gc orphan: purged block index files:{}, cost:{:?}",
         purged_file_num,
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -284,11 +284,11 @@ pub async fn do_dry_run_orphan_files(
         None => return Ok(()),
     };
     let status = format!(
-        "dry_run orphan: read referenced files:{},{},{}, cost:{} sec",
+        "dry_run orphan: read referenced files:{},{},{}, cost:{:?}",
         referenced_files.segments.len(),
         referenced_files.blocks.len(),
         referenced_files.blocks_index.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -297,9 +297,9 @@ pub async fn do_dry_run_orphan_files(
         get_orphan_files_to_be_purged(fuse_table, referenced_files.segments, retention_time)
             .await?;
     let status = format!(
-        "dry_run orphan: read segment_locations_to_be_purged:{}, cost:{} sec",
+        "dry_run orphan: read segment_locations_to_be_purged:{}, cost:{:?}",
         segment_locations_to_be_purged.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -312,9 +312,9 @@ pub async fn do_dry_run_orphan_files(
     let block_locations_to_be_purged =
         get_orphan_files_to_be_purged(fuse_table, referenced_files.blocks, retention_time).await?;
     let status = format!(
-        "dry_run orphan: read block_locations_to_be_purged:{}, cost:{} sec",
+        "dry_run orphan: read block_locations_to_be_purged:{}, cost:{:?}",
         block_locations_to_be_purged.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
     purge_files.extend(block_locations_to_be_purged);
@@ -327,9 +327,9 @@ pub async fn do_dry_run_orphan_files(
         get_orphan_files_to_be_purged(fuse_table, referenced_files.blocks_index, retention_time)
             .await?;
     let status = format!(
-        "dry_run orphan: read index_locations_to_be_purged:{}, cost:{} sec",
+        "dry_run orphan: read index_locations_to_be_purged:{}, cost:{:?}",
         index_locations_to_be_purged.len(),
-        start.elapsed().as_secs()
+        start.elapsed()
     );
     ctx.set_status_info(&status);
 
@@ -352,10 +352,7 @@ pub async fn do_vacuum(
     let purge_files_opt = fuse_table
         .purge(ctx.clone(), instant, dry_run_limit, true, dry_run)
         .await?;
-    let status = format!(
-        "do_vacuum: purged table, cost:{} sec",
-        start.elapsed().as_secs()
-    );
+    let status = format!("do_vacuum: purged table, cost:{:?}", start.elapsed());
     ctx.set_status_info(&status);
     let retention = Duration::days(ctx.get_settings().get_data_retention_time_in_days()? as i64);
     // use min(now - get_retention_period(), retention_time) as gc orphan files retention time

src/query/service/src/catalogs/default/mutable_catalog.rs

@@ -16,6 +16,7 @@ use std::any::Any;
 use std::fmt::Debug;
 use std::fmt::Formatter;
 use std::sync::Arc;
+use std::time::Instant;
 
 use databend_common_catalog::catalog::Catalog;
 use databend_common_config::InnerConfig;
@@ -511,7 +512,14 @@ impl Catalog for MutableCatalog {
                     table_info.desc,
                     req.copied_files.is_some()
                 );
-                Ok(self.ctx.meta.update_table_meta(req).await?)
+                let begin = Instant::now();
+                let res = self.ctx.meta.update_table_meta(req).await;
+                info!(
+                    "update table meta done. table id: {:?}, time used {:?}",
+                    table_info.ident,
+                    begin.elapsed()
+                );
+                Ok(res?)
             }
             DatabaseType::ShareDB(share_ident) => {
                 let tenant = Tenant::new_or_err(share_ident.tenant_name(), func_name!())?;
@@ -523,7 +531,17 @@ impl Catalog for MutableCatalog {
 
     #[async_backtrace::framed]
     async fn update_multi_table_meta(&self, reqs: UpdateMultiTableMetaReq) -> Result<()> {
-        Ok(self.ctx.meta.update_multi_table_meta(reqs).await?)
+        info!(
+            "updating multi table meta. number of tables: {}",
+            reqs.update_table_metas.len()
+        );
+        let begin = Instant::now();
+        let res = self.ctx.meta.update_multi_table_meta(reqs).await;
+        info!(
+            "update multi table meta done. time used {:?}",
+            begin.elapsed()
+        );
+        Ok(res?)
     }
 
     async fn set_table_column_mask_policy(

src/query/service/src/interpreters/interpreter_table_recluster.rs

@@ -184,9 +184,8 @@ impl Interpreter for ReclusterTableInterpreter {
             // Status.
             {
                 let status = format!(
-                    "recluster: run recluster tasks:{} times, cost:{} sec",
-                    times,
-                    elapsed_time.as_secs()
+                    "recluster: run recluster tasks:{} times, cost:{:?}",
+                    times, elapsed_time
                 );
                 ctx.set_status_info(&status);
             }
@@ -197,8 +196,8 @@ impl Interpreter for ReclusterTableInterpreter {
 
             if elapsed_time >= timeout {
                 warn!(
-                    "Recluster stopped because the runtime was over {} secs",
-                    timeout.as_secs()
+                    "Recluster stopped because the runtime was over {:?}",
+                    timeout
                 );
                 break;
             }

src/query/storages/fuse/src/io/snapshots.rs

@@ -192,10 +192,10 @@ impl SnapshotsIO {
             {
                 count += chunk.len();
                 let status = format!(
-                    "read snapshot files:{}/{}, cost:{} sec",
+                    "read snapshot files:{}/{}, cost:{:?}",
                     count,
                     snapshot_files.len(),
-                    start.elapsed().as_secs()
+                    start.elapsed()
                 );
                 info!("{}", status);
                 (status_callback)(status);

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

@@ -263,10 +263,10 @@ pub async fn regenerate_statistics(
         {
             read_segment_count += chunk.len();
             let status = format!(
-                "analyze: read segment files:{}/{}, cost:{} sec",
+                "analyze: read segment files:{}/{}, cost:{:?}",
                 read_segment_count,
                 number_segments,
-                start.elapsed().as_secs()
+                start.elapsed()
             );
             ctx.set_status_info(&status);
         }

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

@@ -296,9 +296,9 @@ impl FuseTable {
         let pruning_stats = pruner.pruning_stats();
 
         info!(
-            "prune snapshot block end, final block numbers:{}, cost:{}",
+            "prune snapshot block end, final block numbers:{}, cost:{:?}",
             block_metas.len(),
-            start.elapsed().as_secs()
+            start.elapsed()
         );
 
         let block_metas = block_metas

src/query/storages/fuse/src/operations/common/processors/sink_commit.rs

@@ -430,12 +430,12 @@ where F: SnapshotGenerator + Send + 'static
                         }
                         metrics_inc_commit_mutation_success();
                         {
-                            let elapsed_time = self.start_time.elapsed().as_millis();
+                            let elapsed_time = self.start_time.elapsed();
                             let status = format!(
-                                "commit mutation success after {} retries, which took {} ms",
+                                "commit mutation success after {} retries, which took {:?}",
                                 self.retries, elapsed_time
                             );
-                            metrics_inc_commit_milliseconds(elapsed_time);
+                            metrics_inc_commit_milliseconds(elapsed_time.as_millis());
                             self.ctx.set_status_info(&status);
                         }
                         if let Some(files) = &self.copied_files {

src/query/storages/fuse/src/operations/common/processors/transform_mutation_aggregator.rs

@@ -136,10 +136,10 @@ impl TableMutationAggregator {
         // Refresh status
         {
             let status = format!(
-                "{}: run tasks:{}, cost:{} sec",
+                "{}: run tasks:{}, cost:{:?}",
                 self.kind,
                 self.finished_tasks,
-                self.start_time.elapsed().as_secs()
+                self.start_time.elapsed()
             );
             self.ctx.set_status_info(&status);
         }
@@ -262,11 +262,11 @@ impl TableMutationAggregator {
                     {
                         count += chunk.len();
                         let status = format!(
-                            "{}: generate new segment files:{}/{}, cost:{} sec",
+                            "{}: generate new segment files:{}/{}, cost:{:?}",
                             self.kind,
                             count,
                             segment_indices.len(),
-                            start.elapsed().as_secs()
+                            start.elapsed()
                         );
                         self.ctx.set_status_info(&status);
                     }