From dd5b880dbc2f25c48690eae5f2c2c304d4ddf570 Mon Sep 17 00:00:00 2001 From: 3pointer Date: Mon, 4 Nov 2019 18:04:33 +0800 Subject: [PATCH] Add some time costs log (#37) * add time costs log --- cmd/raw.go | 16 ++++++---------- cmd/restore.go | 18 ++++++++++-------- pkg/raw/full.go | 29 ++++++++++++++++++++++++++--- pkg/restore/client.go | 22 ++++++++++++++++++++++ pkg/restore/util.go | 20 ++++++++++++++++++-- 5 files changed, 82 insertions(+), 23 deletions(-) diff --git a/cmd/raw.go b/cmd/raw.go index bab83cdab9eec..883363453856f 100644 --- a/cmd/raw.go +++ b/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() diff --git a/cmd/restore.go b/cmd/restore.go index 8eea7c1eba5ae..a7cbece59abe1 100644 --- a/cmd/restore.go +++ b/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) diff --git a/pkg/raw/full.go b/pkg/raw/full.go index 96193545d94f9..a2aaa0a547be9 100644 --- a/pkg/raw/full.go +++ b/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 diff --git a/pkg/restore/client.go b/pkg/restore/client.go index bfbc79e54ad25..2946eb6a1a88e 100644 --- a/pkg/restore/client.go +++ b/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...) diff --git a/pkg/restore/util.go b/pkg/restore/util.go index 2eb307702d288..81f8cc0f3e1dc 100644 --- a/pkg/restore/util.go +++ b/pkg/restore/util.go @@ -2,6 +2,7 @@ package restore import ( "bytes" + "context" "strings" "time" @@ -9,10 +10,12 @@ import ( "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) +}