*: use summary log

cmd/backup.go

@@ -145,6 +145,7 @@ func runBackup(flagSet *pflag.FlagSet, cmdName, db, table string) error {
 	// Checksum has finished
 	close(updateCh)
 
+	utils.TimeCollector.SummaryLog(cmdName)
 	return client.SaveBackupMeta(ctx)
 }
 
@@ -232,7 +233,6 @@ func newTableBackupCommand() *cobra.Command {
 			if len(table) == 0 {
 				return errors.Errorf("empty table name is not allowed")
 			}
-
 			return runBackup(command.Flags(), "Table backup", db, table)
 		},
 	}

cmd/restore.go

@@ -150,7 +150,7 @@ func newFullRestoreCommand() *cobra.Command {
 				return err
 			}
 			close(updateCh)
-
+			utils.TimeCollector.SummaryLog("restore full")
 			return nil
 		},
 	}
@@ -255,6 +255,7 @@ func newDbRestoreCommand() *cobra.Command {
 				return err
 			}
 			close(updateCh)
+			utils.TimeCollector.SummaryLog("restore database")
 			return nil
 		},
 	}
@@ -370,6 +371,7 @@ func newTableRestoreCommand() *cobra.Command {
 			}
 			close(updateCh)
 
+			utils.TimeCollector.SummaryLog("restore table")
 			return nil
 		},
 	}

pkg/backup/client.go

@@ -285,7 +285,7 @@ func (bc *Client) BackupRanges(
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("Backup Ranges", zap.Duration("take", elapsed))
+		utils.TimeCollector.CollectDuration("backup ranges", elapsed)
 	}()
 
 	errCh := make(chan error)
@@ -399,8 +399,7 @@ func (bc *Client) backupRange(
 	// Check if there are duplicated files.
 	results.checkDupFiles()
 
-	log.Info("backup range finished",
-		zap.Duration("take", time.Since(start)))
+	utils.TimeCollector.CollectDuration("backup range finished", time.Since(start))
 	return nil
 }
 
@@ -689,7 +688,7 @@ func (bc *Client) FastChecksum() (bool, error) {
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("Backup Checksum", zap.Duration("take", elapsed))
+		utils.TimeCollector.CollectDuration("backup checksum", elapsed)
 	}()
 
 	dbs, err := utils.LoadBackupTables(&bc.backupMeta)

pkg/restore/client.go

@@ -2,6 +2,7 @@ package restore
 
 import (
 	"context"
+	"fmt"
 	"math"
 	"sort"
 	"sync"
@@ -249,7 +250,7 @@ func (rc *Client) RestoreTable(
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("Restore Table", zap.Stringer("table", table.Schema.Name), zap.Duration("take", elapsed))
+		utils.TimeCollector.CollectDuration(fmt.Sprintf("restore table: %s", table.Schema.Name), elapsed)
 	}()
 	log.Debug("start to restore table",
 		zap.Stringer("table", table.Schema.Name),
@@ -310,7 +311,7 @@ func (rc *Client) RestoreDatabase(
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("Restore Database", zap.Stringer("db", db.Schema.Name), zap.Duration("take", elapsed))
+		utils.TimeCollector.CollectDuration(fmt.Sprintf("restore database: %s", db.Schema.Name), elapsed)
 	}()
 	errCh := make(chan error, len(db.Tables))
 	wg := new(sync.WaitGroup)
@@ -346,7 +347,7 @@ func (rc *Client) RestoreAll(
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("Restore All", zap.Duration("take", elapsed))
+		utils.TimeCollector.CollectDuration("restore all", elapsed)
 	}()
 	errCh := make(chan error, len(rc.databases))
 	wg := new(sync.WaitGroup)
@@ -443,7 +444,7 @@ func (rc *Client) ValidateChecksum(
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("Restore Checksum", zap.Duration("take", elapsed))
+		utils.TimeCollector.CollectDuration("restore checksum", elapsed)
 	}()
 
 	log.Info("Start to validate checksum")

pkg/restore/util.go

@@ -18,6 +18,8 @@ import (
 	"github.com/pingcap/tidb/util/codec"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+
+	"github.com/pingcap/br/pkg/utils"
 )
 
 var recordPrefixSep = []byte("_r")
@@ -333,7 +335,7 @@ func SplitRanges(
 	start := time.Now()
 	defer func() {
 		elapsed := time.Since(start)
-		log.Info("SplitRegion", zap.Duration("costs", elapsed))
+		utils.TimeCollector.CollectDuration("split region", elapsed)
 	}()
 	splitter := restore_util.NewRegionSplitter(restore_util.NewClient(client.GetPDClient()))
 	return splitter.Split(ctx, ranges, rewriteRules, func(*restore_util.Range) {

pkg/utils/unit.go

@@ -1,5 +1,14 @@
 package utils
 
+import (
+	"fmt"
+	"sync"
+	"time"
+
+	"github.com/pingcap/log"
+	"go.uber.org/zap"
+)
+
 // unit of storage
 const (
 	B = 1 << (iota * 10)
@@ -8,3 +17,31 @@ const (
 	GB
 	TB
 )
+
+type timeCollector struct {
+	mu    sync.Mutex
+	times map[string]time.Duration
+}
+
+// TimeCollector collects time into summary log
+var TimeCollector *timeCollector
+
+func init() {
+	TimeCollector = &timeCollector{
+		times: make(map[string]time.Duration),
+	}
+}
+
+func (tc *timeCollector) CollectDuration(name string, t time.Duration) {
+	tc.mu.Lock()
+	defer tc.mu.Unlock()
+	tc.times[name] = t
+}
+
+func (tc *timeCollector) SummaryLog(name string) {
+	z := make([]zap.Field, 0, len(tc.times))
+	for k, v := range tc.times {
+		z = append(z, zap.Duration(k, v))
+	}
+	log.Info(fmt.Sprintf("%s time summary", name), z...)
+}