Add some time costs log (pingcap#37)

* add time costs log

cmd/raw.go

@@ -106,11 +106,9 @@ func newFullBackupCommand() *cobra.Command {
 				client.PrintBackupProgress("Full Backup", int64(approximateRegions), done)
 			}()
 
-			for _, r := range ranges {
-				err = client.BackupRange(r.StartKey, r.EndKey, u, backupTS, rate, concurrency)
-				if err != nil {
-					return err
-				}
+			err = client.BackupRanges(ranges, u, backupTS, rate, concurrency)
+			if err != nil {
+				return err
 			}
 
 			valid, err := client.FastChecksum()
@@ -217,11 +215,9 @@ func newTableBackupCommand() *cobra.Command {
 				client.PrintBackupProgress("Table Backup", int64(approximateRegions), done)
 			}()
 
-			for _, r := range ranges {
-				err = client.BackupRange(r.StartKey, r.EndKey, u, backupTS, rate, concurrency)
-				if err != nil {
-					return err
-				}
+			err = client.BackupRanges(ranges, u, backupTS, rate, concurrency)
+			if err != nil {
+				return err
 			}
 
 			valid, err := client.FastChecksum()

cmd/restore.go

@@ -4,14 +4,15 @@ import (
 	"context"
 
 	"github.com/gogo/protobuf/proto"
-	"github.com/pingcap/br/pkg/restore"
-	"github.com/pingcap/br/pkg/utils"
 	"github.com/pingcap/errors"
 	"github.com/pingcap/kvproto/pkg/backup"
 	"github.com/pingcap/kvproto/pkg/import_sstpb"
 	restore_util "github.com/pingcap/tidb-tools/pkg/restore-util"
 	"github.com/spf13/cobra"
 	flag "github.com/spf13/pflag"
+
+	"github.com/pingcap/br/pkg/restore"
+	"github.com/pingcap/br/pkg/utils"
 )
 
 // NewRestoreCommand returns a restore subcommand
@@ -75,16 +76,16 @@ func newFullRestoreCommand() *cobra.Command {
 				}
 			}
 
-			splitter := restore_util.NewRegionSplitter(restore_util.NewClient(client.GetPDClient()))
 			rewriteRules := &restore_util.RewriteRules{
 				Table: tableRules,
 				Data:  dataRules,
 			}
 
-			err = splitter.Split(ctx, restore.GetRanges(files), rewriteRules)
+			err = restore.SplitRegion(ctx, client, files, rewriteRules)
 			if err != nil {
 				return errors.Trace(err)
 			}
+
 			restoreTS, err := client.GetTS()
 			if err != nil {
 				return errors.Trace(err)
@@ -159,8 +160,8 @@ func newDbRestoreCommand() *cobra.Command {
 			for _, table := range db.Tables {
 				files = append(files, table.Files...)
 			}
-			splitter := restore_util.NewRegionSplitter(restore_util.NewClient(client.GetPDClient()))
-			err = splitter.Split(ctx, restore.GetRanges(files), rewriteRules)
+
+			err = restore.SplitRegion(ctx, client, files, rewriteRules)
 			if err != nil {
 				return errors.Trace(err)
 			}
@@ -246,11 +247,12 @@ func newTableRestoreCommand() *cobra.Command {
 			if err != nil {
 				return errors.Trace(err)
 			}
-			splitter := restore_util.NewRegionSplitter(restore_util.NewClient(client.GetPDClient()))
-			err = splitter.Split(ctx, restore.GetRanges(table.Files), rewriteRules)
+
+			err = restore.SplitRegion(ctx, client, table.Files, rewriteRules)
 			if err != nil {
 				return errors.Trace(err)
 			}
+
 			restoreTS, err := client.GetTS()
 			if err != nil {
 				return errors.Trace(err)

pkg/raw/full.go

@@ -116,7 +116,7 @@ func (bc *BackupClient) SaveBackupMeta(path string) error {
 	if err != nil {
 		return errors.Trace(err)
 	}
-	log.Info("backup meta",
+	log.Debug("backup meta",
 		zap.Reflect("meta", bc.backupMeta))
 	log.Info("save backup meta", zap.String("path", path))
 	return bc.storage.Write(utils.MetaFile, backupMetaData)
@@ -319,8 +319,25 @@ LoadDb:
 	return ranges, nil
 }
 
-// BackupRange make a backup of the given key range.
-func (bc *BackupClient) BackupRange(
+// BackupRanges make a backup of the given key ranges.
+func (bc *BackupClient) BackupRanges(ranges []Range, path string, backupTS uint64, rate uint64, concurrency uint32) error {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("Backup Ranges", zap.Duration("take", elapsed))
+	}()
+
+	for _, r := range ranges {
+		err := bc.backupRange(r.StartKey, r.EndKey, path, backupTS, rate, concurrency)
+		if err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+// backupRange make a backup of the given key range.
+func (bc *BackupClient) backupRange(
 	startKey, endKey []byte,
 	path string,
 	backupTS uint64,
@@ -651,6 +668,12 @@ func (bc *BackupClient) GetRangeRegionCount(startKey, endKey []byte) (int, error
 
 // FastChecksum check data integrity by xor all(sst_checksum) per table
 func (bc *BackupClient) FastChecksum() (bool, error) {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("Backup Checksum", zap.Duration("take", elapsed))
+	}()
+
 	dbs, err := utils.LoadBackupTables(&bc.backupMeta)
 	if err != nil {
 		return false, err

pkg/restore/client.go

@@ -211,6 +211,11 @@ func (rc *Client) CreateTable(table *utils.Table) (*restore_util.RewriteRules, e
 
 // RestoreTable tries to restore the data of a table.
 func (rc *Client) RestoreTable(table *utils.Table, rewriteRules *restore_util.RewriteRules, restoreTS uint64) error {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("RestoreTable", zap.Stringer("table", table.Schema.Name), zap.Duration("take", elapsed))
+	}()
 	log.Info("start to restore table",
 		zap.Stringer("table", table.Schema.Name),
 		zap.Stringer("db", table.Db.Name),
@@ -244,6 +249,7 @@ func (rc *Client) RestoreTable(table *utils.Table, rewriteRules *restore_util.Re
 				"restore table failed",
 				zap.Stringer("table", table.Schema.Name),
 				zap.Stringer("db", table.Db.Name),
+				zap.Error(err),
 			)
 			return err
 		}
@@ -258,6 +264,11 @@ func (rc *Client) RestoreTable(table *utils.Table, rewriteRules *restore_util.Re
 
 // RestoreDatabase tries to restore the data of a database
 func (rc *Client) RestoreDatabase(db *utils.Database, rewriteRules *restore_util.RewriteRules, restoreTS uint64) error {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("RestoreDatabase", zap.Stringer("db", db.Schema.Name), zap.Duration("take", elapsed))
+	}()
 	errCh := make(chan error, len(db.Tables))
 	var wg sync.WaitGroup
 	defer close(errCh)
@@ -286,6 +297,11 @@ func (rc *Client) RestoreDatabase(db *utils.Database, rewriteRules *restore_util
 
 // RestoreAll tries to restore all the data of backup files.
 func (rc *Client) RestoreAll(rewriteRules *restore_util.RewriteRules, restoreTS uint64) error {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("RestoreAll", zap.Duration("take", elapsed))
+	}()
 	errCh := make(chan error, len(rc.databases))
 	var wg sync.WaitGroup
 	defer close(errCh)
@@ -366,6 +382,12 @@ func (rc *Client) switchTiKVMode(ctx context.Context, mode import_sstpb.SwitchMo
 
 //ValidateChecksum validate checksum after restore
 func (rc *Client) ValidateChecksum(rewriteRules []*import_sstpb.RewriteRule) error {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("Restore Checksum", zap.Duration("take", elapsed))
+	}()
+
 	var tables []*utils.Table
 	for _, db := range rc.databases {
 		tables = append(tables, db.Tables...)

pkg/restore/util.go

@@ -2,17 +2,20 @@ package restore
 
 import (
 	"bytes"
+	"context"
 	"strings"
 	"time"
 
 	_ "github.com/go-sql-driver/mysql" // mysql driver
 	"github.com/pingcap/kvproto/pkg/backup"
 	"github.com/pingcap/kvproto/pkg/import_sstpb"
 	"github.com/pingcap/kvproto/pkg/metapb"
+	"github.com/pingcap/log"
 	"github.com/pingcap/parser/model"
 	restore_util "github.com/pingcap/tidb-tools/pkg/restore-util"
 	"github.com/pingcap/tidb/tablecodec"
 	"github.com/pingcap/tidb/util/codec"
+	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -121,8 +124,8 @@ func withRetry(retryableFunc retryableFunc, continueFunc continueFunc, attempts
 	return lastErr
 }
 
-// GetRanges returns the ranges of the files.
-func GetRanges(files []*backup.File) []restore_util.Range {
+// getRanges returns the ranges of the files.
+func getRanges(files []*backup.File) []restore_util.Range {
 	ranges := make([]restore_util.Range, 0, len(files))
 	fileAppended := make(map[string]bool)
 
@@ -198,3 +201,16 @@ func rewriteRawKeyWithNewPrefix(key []byte, rewriteRules *restore_util.RewriteRu
 	}
 	return []byte("")
 }
+
+// SplitRegion splits region by
+// 1. data range after rewrite
+// 2. rewrite rules
+func SplitRegion(ctx context.Context, client *Client, files []*backup.File, rewriteRules *restore_util.RewriteRules) error {
+	start := time.Now()
+	defer func() {
+		elapsed := time.Since(start)
+		log.Info("SplitRegion", zap.Duration("costs", elapsed))
+	}()
+	splitter := restore_util.NewRegionSplitter(restore_util.NewClient(client.GetPDClient()))
+	return splitter.Split(ctx, getRanges(files), rewriteRules)
+}