From 373608fe9dfc79690317949b1504a3848ba26229 Mon Sep 17 00:00:00 2001 From: Weizhen Wang Date: Wed, 6 Dec 2023 16:14:50 +0800 Subject: [PATCH] *: fix log for statistics (#49215) close pingcap/tidb#49216 --- pkg/domain/domain.go | 2 +- pkg/statistics/builder.go | 4 ++-- .../handle/autoanalyze/autoanalyze.go | 20 +++++++++---------- pkg/statistics/handle/cache/statscache.go | 2 +- pkg/statistics/handle/ddl/ddl.go | 2 +- .../handle/globalstats/global_stats_async.go | 14 ++++++------- pkg/statistics/handle/handle.go | 4 ++-- pkg/statistics/handle/lockstats/lock_stats.go | 6 +++--- .../handle/lockstats/unlock_stats.go | 4 ++-- pkg/statistics/handle/logutil/logutil.go | 8 ++++---- pkg/statistics/handle/storage/read.go | 4 ++-- pkg/statistics/handle/storage/save.go | 6 +++--- pkg/statistics/histogram.go | 4 ++-- 13 files changed, 40 insertions(+), 40 deletions(-) diff --git a/pkg/domain/domain.go b/pkg/domain/domain.go index 4337ce9473d47..2b0405e21399b 100644 --- a/pkg/domain/domain.go +++ b/pkg/domain/domain.go @@ -2371,7 +2371,7 @@ func (do *Domain) syncIndexUsageWorker(owner owner.Manager) { continue } if err := handle.GCIndexUsage(); err != nil { - statslogutil.StatsLogger.Error("gc index usage failed", zap.Error(err)) + statslogutil.StatsLogger().Error("gc index usage failed", zap.Error(err)) } } } diff --git a/pkg/statistics/builder.go b/pkg/statistics/builder.go index 27c1e18fc62d4..00e5956239da8 100644 --- a/pkg/statistics/builder.go +++ b/pkg/statistics/builder.go @@ -401,10 +401,10 @@ func BuildHistAndTopN( if foundTwice { datumString, err := firstTimeSample.ToString() if err != nil { - statslogutil.StatsLogger.Error("try to convert datum to string failed", zap.Error(err)) + statslogutil.StatsLogger().Error("try to convert datum to string failed", zap.Error(err)) } - statslogutil.StatsLogger.Warn( + statslogutil.StatsLogger().Warn( "invalid sample data", zap.Bool("isColumn", isColumn), zap.Int64("columnID", id), diff --git a/pkg/statistics/handle/autoanalyze/autoanalyze.go b/pkg/statistics/handle/autoanalyze/autoanalyze.go index 4e4a4321f735a..fb72e13b3c7c9 100644 --- a/pkg/statistics/handle/autoanalyze/autoanalyze.go +++ b/pkg/statistics/handle/autoanalyze/autoanalyze.go @@ -163,7 +163,7 @@ func HandleAutoAnalyze( ) (analyzed bool) { defer func() { if r := recover(); r != nil { - statslogutil.StatsLogger.Error( + statslogutil.StatsLogger().Error( "HandleAutoAnalyze panicked", zap.Any("recover", r), zap.Stack("stack"), @@ -179,7 +179,7 @@ func HandleAutoAnalyze( parameters[variable.TiDBAutoAnalyzeEndTime], ) if err != nil { - statslogutil.StatsLogger.Error( + statslogutil.StatsLogger().Error( "parse auto analyze period failed", zap.Error(err), ) @@ -237,7 +237,7 @@ func randomPickOneTableAndTryAutoAnalyze( tidsAndPids := getAllTidsAndPids(tbls) lockedTables, err := statsHandle.GetLockedTables(tidsAndPids...) if err != nil { - statslogutil.StatsLogger.Error( + statslogutil.StatsLogger().Error( "check table lock failed", zap.Error(err), ) @@ -329,7 +329,7 @@ func tryAutoAnalyzeTable( if err != nil { return false } - statslogutil.StatsLogger.Info( + statslogutil.StatsLogger().Info( "auto analyze triggered", zap.String("sql", escaped), zap.String("reason", reason), @@ -352,7 +352,7 @@ func tryAutoAnalyzeTable( return false } - statslogutil.StatsLogger.Info( + statslogutil.StatsLogger().Info( "auto analyze for unanalyzed indexes", zap.String("sql", escaped), ) @@ -434,7 +434,7 @@ func tryAutoAnalyzePartitionTableInDynamicMode( ratio, ); needAnalyze { needAnalyzePartitionNames = append(needAnalyzePartitionNames, def.Name.O) - statslogutil.StatsLogger.Info( + statslogutil.StatsLogger().Info( "need to auto analyze", zap.String("database", db), zap.String("table", tblInfo.Name.String()), @@ -459,7 +459,7 @@ func tryAutoAnalyzePartitionTableInDynamicMode( } if len(needAnalyzePartitionNames) > 0 { - statslogutil.StatsLogger.Info("start to auto analyze", + statslogutil.StatsLogger().Info("start to auto analyze", zap.String("database", db), zap.String("table", tblInfo.Name.String()), zap.Any("partitions", needAnalyzePartitionNames), @@ -479,7 +479,7 @@ func tryAutoAnalyzePartitionTableInDynamicMode( sql := getSQL("analyze table %n.%n partition", "", end-start) params := append([]interface{}{db, tblInfo.Name.O}, needAnalyzePartitionNames[start:end]...) - statslogutil.StatsLogger.Info( + statslogutil.StatsLogger().Info( "auto analyze triggered", zap.String("database", db), zap.String("table", tblInfo.Name.String()), @@ -517,7 +517,7 @@ func tryAutoAnalyzePartitionTableInDynamicMode( sql := getSQL("analyze table %n.%n partition", " index %n", end-start) params := append([]interface{}{db, tblInfo.Name.O}, needAnalyzePartitionNames[start:end]...) params = append(params, idx.Name.O) - statslogutil.StatsLogger.Info("auto analyze for unanalyzed", + statslogutil.StatsLogger().Info("auto analyze for unanalyzed", zap.String("database", db), zap.String("table", tblInfo.Name.String()), zap.String("index", idx.Name.String()), @@ -556,7 +556,7 @@ func execAutoAnalyze( if err1 != nil { escaped = "" } - statslogutil.StatsLogger.Error( + statslogutil.StatsLogger().Error( "auto analyze failed", zap.String("sql", escaped), zap.Duration("cost_time", dur), diff --git a/pkg/statistics/handle/cache/statscache.go b/pkg/statistics/handle/cache/statscache.go index e09ff2df107d8..2573b0f02ee20 100644 --- a/pkg/statistics/handle/cache/statscache.go +++ b/pkg/statistics/handle/cache/statscache.go @@ -101,7 +101,7 @@ func (s *StatsCacheImpl) Update(is infoschema.InfoSchema) error { tbl, err := s.statsHandle.TableStatsFromStorage(tableInfo, physicalID, false, 0) // Error is not nil may mean that there are some ddl changes on this table, we will not update it. if err != nil { - statslogutil.StatsLogger.Error("error occurred when read table stats", zap.String("table", tableInfo.Name.O), zap.Error(err)) + statslogutil.StatsLogger().Error("error occurred when read table stats", zap.String("table", tableInfo.Name.O), zap.Error(err)) continue } if tbl == nil { diff --git a/pkg/statistics/handle/ddl/ddl.go b/pkg/statistics/handle/ddl/ddl.go index 2633b08408c4b..3d23eeed96e10 100644 --- a/pkg/statistics/handle/ddl/ddl.go +++ b/pkg/statistics/handle/ddl/ddl.go @@ -135,7 +135,7 @@ func (h *ddlHandlerImpl) HandleDDLEvent(t *util.DDLEvent) error { sctx := se.(sessionctx.Context) is := sctx.GetDomainInfoSchema().(infoschema.InfoSchema) schema, _ := is.SchemaByTable(globalTableInfo) - logutil.StatsLogger.Warn( + logutil.StatsLogger().Warn( "drop partition with pseudo stats, "+ "usually it won't happen because we always load stats when initializing the handle", zap.String("schema", schema.Name.O), diff --git a/pkg/statistics/handle/globalstats/global_stats_async.go b/pkg/statistics/handle/globalstats/global_stats_async.go index 0ecfd66463866..81f40a8904247 100644 --- a/pkg/statistics/handle/globalstats/global_stats_async.go +++ b/pkg/statistics/handle/globalstats/global_stats_async.go @@ -225,7 +225,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) dealErrPartitionColumnStatsMissin func (a *AsyncMergePartitionStats2GlobalStats) ioWorker(sctx sessionctx.Context, isIndex bool) (err error) { defer func() { if r := recover(); r != nil { - statslogutil.StatsLogger.Warn("ioWorker panic", zap.Stack("stack"), zap.Any("error", r)) + statslogutil.StatsLogger().Warn("ioWorker panic", zap.Stack("stack"), zap.Any("error", r)) close(a.ioWorkerExitWhenErrChan) err = errors.New(fmt.Sprint(r)) } @@ -260,7 +260,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) ioWorker(sctx sessionctx.Context, func (a *AsyncMergePartitionStats2GlobalStats) cpuWorker(stmtCtx *stmtctx.StatementContext, sctx sessionctx.Context, opts map[ast.AnalyzeOptionType]uint64, isIndex bool, tz *time.Location, analyzeVersion int) (err error) { defer func() { if r := recover(); r != nil { - statslogutil.StatsLogger.Warn("cpuWorker panic", zap.Stack("stack"), zap.Any("error", r)) + statslogutil.StatsLogger().Warn("cpuWorker panic", zap.Stack("stack"), zap.Any("error", r)) err = errors.New(fmt.Sprint(r)) } close(a.cpuWorkerExitChan) @@ -282,7 +282,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) cpuWorker(stmtCtx *stmtctx.Statem } err = a.dealCMSketch() if err != nil { - statslogutil.StatsLogger.Warn("dealCMSketch failed", zap.Error(err)) + statslogutil.StatsLogger().Warn("dealCMSketch failed", zap.Error(err)) return err } failpoint.Inject("PanicSameTime", func(val failpoint.Value) { @@ -293,7 +293,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) cpuWorker(stmtCtx *stmtctx.Statem }) err = a.dealHistogramAndTopN(stmtCtx, sctx, opts, isIndex, tz, analyzeVersion) if err != nil { - statslogutil.StatsLogger.Warn("dealHistogramAndTopN failed", zap.Error(err)) + statslogutil.StatsLogger().Warn("dealHistogramAndTopN failed", zap.Error(err)) return err } return nil @@ -361,7 +361,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) loadFmsketch(sctx sessionctx.Cont fmsketch, i, }: case <-a.cpuWorkerExitChan: - statslogutil.StatsLogger.Warn("ioWorker detects CPUWorker has exited") + statslogutil.StatsLogger().Warn("ioWorker detects CPUWorker has exited") return nil } } @@ -392,7 +392,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) loadCMsketch(sctx sessionctx.Cont cmsketch, i, }: case <-a.cpuWorkerExitChan: - statslogutil.StatsLogger.Warn("ioWorker detects CPUWorker has exited") + statslogutil.StatsLogger().Warn("ioWorker detects CPUWorker has exited") return nil } } @@ -434,7 +434,7 @@ func (a *AsyncMergePartitionStats2GlobalStats) loadHistogramAndTopN(sctx session NewStatsWrapper(hists, topn), i, }: case <-a.cpuWorkerExitChan: - statslogutil.StatsLogger.Warn("ioWorker detects CPUWorker has exited") + statslogutil.StatsLogger().Warn("ioWorker detects CPUWorker has exited") return nil } } diff --git a/pkg/statistics/handle/handle.go b/pkg/statistics/handle/handle.go index 020525037a4fc..82872c1ebb72e 100644 --- a/pkg/statistics/handle/handle.go +++ b/pkg/statistics/handle/handle.go @@ -175,11 +175,11 @@ func (h *Handle) FlushStats() { for len(h.DDLEventCh()) > 0 { e := <-h.DDLEventCh() if err := h.HandleDDLEvent(e); err != nil { - statslogutil.StatsLogger.Error("handle ddl event fail", zap.Error(err)) + statslogutil.StatsLogger().Error("handle ddl event fail", zap.Error(err)) } } if err := h.DumpStatsDeltaToKV(true); err != nil { - statslogutil.StatsLogger.Error("dump stats delta fail", zap.Error(err)) + statslogutil.StatsLogger().Error("dump stats delta fail", zap.Error(err)) } } diff --git a/pkg/statistics/handle/lockstats/lock_stats.go b/pkg/statistics/handle/lockstats/lock_stats.go index 20c78784efcba..bb4a04cd2600b 100644 --- a/pkg/statistics/handle/lockstats/lock_stats.go +++ b/pkg/statistics/handle/lockstats/lock_stats.go @@ -156,7 +156,7 @@ func AddLockedTables( ids = append(ids, pid) } } - logutil.StatsLogger.Info("lock table", + logutil.StatsLogger().Info("lock table", zap.Any("tables", tables), ) @@ -210,7 +210,7 @@ func AddLockedPartitions( pNames = append(pNames, pName) } - logutil.StatsLogger.Info("lock partitions", + logutil.StatsLogger().Info("lock partitions", zap.Int64("tableID", tid), zap.String("tableName", tableName), zap.Int64s("partitionIDs", pids), @@ -291,7 +291,7 @@ func generateStableSkippedPartitionsMessage(ids []int64, tableName string, skipp func insertIntoStatsTableLocked(sctx sessionctx.Context, tid int64) error { _, _, err := util.ExecRows(sctx, insertSQL, tid, tid) if err != nil { - logutil.StatsLogger.Error("error occurred when insert mysql.stats_table_locked", zap.Error(err)) + logutil.StatsLogger().Error("error occurred when insert mysql.stats_table_locked", zap.Error(err)) return err } return nil diff --git a/pkg/statistics/handle/lockstats/unlock_stats.go b/pkg/statistics/handle/lockstats/unlock_stats.go index 21d422d66d691..1c72679c5462d 100644 --- a/pkg/statistics/handle/lockstats/unlock_stats.go +++ b/pkg/statistics/handle/lockstats/unlock_stats.go @@ -54,7 +54,7 @@ func RemoveLockedTables( } } - statslogutil.StatsLogger.Info("unlock table", + statslogutil.StatsLogger().Info("unlock table", zap.Any("tables", tables), ) @@ -107,7 +107,7 @@ func RemoveLockedPartitions( for pid := range pidNames { pids = append(pids, pid) } - statslogutil.StatsLogger.Info("unlock partitions", + statslogutil.StatsLogger().Info("unlock partitions", zap.Int64("tableID", tid), zap.String("tableName", tableName), zap.Int64s("partitionIDs", pids), diff --git a/pkg/statistics/handle/logutil/logutil.go b/pkg/statistics/handle/logutil/logutil.go index c3ae89384dda8..ea791531a7760 100644 --- a/pkg/statistics/handle/logutil/logutil.go +++ b/pkg/statistics/handle/logutil/logutil.go @@ -19,7 +19,7 @@ import ( "go.uber.org/zap" ) -var ( - // StatsLogger with category "stats" is used to log statistic related messages. - StatsLogger = logutil.BgLogger().With(zap.String("category", "stats")) -) +// StatsLogger with category "stats" is used to log statistic related messages. +func StatsLogger() *zap.Logger { + return logutil.BgLogger().With(zap.String("category", "stats")) +} diff --git a/pkg/statistics/handle/storage/read.go b/pkg/statistics/handle/storage/read.go index 531b8872d3c66..fb5cc3c18d159 100644 --- a/pkg/statistics/handle/storage/read.go +++ b/pkg/statistics/handle/storage/read.go @@ -200,7 +200,7 @@ func ExtendedStatsFromStorage(sctx sessionctx.Context, table *statistics.Table, colIDs := row.GetString(3) err := json.Unmarshal([]byte(colIDs), &item.ColIDs) if err != nil { - statslogutil.StatsLogger.Error("decode column IDs failed", zap.String("column_ids", colIDs), zap.Error(err)) + statslogutil.StatsLogger().Error("decode column IDs failed", zap.String("column_ids", colIDs), zap.Error(err)) return nil, err } statsStr := row.GetString(4) @@ -208,7 +208,7 @@ func ExtendedStatsFromStorage(sctx sessionctx.Context, table *statistics.Table, if statsStr != "" { item.ScalarVals, err = strconv.ParseFloat(statsStr, 64) if err != nil { - statslogutil.StatsLogger.Error("parse scalar stats failed", zap.String("stats", statsStr), zap.Error(err)) + statslogutil.StatsLogger().Error("parse scalar stats failed", zap.String("stats", statsStr), zap.Error(err)) return nil, err } } diff --git a/pkg/statistics/handle/storage/save.go b/pkg/statistics/handle/storage/save.go index d3adec903c4ff..38c8ccefc5f59 100644 --- a/pkg/statistics/handle/storage/save.go +++ b/pkg/statistics/handle/storage/save.go @@ -197,7 +197,7 @@ func SaveTableStatsToStorage(sctx sessionctx.Context, if modifyCnt < 0 { modifyCnt = 0 } - statslogutil.StatsLogger.Info("incrementally update modifyCount", + statslogutil.StatsLogger().Info("incrementally update modifyCount", zap.Int64("tableID", tableID), zap.Int64("curModifyCnt", curModifyCnt), zap.Int64("results.BaseModifyCnt", results.BaseModifyCnt), @@ -208,7 +208,7 @@ func SaveTableStatsToStorage(sctx sessionctx.Context, if cnt < 0 { cnt = 0 } - statslogutil.StatsLogger.Info("incrementally update count", + statslogutil.StatsLogger().Info("incrementally update count", zap.Int64("tableID", tableID), zap.Int64("curCnt", curCnt), zap.Int64("results.Count", results.Count), @@ -219,7 +219,7 @@ func SaveTableStatsToStorage(sctx sessionctx.Context, if cnt < 0 { cnt = 0 } - statslogutil.StatsLogger.Info("directly update count", + statslogutil.StatsLogger().Info("directly update count", zap.Int64("tableID", tableID), zap.Int64("results.Count", results.Count), zap.Int64("count", cnt)) diff --git a/pkg/statistics/histogram.go b/pkg/statistics/histogram.go index 09209acf21ec3..1966e385f1b53 100644 --- a/pkg/statistics/histogram.go +++ b/pkg/statistics/histogram.go @@ -1272,7 +1272,7 @@ func mergeBucketNDV(sc *stmtctx.StatementContext, left *bucket4Merging, right *b // illegal order. if upperCompare < 0 { err := errors.Errorf("illegal bucket order") - statslogutil.StatsLogger.Warn("fail to mergeBucketNDV", zap.Error(err)) + statslogutil.StatsLogger().Warn("fail to mergeBucketNDV", zap.Error(err)) return nil, err } // ___right_| @@ -1288,7 +1288,7 @@ func mergeBucketNDV(sc *stmtctx.StatementContext, left *bucket4Merging, right *b // illegal order. if lowerCompare < 0 { err := errors.Errorf("illegal bucket order") - statslogutil.StatsLogger.Warn("fail to mergeBucketNDV", zap.Error(err)) + statslogutil.StatsLogger().Warn("fail to mergeBucketNDV", zap.Error(err)) return nil, err } // |___right___|