Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

executor: replace logger with zap logger #9521

Merged
merged 12 commits into from
Mar 14, 2019
Merged

executor: replace logger with zap logger #9521

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
a3b37d1
executor: replace logger with zap logger
alivxxx Mar 1, 2019
4922d95
Merge branch 'master' into log
zhouqiang-cl Mar 9, 2019
e7a9fa6
Merge branch 'master' of github.com:pingcap/tidb into log
alivxxx Mar 11, 2019
e022b85
address comments
alivxxx Mar 11, 2019
e8250b8
address comments
alivxxx Mar 12, 2019
04eecfa
address comments
alivxxx Mar 13, 2019
74fc487
Apply suggestions from code review
eurekaka Mar 14, 2019
4c29b73
Merge branch 'master' into log
eurekaka Mar 14, 2019
7d32cef
Merge branch 'master' into log
alivxxx Mar 14, 2019
9cfde5d
fix merge error
alivxxx Mar 14, 2019
d033c9d
Merge branch 'master' into log
zz-jason Mar 14, 2019
1ca6ab0
Merge branch 'master' into log
alivxxx Mar 14, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 7 additions & 5 deletions executor/adapter.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ import (

"github.com/opentracing/opentracing-go"
"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/ast"
"github.com/pingcap/parser/model"
"github.com/pingcap/parser/mysql"
Expand All @@ -40,7 +41,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"
)

// processinfoSetter is the interface use to set current running process info.
Expand Down Expand Up @@ -286,7 +288,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)
log.Error("Get current transaction failed", zap.Error(err))
} else {
if txn.Valid() {
txnTS = txn.StartTS()
Expand All @@ -313,7 +315,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)
log.Debug("InitTxnWithStartTS", zap.Uint64("con", ctx.GetSessionVars().ConnectionID), zap.String("text", a.Text))
err = ctx.InitTxnWithStartTS(math.MaxUint64)
} else if ctx.GetSessionVars().SnapshotTS != 0 {
if _, ok := a.Plan.(*plannercore.CheckTable); ok {
Expand Down Expand Up @@ -363,13 +365,13 @@ var QueryReplacer = strings.NewReplacer("\r", " ", "\n", " ", "\t", " ")
// 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
Expand Down
17 changes: 10 additions & 7 deletions executor/admin.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import (
"math"

"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/ast"
"github.com/pingcap/parser/model"
"github.com/pingcap/parser/terror"
Expand All @@ -34,7 +35,7 @@ import (
"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"
)

var (
Expand Down Expand Up @@ -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)
log.Info("Recover index", zap.String("table", e.table.Meta().Name.O),
zap.String("index", e.index.Meta().Name.O), zap.Int64("total added cnt", totalAddedCnt),
zap.Int64("total scan cnt", totalScanCnt), zap.Int64("next handle", result.nextHandle))
}

// no more rows
Expand Down Expand Up @@ -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)
log.Warn("The constraint of unique index is broken when recovering index",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we print [recover-index] prefix? @zimulala What's your opinion?

zap.String("index name", e.index.Meta().Name.O), zap.ByteString("key value", key),
qw4990 marked this conversation as resolved.
Show resolved Hide resolved
zap.Int64("handle", rows[i].handle), zap.Int64("another handle", handle))
}
}
rows[i].skip = true
Expand Down Expand Up @@ -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)
log.Info("Cleaning up dangling index", zap.String("table", e.table.Meta().Name.String()),
zap.String("index", e.index.Meta().Name.String()), zap.Uint64("count", e.removeCnt))
}
}
}
Expand Down
10 changes: 6 additions & 4 deletions executor/aggregate.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (

opentracing "github.com/opentracing/opentracing-go"
"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/mysql"
"github.com/pingcap/tidb/executor/aggfuncs"
"github.com/pingcap/tidb/expression"
Expand All @@ -30,8 +31,8 @@ import (
"github.com/pingcap/tidb/util/chunk"
"github.com/pingcap/tidb/util/codec"
"github.com/pingcap/tidb/util/set"
log "github.com/sirupsen/logrus"
"github.com/spaolacci/murmur3"
"go.uber.org/zap"
)

type aggPartialResultMapper map[string][]aggfuncs.PartialResult
Expand Down Expand Up @@ -318,9 +319,10 @@ func (w *HashAggPartialWorker) getChildInput() bool {
}

func recoveryHashAgg(output chan *AfFinalResult, r interface{}) {
output <- &AfFinalResult{err: errors.Errorf("%v", r)}
err := errors.Errorf("%v", r)
output <- &AfFinalResult{err: err}
buf := util.GetStack()
alivxxx marked this conversation as resolved.
Show resolved Hide resolved
log.Errorf("panic in the recoverable goroutine: %v, stack trace:\n%s", r, buf)
log.Error("Panic in the recoverable goroutine", zap.Error(err), zap.String("stack trace", string(buf)))
alivxxx marked this conversation as resolved.
Show resolved Hide resolved
}

func (w *HashAggPartialWorker) run(ctx sessionctx.Context, waitGroup *sync.WaitGroup, finalConcurrency int) {
Expand Down Expand Up @@ -475,7 +477,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))
log.Error("Append final result failed", zap.String("error stack", errors.ErrorStack(err)))
}
}
if len(w.aggFuncs) == 0 {
Expand Down
10 changes: 6 additions & 4 deletions executor/analyze.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ import (
"strconv"

"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/model"
"github.com/pingcap/parser/mysql"
"github.com/pingcap/tidb/distsql"
Expand All @@ -31,7 +32,7 @@ import (
"github.com/pingcap/tidb/util/chunk"
"github.com/pingcap/tidb/util/ranger"
"github.com/pingcap/tipb/go-tipb"
log "github.com/sirupsen/logrus"
"go.uber.org/zap"
)

var _ Executor = &AnalyzeExec{}
Expand Down Expand Up @@ -72,15 +73,16 @@ func (e *AnalyzeExec) Next(ctx context.Context, req *chunk.RecordBatch) error {
err = result.Err
if errors.Trace(err) == errAnalyzeWorkerPanic {
panicCnt++
} else {
log.Error("Analyze failed", zap.String("error stack", errors.ErrorStack(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))
log.Error("Save stats to storage failed", zap.String("error stack", errors.ErrorStack(err)))
continue
}
}
Expand Down Expand Up @@ -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)
log.Error("Analyze worker panicked", zap.String("panic stack", string(buf)))
metrics.PanicCounter.WithLabelValues(metrics.LabelAnalyze).Inc()
resultCh <- statistics.AnalyzeResult{
Err: errAnalyzeWorkerPanic,
Expand Down
5 changes: 3 additions & 2 deletions executor/checksum.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import (
"strconv"

"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/model"
"github.com/pingcap/tidb/distsql"
"github.com/pingcap/tidb/kv"
Expand All @@ -26,7 +27,7 @@ import (
"github.com/pingcap/tidb/util/chunk"
"github.com/pingcap/tidb/util/ranger"
"github.com/pingcap/tipb/go-tipb"
log "github.com/sirupsen/logrus"
"go.uber.org/zap"
)

var _ Executor = &ChecksumTableExec{}
Expand Down Expand Up @@ -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))
log.Error("Checksum failed", zap.String("error stack", errors.ErrorStack(err)))
continue
}
e.handleResult(result)
Expand Down
7 changes: 4 additions & 3 deletions executor/compiler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,14 +19,15 @@ import (

"github.com/opentracing/opentracing-go"
"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/ast"
"github.com/pingcap/tidb/config"
"github.com/pingcap/tidb/infoschema"
"github.com/pingcap/tidb/metrics"
"github.com/pingcap/tidb/planner"
plannercore "github.com/pingcap/tidb/planner/core"
"github.com/pingcap/tidb/sessionctx"
log "github.com/sirupsen/logrus"
"go.uber.org/zap"
)

// Compiler compiles an ast.StmtNode to a physical plan.
Expand Down Expand Up @@ -76,7 +77,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)
log.Warn("[EXPENSIVE_QUERY]", zap.String("sql", sql))
return
}

Expand Down Expand Up @@ -305,7 +306,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())
log.Info("Use snapshot schema", zap.Uint64("con", sessVar.ConnectionID), zap.Int64("schema meta version", is.SchemaMetaVersion()))
} else {
is = sessVar.TxnCtx.InfoSchema.(infoschema.InfoSchema)
}
Expand Down
7 changes: 4 additions & 3 deletions executor/ddl.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ import (
"strings"

"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/ast"
"github.com/pingcap/parser/model"
"github.com/pingcap/parser/mysql"
Expand All @@ -33,7 +34,7 @@ import (
"github.com/pingcap/tidb/util/chunk"
"github.com/pingcap/tidb/util/gcutil"
"github.com/pingcap/tidb/util/sqlexec"
log "github.com/sirupsen/logrus"
"go.uber.org/zap"
)

// DDLExec represents a DDL executor.
Expand All @@ -60,7 +61,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)
log.Error("Active txn failed", zap.Error(err))
return errors.Trace(err1)
}
schemaInfoErr := checker.Check(txn.StartTS())
Expand Down Expand Up @@ -252,7 +253,7 @@ func (e *DDLExec) executeDropTableOrView(s *ast.DropTableStmt) error {
}

if config.CheckTableBeforeDrop {
log.Warnf("admin check table `%s`.`%s` before drop.", fullti.Schema.O, fullti.Name.O)
log.Warn("Admin check table before drop", zap.String("table name", fmt.Sprintf("`%s`.`%s`", fullti.Schema.O, 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 {
Expand Down
15 changes: 8 additions & 7 deletions executor/distsql.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ import (

"github.com/opentracing/opentracing-go"
"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/model"
"github.com/pingcap/parser/mysql"
"github.com/pingcap/parser/terror"
Expand All @@ -41,7 +42,7 @@ import (
"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"
)

var (
Expand Down Expand Up @@ -464,7 +465,7 @@ func (e *IndexLookUpExecutor) startIndexWorker(ctx context.Context, kvRanges []k
}
cancel()
if err := result.Close(); err != nil {
log.Error("close Select result failed:", errors.ErrorStack(err))
log.Error("Close Select result failed", zap.String("error stack", errors.ErrorStack(err)))
}
if e.runtimeStats != nil {
copStats := e.ctx.GetSessionVars().StmtCtx.RuntimeStatsColl.GetRootStats(e.idxPlans[len(e.idxPlans)-1].ExplainID())
Expand Down Expand Up @@ -516,7 +517,7 @@ func (e *IndexLookUpExecutor) buildTableReader(ctx context.Context, handles []in
}
tableReader, err := e.dataReaderBuilder.buildTableReaderFromHandles(ctx, tableReaderExec, handles)
if err != nil {
log.Error(err)
log.Error("Build table reader from handles failed", zap.Error(err))
return nil, errors.Trace(err)
}
return tableReader, nil
Expand Down Expand Up @@ -612,7 +613,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)
log.Error("Index worker panicked", zap.String("panic stack", string(buf)))
err4Panic := errors.Errorf("%v", r)
doneCh := make(chan error, 1)
doneCh <- err4Panic
Expand Down Expand Up @@ -713,7 +714,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)
log.Error("Table worker panicked", zap.String("panic stack", string(buf)))
task.doneCh <- errors.Errorf("%v", r)
}
}()
Expand All @@ -739,7 +740,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)
log.Error("Build table reader failed", zap.Error(err))
return errors.Trace(err)
}
defer terror.Call(tableReader.Close)
Expand All @@ -754,7 +755,7 @@ func (w *tableWorker) executeTask(ctx context.Context, task *lookupTableTask) er
chk := tableReader.newFirstChunk()
err = tableReader.Next(ctx, chunk.NewRecordBatch(chk))
if err != nil {
log.Error(err)
log.Error("Table reader fetch next chunk failed", zap.Error(err))
return errors.Trace(err)
}
if chk.NumRows() == 0 {
Expand Down
7 changes: 4 additions & 3 deletions executor/executor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ import (
"github.com/cznic/mathutil"
"github.com/opentracing/opentracing-go"
"github.com/pingcap/errors"
"github.com/pingcap/log"
"github.com/pingcap/parser/ast"
"github.com/pingcap/parser/model"
"github.com/pingcap/parser/mysql"
Expand All @@ -45,7 +46,7 @@ import (
"github.com/pingcap/tidb/util/chunk"
"github.com/pingcap/tidb/util/execdetails"
"github.com/pingcap/tidb/util/memory"
log "github.com/sirupsen/logrus"
"go.uber.org/zap"
)

var (
Expand Down Expand Up @@ -466,7 +467,7 @@ func (e *CheckTableExec) Next(ctx context.Context, req *chunk.RecordBatch) error
err = e.doCheckTable(tb)
}
if err != nil {
log.Warnf("%v error:%v", t.Name, errors.ErrorStack(err))
log.Warn("Check table failed", zap.String("table name", t.Name.O), zap.String("error stack", errors.ErrorStack(err)))
if admin.ErrDataInConsistent.Equal(err) {
return ErrAdminCheckTable.GenWithStack("%v err:%v", t.Name, err)
}
Expand Down Expand Up @@ -1215,7 +1216,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)
log.Error("resultPuller panicked", zap.String("panic stack", string(buf)))
result.err = errors.Errorf("%v", r)
e.resultPool <- result
e.stopFetchData.Store(true)
Expand Down
Loading