From e87c6f157ab94893b644e9cae68a44a40abfab92 Mon Sep 17 00:00:00 2001 From: Haibin Xie Date: Thu, 4 Apr 2019 16:07:26 +0800 Subject: [PATCH] executor: replace logger with zap logger (#9521) (#10043) --- executor/adapter.go | 11 ++++++----- executor/admin.go | 17 ++++++++++------- executor/aggregate.go | 10 +++++----- executor/analyze.go | 12 +++++++----- executor/checksum.go | 5 +++-- executor/compiler.go | 7 ++++--- executor/ddl.go | 10 +++++++--- executor/distsql.go | 15 ++++++++------- executor/executor.go | 7 ++++--- executor/index_lookup_join.go | 7 ++++--- executor/insert.go | 5 +++-- executor/insert_common.go | 7 ++++--- executor/load_data.go | 7 ++++--- executor/projection.go | 8 +++++--- executor/replace.go | 5 +++-- executor/set.go | 7 ++++--- executor/simple.go | 5 +++-- executor/write.go | 6 ++++-- util/logutil/log.go | 4 ++-- 19 files changed, 90 insertions(+), 65 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index a01e1d5f37c63..e301f409539e9 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -21,6 +21,7 @@ import ( "time" "github.com/pingcap/errors" + "github.com/pingcap/log" "github.com/pingcap/parser/ast" "github.com/pingcap/parser/model" "github.com/pingcap/parser/mysql" @@ -38,8 +39,8 @@ import ( "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/sqlexec" - log "github.com/sirupsen/logrus" "go.uber.org/zap" + "go.uber.org/zap/zapcore" "golang.org/x/net/context" ) @@ -282,7 +283,7 @@ func (a *ExecStmt) handleNoDelayExecutor(ctx context.Context, sctx sessionctx.Co txnTS := uint64(0) // Don't active pending txn here. if txn, err1 := sctx.Txn(false); err1 != nil { - log.Error(err1) + logutil.Logger(ctx).Error("get current transaction failed", zap.Error(err)) } else { if txn.Valid() { txnTS = txn.StartTS() @@ -310,7 +311,7 @@ func (a *ExecStmt) buildExecutor(ctx sessionctx.Context) (Executor, error) { return nil, errors.Trace(err) } if isPointGet { - log.Debugf("con:%d InitTxnWithStartTS %s", ctx.GetSessionVars().ConnectionID, a.Text) + logutil.Logger(context.Background()).Debug("init txnStartTS with MaxUint64", zap.Uint64("conn", ctx.GetSessionVars().ConnectionID), zap.String("text", a.Text)) err = ctx.InitTxnWithStartTS(math.MaxUint64) } if err != nil { @@ -374,13 +375,13 @@ func (a *ExecStmt) logAudit() { // LogSlowQuery is used to print the slow query in the log files. func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool) { level := log.GetLevel() - if level < log.WarnLevel { + if level > zapcore.WarnLevel { return } cfg := config.GetGlobalConfig() costTime := time.Since(a.StartTime) threshold := time.Duration(atomic.LoadUint64(&cfg.Log.SlowThreshold)) * time.Millisecond - if costTime < threshold && level < log.DebugLevel { + if costTime < threshold && level > zapcore.DebugLevel { return } sql := a.Text diff --git a/executor/admin.go b/executor/admin.go index 554b7074e4aba..f10a1bc88d49f 100644 --- a/executor/admin.go +++ b/executor/admin.go @@ -30,10 +30,11 @@ import ( "github.com/pingcap/tidb/tablecodec" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/ranger" "github.com/pingcap/tidb/util/timeutil" "github.com/pingcap/tipb/go-tipb" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -308,8 +309,9 @@ func (e *RecoverIndexExec) backfillIndex(ctx context.Context) (int64, int64, err totalScanCnt += result.scanRowCount if totalScanCnt-lastLogCnt >= 50000 { lastLogCnt = totalScanCnt - log.Infof("[recover-index] recover table:%v, index:%v, totalAddedCnt:%v, totalScanCnt:%v, nextHandle: %v", - e.table.Meta().Name.O, e.index.Meta().Name.O, totalAddedCnt, totalScanCnt, result.nextHandle) + logutil.Logger(ctx).Info("recover index", zap.String("table", e.table.Meta().Name.O), + zap.String("index", e.index.Meta().Name.O), zap.Int64("totalAddedCnt", totalAddedCnt), + zap.Int64("totalScanCnt", totalScanCnt), zap.Int64("nextHandle", result.nextHandle)) } // no more rows @@ -393,8 +395,9 @@ func (e *RecoverIndexExec) batchMarkDup(txn kv.Transaction, rows []recoverRows) } if handle != rows[i].handle { - log.Warnf("[recover-index] The constraint of unique index:%v is broken, handle:%v is not equal handle:%v with idxKey:%v.", - e.index.Meta().Name.O, handle, rows[i].handle, key) + logutil.Logger(context.Background()).Warn("recover index: the constraint of unique index is broken, handle in index is not equal to handle in table", + zap.String("index", e.index.Meta().Name.O), zap.ByteString("indexKey", key), + zap.Int64("handleInTable", rows[i].handle), zap.Int64("handleInIndex", handle)) } } rows[i].skip = true @@ -520,8 +523,8 @@ func (e *CleanupIndexExec) deleteDanglingIdx(txn kv.Transaction, values map[stri } e.removeCnt++ if e.removeCnt%e.batchSize == 0 { - log.Infof("[cleaning up dangling index] table: %v, index: %v, count: %v.", - e.table.Meta().Name.String(), e.index.Meta().Name.String(), e.removeCnt) + logutil.Logger(context.Background()).Info("clean up dangling index", zap.String("table", e.table.Meta().Name.String()), + zap.String("index", e.index.Meta().Name.String()), zap.Uint64("count", e.removeCnt)) } } } diff --git a/executor/aggregate.go b/executor/aggregate.go index f391c2d5946d1..02409fed792f4 100644 --- a/executor/aggregate.go +++ b/executor/aggregate.go @@ -24,12 +24,12 @@ import ( "github.com/pingcap/tidb/sessionctx" "github.com/pingcap/tidb/sessionctx/stmtctx" "github.com/pingcap/tidb/types" - "github.com/pingcap/tidb/util" "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/codec" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/set" - log "github.com/sirupsen/logrus" "github.com/spaolacci/murmur3" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -317,9 +317,9 @@ func (w *HashAggPartialWorker) getChildInput() bool { } func recoveryHashAgg(output chan *AfFinalResult, r interface{}) { + err := errors.Errorf("%v", r) output <- &AfFinalResult{err: errors.Errorf("%v", r)} - buf := util.GetStack() - log.Errorf("panic in the recoverable goroutine: %v, stack trace:\n%s", r, buf) + logutil.Logger(context.Background()).Error("parallel hash aggregation panicked", zap.Error(err)) } func (w *HashAggPartialWorker) run(ctx sessionctx.Context, waitGroup *sync.WaitGroup, finalConcurrency int) { @@ -474,7 +474,7 @@ func (w *HashAggFinalWorker) getFinalResult(sctx sessionctx.Context) { partialResults := w.getPartialResult(sctx.GetSessionVars().StmtCtx, []byte(groupKey), w.partialResultMap) for i, af := range w.aggFuncs { if err := af.AppendFinalResult2Chunk(sctx, partialResults[i], result); err != nil { - log.Error(errors.ErrorStack(err)) + logutil.Logger(context.Background()).Error("HashAggFinalWorker failed to append final result to Chunk", zap.Error(err)) } } if len(w.aggFuncs) == 0 { diff --git a/executor/analyze.go b/executor/analyze.go index 0f5b06f774843..06b59b41a7746 100644 --- a/executor/analyze.go +++ b/executor/analyze.go @@ -28,9 +28,10 @@ import ( "github.com/pingcap/tidb/statistics" "github.com/pingcap/tidb/tablecodec" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/ranger" "github.com/pingcap/tipb/go-tipb" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -72,15 +73,16 @@ func (e *AnalyzeExec) Next(ctx context.Context, chk *chunk.Chunk) error { err = result.Err if errors.Trace(err) == errAnalyzeWorkerPanic { panicCnt++ + } else { + logutil.Logger(ctx).Error("analyze failed", zap.Error(err)) } - log.Error(errors.ErrorStack(err)) continue } for i, hg := range result.Hist { err1 := statsHandle.SaveStatsToStorage(result.PhysicalTableID, result.Count, result.IsIndex, hg, result.Cms[i], 1) if err1 != nil { err = err1 - log.Error(errors.ErrorStack(err)) + logutil.Logger(ctx).Error("save stats to storage failed", zap.Error(err)) continue } } @@ -122,7 +124,7 @@ func (e *AnalyzeExec) analyzeWorker(taskCh <-chan *analyzeTask, resultCh chan<- buf := make([]byte, 4096) stackSize := runtime.Stack(buf, false) buf = buf[:stackSize] - log.Errorf("analyzeWorker panic stack is:\n%s", buf) + logutil.Logger(context.Background()).Error("analyze worker panicked", zap.String("stack", string(buf))) metrics.PanicCounter.WithLabelValues(metrics.LabelAnalyze).Inc() resultCh <- statistics.AnalyzeResult{ Err: errAnalyzeWorkerPanic, @@ -246,7 +248,7 @@ func (e *AnalyzeIndexExec) buildStatsFromResult(result distsql.SelectResult, nee } if needCMS { if resp.Cms == nil { - log.Warnf("nil CMS in response, table is %s, index is %s", e.idxInfo.Table.O, e.idxInfo.Name.O) + logutil.Logger(context.TODO()).Warn("nil CMS in response", zap.String("table", e.idxInfo.Table.O), zap.String("index", e.idxInfo.Name.O)) } else { err := cms.MergeCMSketch(statistics.CMSketchFromProto(resp.Cms)) if err != nil { diff --git a/executor/checksum.go b/executor/checksum.go index e0570d37f6c9b..0ae8a0a3b1a4b 100644 --- a/executor/checksum.go +++ b/executor/checksum.go @@ -23,9 +23,10 @@ import ( "github.com/pingcap/tidb/sessionctx" "github.com/pingcap/tidb/sessionctx/variable" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/ranger" "github.com/pingcap/tipb/go-tipb" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -70,7 +71,7 @@ func (e *ChecksumTableExec) Open(ctx context.Context) error { result := <-resultCh if result.Error != nil { err = result.Error - log.Error(errors.ErrorStack(err)) + logutil.Logger(ctx).Error("checksum failed", zap.Error(err)) continue } e.handleResult(result) diff --git a/executor/compiler.go b/executor/compiler.go index 53ac499fed25b..30b8c5454caf5 100644 --- a/executor/compiler.go +++ b/executor/compiler.go @@ -24,7 +24,8 @@ import ( "github.com/pingcap/tidb/metrics" plannercore "github.com/pingcap/tidb/planner/core" "github.com/pingcap/tidb/sessionctx" - log "github.com/sirupsen/logrus" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -75,7 +76,7 @@ func logExpensiveQuery(stmtNode ast.StmtNode, finalPlan plannercore.Plan) (expen if len(sql) > logSQLLen { sql = fmt.Sprintf("%s len(%d)", sql[:logSQLLen], len(sql)) } - log.Warnf("[EXPENSIVE_QUERY] %s", sql) + logutil.Logger(context.Background()).Warn("EXPENSIVE_QUERY", zap.String("SQL", sql)) return } @@ -195,7 +196,7 @@ func GetInfoSchema(ctx sessionctx.Context) infoschema.InfoSchema { var is infoschema.InfoSchema if snap := sessVar.SnapshotInfoschema; snap != nil { is = snap.(infoschema.InfoSchema) - log.Infof("con:%d use snapshot schema %d", sessVar.ConnectionID, is.SchemaMetaVersion()) + logutil.Logger(context.Background()).Info("use snapshot schema", zap.Uint64("conn", sessVar.ConnectionID), zap.Int64("schemaVersion", is.SchemaMetaVersion())) } else { is = sessVar.TxnCtx.InfoSchema.(infoschema.InfoSchema) } diff --git a/executor/ddl.go b/executor/ddl.go index b6eacce1f6e80..fac253a5790ec 100644 --- a/executor/ddl.go +++ b/executor/ddl.go @@ -27,8 +27,9 @@ import ( "github.com/pingcap/tidb/sessionctx/variable" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/sqlexec" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -56,7 +57,7 @@ func (e *DDLExec) toErr(err error) error { checker := domain.NewSchemaChecker(dom, e.is.SchemaMetaVersion(), nil) txn, err1 := e.ctx.Txn(true) if err1 != nil { - log.Error(err) + logutil.Logger(context.Background()).Error("active txn failed", zap.Error(err)) return errors.Trace(err1) } schemaInfoErr := checker.Check(txn.StartTS()) @@ -241,7 +242,10 @@ func (e *DDLExec) executeDropTable(s *ast.DropTableStmt) error { } if config.CheckTableBeforeDrop { - log.Warnf("admin check table `%s`.`%s` before drop.", fullti.Schema.O, fullti.Name.O) + logutil.Logger(context.Background()).Warn("admin check table before drop", + zap.String("database", fullti.Schema.O), + zap.String("table", fullti.Name.O), + ) sql := fmt.Sprintf("admin check table `%s`.`%s`", fullti.Schema.O, fullti.Name.O) _, _, err = e.ctx.(sqlexec.RestrictedSQLExecutor).ExecRestrictedSQL(e.ctx, sql) if err != nil { diff --git a/executor/distsql.go b/executor/distsql.go index 22e326e2390b0..f11a1f89e20bb 100644 --- a/executor/distsql.go +++ b/executor/distsql.go @@ -36,10 +36,11 @@ import ( "github.com/pingcap/tidb/table" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/memory" "github.com/pingcap/tidb/util/ranger" "github.com/pingcap/tipb/go-tipb" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -445,7 +446,7 @@ func (e *IndexLookUpExecutor) startIndexWorker(ctx context.Context, kvRanges []k e.ctx.StoreQueryFeedback(e.feedback) cancel() if err := result.Close(); err != nil { - log.Error("close Select result failed:", errors.ErrorStack(err)) + logutil.Logger(ctx).Error("close Select result failed", zap.Error(err)) } close(workCh) close(e.resultCh) @@ -494,7 +495,7 @@ func (e *IndexLookUpExecutor) buildTableReader(ctx context.Context, handles []in tableReaderExec.runtimeStats = nil tableReader, err := e.dataReaderBuilder.buildTableReaderFromHandles(ctx, tableReaderExec, handles) if err != nil { - log.Error(err) + logutil.Logger(ctx).Error("build table reader from handles failed", zap.Error(err)) return nil, errors.Trace(err) } return tableReader, nil @@ -586,7 +587,7 @@ func (w *indexWorker) fetchHandles(ctx context.Context, result distsql.SelectRes buf := make([]byte, 4096) stackSize := runtime.Stack(buf, false) buf = buf[:stackSize] - log.Errorf("indexWorker panic stack is:\n%s", buf) + logutil.Logger(ctx).Error("indexWorker in IndexLookupExecutor panicked", zap.String("stack", string(buf))) err4Panic := errors.Errorf("%v", r) doneCh := make(chan error, 1) doneCh <- err4Panic @@ -686,7 +687,7 @@ func (w *tableWorker) pickAndExecTask(ctx context.Context) { buf := make([]byte, 4096) stackSize := runtime.Stack(buf, false) buf = buf[:stackSize] - log.Errorf("tableWorker panic stack is:\n%s", buf) + logutil.Logger(ctx).Error("tableWorker in IndexLookUpExecutor panicked", zap.String("stack", string(buf))) task.doneCh <- errors.Errorf("%v", r) } }() @@ -712,7 +713,7 @@ func (w *tableWorker) pickAndExecTask(ctx context.Context) { func (w *tableWorker) executeTask(ctx context.Context, task *lookupTableTask) error { tableReader, err := w.buildTblReader(ctx, task.handles) if err != nil { - log.Error(err) + logutil.Logger(ctx).Error("build table reader failed", zap.Error(err)) return errors.Trace(err) } defer terror.Call(tableReader.Close) @@ -727,7 +728,7 @@ func (w *tableWorker) executeTask(ctx context.Context, task *lookupTableTask) er chk := tableReader.newFirstChunk() err = tableReader.Next(ctx, chk) if err != nil { - log.Error(err) + logutil.Logger(ctx).Error("table reader fetch next chunk failed", zap.Error(err)) return errors.Trace(err) } if chk.NumRows() == 0 { diff --git a/executor/executor.go b/executor/executor.go index d0d11b6357280..c1096513aa36e 100644 --- a/executor/executor.go +++ b/executor/executor.go @@ -42,8 +42,9 @@ import ( "github.com/pingcap/tidb/util/admin" "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/execdetails" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/memory" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" ) var ( @@ -448,7 +449,7 @@ func (e *CheckTableExec) Next(ctx context.Context, chk *chunk.Chunk) error { err = e.doCheckTable(tb) } if err != nil { - log.Warnf("%v error:%v", t.Name, errors.ErrorStack(err)) + logutil.Logger(ctx).Warn("check table failed", zap.String("tableName", t.Name.O), zap.Error(err)) if admin.ErrDataInConsistent.Equal(err) { return ErrAdminCheckTable.GenWithStack("%v err:%v", t.Name, err) } @@ -1177,7 +1178,7 @@ func (e *UnionExec) resultPuller(ctx context.Context, childID int) { buf := make([]byte, 4096) stackSize := runtime.Stack(buf, false) buf = buf[:stackSize] - log.Errorf("resultPuller panic stack is:\n%s", buf) + logutil.Logger(ctx).Error("resultPuller panicked", zap.String("stack", string(buf))) result.err = errors.Errorf("%v", r) e.resultPool <- result e.stopFetchData.Store(true) diff --git a/executor/index_lookup_join.go b/executor/index_lookup_join.go index 95190b7f8535f..4045ff6f0e0b0 100644 --- a/executor/index_lookup_join.go +++ b/executor/index_lookup_join.go @@ -30,10 +30,11 @@ import ( "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" "github.com/pingcap/tidb/util/codec" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/memory" "github.com/pingcap/tidb/util/mvmap" "github.com/pingcap/tidb/util/ranger" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -305,7 +306,7 @@ func (ow *outerWorker) run(ctx context.Context, wg *sync.WaitGroup) { buf := make([]byte, 4096) stackSize := runtime.Stack(buf, false) buf = buf[:stackSize] - log.Errorf("outerWorker panic stack is:\n%s", buf) + logutil.Logger(ctx).Error("outerWorker panicked", zap.String("stack", string(buf))) task := &lookUpJoinTask{doneCh: make(chan error, 1)} task.doneCh <- errors.Errorf("%v", r) ow.pushToChan(ctx, task, ow.resultCh) @@ -407,7 +408,7 @@ func (iw *innerWorker) run(ctx context.Context, wg *sync.WaitGroup) { buf := make([]byte, 4096) stackSize := runtime.Stack(buf, false) buf = buf[:stackSize] - log.Errorf("innerWorker panic stack is:\n%s", buf) + logutil.Logger(ctx).Error("innerWorker panicked", zap.String("stack", string(buf))) // "task != nil" is guaranteed when panic happened. task.doneCh <- errors.Errorf("%v", r) } diff --git a/executor/insert.go b/executor/insert.go index 2a6a83b055bd6..2800d0c09efd2 100644 --- a/executor/insert.go +++ b/executor/insert.go @@ -22,7 +22,8 @@ import ( "github.com/pingcap/tidb/tablecodec" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" - log "github.com/sirupsen/logrus" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -161,7 +162,7 @@ func (e *InsertExec) Open(ctx context.Context) error { func (e *InsertExec) updateDupRow(row toBeCheckedRow, handle int64, onDuplicate []*expression.Assignment) error { oldRow, err := e.getOldRow(e.ctx, e.Table, handle) if err != nil { - log.Errorf("[insert on dup] handle is %d for the to-be-inserted row %s", handle, types.DatumsToStrNoErr(row.row)) + logutil.Logger(context.Background()).Error("get old row failed when insert on dup", zap.Int64("handle", handle), zap.String("toBeInsertedRow", types.DatumsToStrNoErr(row.row))) return errors.Trace(err) } // Do update row. diff --git a/executor/insert_common.go b/executor/insert_common.go index c8e3fca8ca44f..f77502d16ed51 100644 --- a/executor/insert_common.go +++ b/executor/insert_common.go @@ -26,7 +26,8 @@ import ( "github.com/pingcap/tidb/table" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" - log "github.com/sirupsen/logrus" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -219,7 +220,7 @@ func (e *InsertValues) handleErr(col *table.Column, val *types.Datum, rowIdx int if types.ErrTruncated.Equal(err) { valStr, err1 := val.ToString() if err1 != nil { - log.Warn(err1) + logutil.Logger(context.Background()).Warn("truncate error", zap.Error(err1)) } return table.ErrTruncatedWrongValueForField.GenWithStackByArgs(types.TypeStr(col.Tp), valStr, col.Name.O, rowIdx+1) } @@ -511,7 +512,7 @@ func (e *InsertValues) adjustAutoIncrementDatum(d types.Datum, hasValue bool, c func (e *InsertValues) handleWarning(err error, logInfo string) { sc := e.ctx.GetSessionVars().StmtCtx sc.AppendWarning(err) - log.Warn(logInfo) + logutil.Logger(context.Background()).Warn(logInfo) } // batchCheckAndInsert checks rows with duplicate errors. diff --git a/executor/load_data.go b/executor/load_data.go index 74a5cff129fde..caedba7c46027 100644 --- a/executor/load_data.go +++ b/executor/load_data.go @@ -24,7 +24,8 @@ import ( "github.com/pingcap/tidb/table" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" - log "github.com/sirupsen/logrus" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -249,8 +250,8 @@ func (e *LoadDataInfo) InsertData(prevData, curData []byte) ([]byte, bool, error e.rowCount++ if e.maxRowsInBatch != 0 && e.rowCount%e.maxRowsInBatch == 0 { reachLimit = true - log.Infof("This insert rows has reached the batch %d, current total rows %d", - e.maxRowsInBatch, e.rowCount) + logutil.Logger(context.Background()).Info("batch limit hit when inserting rows", zap.Int("maxBatchRows", e.maxChunkSize), + zap.Uint64("totalRows", e.rowCount)) break } } diff --git a/executor/projection.go b/executor/projection.go index 9dfaee07b10be..2a69b30e3d6e6 100644 --- a/executor/projection.go +++ b/executor/projection.go @@ -14,6 +14,8 @@ package executor import ( + "context" + "fmt" "time" "github.com/pingcap/errors" @@ -21,8 +23,8 @@ import ( "github.com/pingcap/tidb/sessionctx" "github.com/pingcap/tidb/util" "github.com/pingcap/tidb/util/chunk" - log "github.com/sirupsen/logrus" - "golang.org/x/net/context" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" ) // This file contains the implementation of the physical Projection Operator: @@ -356,7 +358,7 @@ func recoveryProjection(output *projectionOutput, r interface{}) { output.done <- errors.Errorf("%v", r) } buf := util.GetStack() - log.Errorf("panic in the recoverable goroutine: %v, stack trace:\n%s", r, buf) + logutil.Logger(context.Background()).Error("projection executor panicked", zap.String("error", fmt.Sprintf("%v", r)), zap.String("stack", string(buf))) } func readProjectionInput(inputCh <-chan *projectionInput, finishCh <-chan struct{}) *projectionInput { diff --git a/executor/replace.go b/executor/replace.go index 5aa983a6e0ebb..2f24ffff7b6ae 100644 --- a/executor/replace.go +++ b/executor/replace.go @@ -19,7 +19,8 @@ import ( "github.com/pingcap/tidb/tablecodec" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" - log "github.com/sirupsen/logrus" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -52,7 +53,7 @@ func (e *ReplaceExec) removeRow(handle int64, r toBeCheckedRow) (bool, error) { newRow := r.row oldRow, err := e.batchChecker.getOldRow(e.ctx, r.t, handle) if err != nil { - log.Errorf("[replace] handle is %d for the to-be-inserted row %v", handle, types.DatumsToStrNoErr(r.row)) + logutil.Logger(context.Background()).Error("get old row failed when replace", zap.Int64("handle", handle), zap.String("toBeInsertedRow", types.DatumsToStrNoErr(r.row))) return false, errors.Trace(err) } rowUnchanged, err := types.EqualDatums(e.ctx.GetSessionVars().StmtCtx, oldRow, newRow) diff --git a/executor/set.go b/executor/set.go index 0e22422b9b87c..9564e96bf6e5f 100644 --- a/executor/set.go +++ b/executor/set.go @@ -29,8 +29,9 @@ import ( "github.com/pingcap/tidb/sessionctx/variable" "github.com/pingcap/tidb/types" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/sqlexec" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -188,7 +189,7 @@ func (e *SetExecutor) setSysVariable(name string, v *expression.VarAssignment) e valStr, err = value.ToString() terror.Log(errors.Trace(err)) } - log.Infof("con:%d %s=%s", sessionVars.ConnectionID, name, valStr) + logutil.Logger(context.Background()).Info("set session var", zap.Uint64("conn", sessionVars.ConnectionID), zap.String("name", name), zap.String("val", valStr)) } return nil @@ -262,7 +263,7 @@ func (e *SetExecutor) loadSnapshotInfoSchemaIfNeeded(name string) error { vars.SnapshotInfoschema = nil return nil } - log.Infof("con:%d loadSnapshotInfoSchema, SnapshotTS:%d", vars.ConnectionID, vars.SnapshotTS) + logutil.Logger(context.Background()).Info("load snapshot info schema", zap.Uint64("conn", vars.ConnectionID), zap.Uint64("SnapshotTS", vars.SnapshotTS)) dom := domain.GetDomain(e.ctx) snapInfo, err := dom.GetSnapshotInfoSchema(vars.SnapshotTS) if err != nil { diff --git a/executor/simple.go b/executor/simple.go index 8093996c3876e..3fa6054515bd3 100644 --- a/executor/simple.go +++ b/executor/simple.go @@ -30,8 +30,9 @@ import ( "github.com/pingcap/tidb/sessionctx" "github.com/pingcap/tidb/sessionctx/variable" "github.com/pingcap/tidb/util/chunk" + "github.com/pingcap/tidb/util/logutil" "github.com/pingcap/tidb/util/sqlexec" - log "github.com/sirupsen/logrus" + "go.uber.org/zap" "golang.org/x/net/context" ) @@ -127,7 +128,7 @@ func (e *SimpleExec) executeCommit(s *ast.CommitStmt) { func (e *SimpleExec) executeRollback(s *ast.RollbackStmt) error { sessVars := e.ctx.GetSessionVars() - log.Debugf("con:%d execute rollback statement", sessVars.ConnectionID) + logutil.Logger(context.Background()).Debug("execute rollback statement", zap.Uint64("conn", sessVars.ConnectionID)) sessVars.SetStatusFlag(mysql.ServerStatusInTrans, false) txn, err := e.ctx.Txn(true) if err != nil { diff --git a/executor/write.go b/executor/write.go index 585c438587e76..c6943c25dd627 100644 --- a/executor/write.go +++ b/executor/write.go @@ -14,6 +14,7 @@ package executor import ( + "context" "strings" "github.com/pingcap/errors" @@ -24,7 +25,8 @@ import ( "github.com/pingcap/tidb/table" "github.com/pingcap/tidb/table/tables" "github.com/pingcap/tidb/types" - log "github.com/sirupsen/logrus" + "github.com/pingcap/tidb/util/logutil" + "go.uber.org/zap" ) var ( @@ -178,7 +180,7 @@ func updateRecord(ctx sessionctx.Context, h int64, oldData, newData []types.Datu // so we reset the error msg here, and wrap old err with errors.Wrap. func resetErrDataTooLong(colName string, rowIdx int, err error) error { newErr := types.ErrDataTooLong.GenWithStack("Data too long for column '%v' at row %v", colName, rowIdx) - log.Error(err) + logutil.Logger(context.Background()).Error("data too long for column", zap.String("colName", colName), zap.Int("rowIndex", rowIdx)) return errors.Trace(newErr) } diff --git a/util/logutil/log.go b/util/logutil/log.go index 3a275e94052af..a0fef5bba1377 100644 --- a/util/logutil/log.go +++ b/util/logutil/log.go @@ -264,8 +264,8 @@ func initFileLog(cfg *zaplog.FileLogConfig, logger *log.Logger) error { // SlowQueryLogger is used to log slow query, InitLogger will modify it according to config file. var SlowQueryLogger = log.StandardLogger() -// SlowQueryZapLogger is used to log slow query, InitZapLogger will set it according to config file. -var SlowQueryZapLogger *zap.Logger +// SlowQueryZapLogger is used to log slow query, InitZapLogger will modify it according to config file. +var SlowQueryZapLogger = zaplog.L() // InitLogger initializes PD's logger. func InitLogger(cfg *LogConfig) error {