fix: add debug log for commit time cost

baseapp/abci.go

@@ -444,15 +444,15 @@ func (app *BaseApp) Commit() abci.ResponseCommit {
 	// Write the DeliverTx state into branched storage and commit the MultiStore.
 	// The write to the DeliverTx state writes all state transitions to the root
 	// MultiStore (app.cms) so when Commit() is called is persists those values.
-	t := time.Now()
+	startWriteTime := time.Now()
 	app.deliverState.ms.Write()
-	fmt.Printf("____ms.Write, height: %d, duration: %.2fms\n",
-		header.Height, float64(time.Since(t).Microseconds())/1000)
-	t = time.Now()
+	app.logger.Debug("ms.Write", "height", header.Height, "cost of time",
+		fmt.Sprintf(" %.2fms", float64(time.Since(startWriteTime).Microseconds())/1000))
 
+	startCommitTime := time.Now()
 	commitID := app.cms.Commit()
-	fmt.Printf("____ms.Commit, height: %d, duration: %.2fms\n",
-		header.Height, float64(time.Since(t).Microseconds())/1000)
+	app.logger.Debug("cms.Commit", "height", header.Height, "cost of time",
+		fmt.Sprintf(" %.2fms", float64(time.Since(startCommitTime).Microseconds())/1000))
 
 	res := abci.ResponseCommit{
 		Data:         commitID.Hash,

store/rootmulti/store.go

@@ -625,14 +625,10 @@ func (rs *Store) PruneStores(clearPruningManager bool, pruningHeights []int64) (
 		rs.logger.Debug("no heights need to be pruned")
 		return nil
 	}
-	t := time.Now()
-	defer func() {
-		fmt.Printf("_________PruneStores, from: %d, to: %d, duration: %.2fms\n",
-			pruningHeights[0], pruningHeights[len(pruningHeights)-1], float64(time.Since(t).Microseconds())/1000)
-	}()
 
 	rs.logger.Debug("pruning store", "heights", pruningHeights)
 
+	startPruneTime := time.Now()
 	var wg sync.WaitGroup
 	errCh := make(chan error)
 	for key, store := range rs.stores {
@@ -648,13 +644,12 @@ func (rs *Store) PruneStores(clearPruningManager bool, pruningHeights []int64) (
 
 		wg.Add(1)
 		go func(key types.StoreKey, store types.CommitStore) {
-			t1 := time.Now()
-			fmt.Printf("______________DeleteVersions, store: %s\n",
-				key.Name())
+			rs.logger.Debug("DeleteVersions", "store", key.Name())
+			startDeleteTime := time.Now()
 			err := store.(*iavl.Store).DeleteVersions(pruningHeights...)
 			if err == nil {
-				fmt.Printf("______________DeleteVersions, store: %s, duration: %.2fms\n",
-					key.Name(), float64(time.Since(t1).Microseconds())/1000)
+				rs.logger.Debug("DeleteVersions", "store", key.Name(), "cost of time",
+					fmt.Sprintf("%.2fms", float64(time.Since(startDeleteTime).Microseconds())/1000))
 				wg.Done()
 				return
 			}
@@ -675,6 +670,12 @@ func (rs *Store) PruneStores(clearPruningManager bool, pruningHeights []int64) (
 
 	select {
 	case <-done:
+		rs.logger.Debug(
+			"PruneStores",
+			"from", pruningHeights[0],
+			"to", pruningHeights[len(pruningHeights)-1],
+			"cost of time", fmt.Sprintf("%.2fms", float64(time.Since(startPruneTime).Microseconds())/1000),
+		)
 		return nil
 	case err := <-errCh:
 		return err