From a2e490be3896d0a9f4ecd1c70c205faef408bf6a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dani=C3=ABl=20van=20Eeden?= Date: Tue, 3 Aug 2021 10:46:39 +0200 Subject: [PATCH 1/2] server, session: Reduce noise from SELECT...FOR UPDATE NOWAIT Issue: https://github.com/pingcap/tidb/issues/26842 --- server/conn.go | 20 ++++++++++++-------- session/session.go | 3 ++- 2 files changed, 14 insertions(+), 9 deletions(-) diff --git a/server/conn.go b/server/conn.go index be20a7c2763e2..0e43868b95792 100644 --- a/server/conn.go +++ b/server/conn.go @@ -995,14 +995,18 @@ func (cc *clientConn) Run(ctx context.Context) { txnMode = cc.ctx.GetSessionVars().GetReadableTxnMode() } metrics.ExecuteErrorCounter.WithLabelValues(metrics.ExecuteErrorToLabel(err)).Inc() - logutil.Logger(ctx).Info("command dispatched failed", - zap.String("connInfo", cc.String()), - zap.String("command", mysql.Command2Str[data[0]]), - zap.String("status", cc.SessionStatusToString()), - zap.Stringer("sql", getLastStmtInConn{cc}), - zap.String("txn_mode", txnMode), - zap.String("err", errStrForLog(err, cc.ctx.GetSessionVars().EnableRedactLog)), - ) + if storeerr.ErrLockAcquireFailAndNoWaitSet.Equal(err) { + logutil.Logger(ctx).Debug("Expected error for FOR UPDATE NOWAIT", zap.Error(err)) + } else { + logutil.Logger(ctx).Info("command dispatched failed", + zap.String("connInfo", cc.String()), + zap.String("command", mysql.Command2Str[data[0]]), + zap.String("status", cc.SessionStatusToString()), + zap.Stringer("sql", getLastStmtInConn{cc}), + zap.String("txn_mode", txnMode), + zap.String("err", errStrForLog(err, cc.ctx.GetSessionVars().EnableRedactLog)), + ) + } err1 := cc.writeError(ctx, err) terror.Log(err1) } diff --git a/session/session.go b/session/session.go index 9087239fea383..bcc4f2694dc48 100644 --- a/session/session.go +++ b/session/session.go @@ -74,6 +74,7 @@ import ( "github.com/pingcap/tidb/sessionctx/variable" "github.com/pingcap/tidb/statistics" "github.com/pingcap/tidb/statistics/handle" + storeerr "github.com/pingcap/tidb/store/driver/error" "github.com/pingcap/tidb/tablecodec" "github.com/pingcap/tidb/telemetry" "github.com/pingcap/tidb/types" @@ -1568,7 +1569,7 @@ func (s *session) ExecuteStmt(ctx context.Context, stmtNode ast.StmtNode) (sqlex logStmt(stmt, s) recordSet, err := runStmt(ctx, s, stmt) if err != nil { - if !kv.ErrKeyExists.Equal(err) { + if !kv.ErrKeyExists.Equal(err) && !storeerr.ErrLockAcquireFailAndNoWaitSet.Equal(err) { logutil.Logger(ctx).Warn("run statement failed", zap.Int64("schemaVersion", s.GetInfoSchema().SchemaMetaVersion()), zap.Error(err), From 25b6d364ee722b74c56da9e5ea17753dd91ef19f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dani=C3=ABl=20van=20Eeden?= Date: Tue, 14 Sep 2021 14:31:52 +0200 Subject: [PATCH 2/2] Update based on review from Morgan --- session/session.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/session/session.go b/session/session.go index bcc4f2694dc48..279b82f98ec2d 100644 --- a/session/session.go +++ b/session/session.go @@ -671,7 +671,13 @@ func (m temporaryTableKVFilter) IsUnnecessaryKeyValue(key, value []byte, flags t // of the errors defined in kv/error.go, these look to be clearly related to a client-inflicted issue, // and the server is only responsible for handling the error correctly. It does not need to log. func errIsNoisy(err error) bool { - return kv.ErrKeyExists.Equal(err) + if kv.ErrKeyExists.Equal(err) { + return true + } + if storeerr.ErrLockAcquireFailAndNoWaitSet.Equal(err) { + return true + } + return false } func (s *session) doCommitWithRetry(ctx context.Context) error { @@ -1569,7 +1575,7 @@ func (s *session) ExecuteStmt(ctx context.Context, stmtNode ast.StmtNode) (sqlex logStmt(stmt, s) recordSet, err := runStmt(ctx, s, stmt) if err != nil { - if !kv.ErrKeyExists.Equal(err) && !storeerr.ErrLockAcquireFailAndNoWaitSet.Equal(err) { + if !errIsNoisy(err) { logutil.Logger(ctx).Warn("run statement failed", zap.Int64("schemaVersion", s.GetInfoSchema().SchemaMetaVersion()), zap.Error(err),