From 7c9ebeff2fc231d76919cd138a696d217ef9145d Mon Sep 17 00:00:00 2001 From: luancheng Date: Fri, 13 Dec 2019 14:54:38 +0800 Subject: [PATCH] *: use summary log --- cmd/backup.go | 2 +- cmd/restore.go | 4 +++- pkg/backup/client.go | 7 +++---- pkg/restore/client.go | 9 +++++---- pkg/restore/util.go | 4 +++- pkg/utils/unit.go | 37 +++++++++++++++++++++++++++++++++++++ 6 files changed, 52 insertions(+), 11 deletions(-) diff --git a/cmd/backup.go b/cmd/backup.go index d1606bfbe..06595a698 100644 --- a/cmd/backup.go +++ b/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) }, } diff --git a/cmd/restore.go b/cmd/restore.go index f7d7fa42a..a9bf7b3cc 100644 --- a/cmd/restore.go +++ b/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 }, } diff --git a/pkg/backup/client.go b/pkg/backup/client.go index 6f4338788..74038e5f9 100644 --- a/pkg/backup/client.go +++ b/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) diff --git a/pkg/restore/client.go b/pkg/restore/client.go index 50ba45469..924596050 100644 --- a/pkg/restore/client.go +++ b/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") diff --git a/pkg/restore/util.go b/pkg/restore/util.go index c1d6d9db9..7d4e17842 100644 --- a/pkg/restore/util.go +++ b/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) { diff --git a/pkg/utils/unit.go b/pkg/utils/unit.go index 5f8009878..23d37ae45 100644 --- a/pkg/utils/unit.go +++ b/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...) +}