From d97e2269927fa6162abc3f2de855349fcb2a0218 Mon Sep 17 00:00:00 2001 From: TonsnakeLin <87681388+TonsnakeLin@users.noreply.github.com> Date: Tue, 7 Dec 2021 20:49:56 +0800 Subject: [PATCH] cherry pick #30461 to release-5.3 Signed-off-by: ti-srebot --- executor/adapter.go | 9 ++++----- util/logutil/log_test.go | 8 ++++++-- util/logutil/slow_query_logger.go | 3 +++ 3 files changed, 13 insertions(+), 7 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index 457e0fee67579..0a743cce57d0c 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -1010,13 +1010,12 @@ func (a *ExecStmt) LogSlowQuery(txnTS uint64, succ bool, hasMoreResults bool) { if _, ok := a.StmtNode.(*ast.CommitStmt); ok { slowItems.PrevStmt = sessVars.PrevStmt.String() } + slowLog := sessVars.SlowLogFormat(slowItems) if trace.IsEnabled() { - trace.Log(a.GoCtx, "details", sessVars.SlowLogFormat(slowItems)) + trace.Log(a.GoCtx, "details", slowLog) } - if costTime < threshold { - logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(slowItems)) - } else { - logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(slowItems)) + logutil.SlowQueryLogger.Warn(slowLog) + if costTime >= threshold { if sessVars.InRestrictedSQL { totalQueryProcHistogramInternal.Observe(costTime.Seconds()) totalCopProcHistogramInternal.Observe(execDetail.TimeDetail.ProcessTime.Seconds()) diff --git a/util/logutil/log_test.go b/util/logutil/log_test.go index 23bbbfa621941..ff32c19b35e68 100644 --- a/util/logutil/log_test.go +++ b/util/logutil/log_test.go @@ -25,6 +25,7 @@ import ( "github.com/pingcap/log" "github.com/stretchr/testify/require" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) func TestZapLoggerWithKeys(t *testing.T) { @@ -115,13 +116,16 @@ func TestGrpcLoggerCreation(t *testing.T) { } func TestSlowQueryLoggerCreation(t *testing.T) { - level := "warn" + level := "Error" conf := NewLogConfig(level, DefaultLogFormat, "", EmptyFileLogConfig, false) _, prop, err := newSlowQueryLogger(conf) // assert after init slow query logger, the original conf is not changed require.Equal(t, conf.Level, level) require.Nil(t, err) - require.Equal(t, prop.Level.String(), conf.Level) + // slow query logger doesn't use the level of the global log config, and the + // level should be less than WarnLevel which is used by it to log slow query. + require.NotEqual(t, conf.Level, prop.Level.String()) + require.True(t, prop.Level.Level() <= zapcore.WarnLevel) } func TestGlobalLoggerReplace(t *testing.T) { diff --git a/util/logutil/slow_query_logger.go b/util/logutil/slow_query_logger.go index 5f81f3d73b2f4..05fe4b28db842 100644 --- a/util/logutil/slow_query_logger.go +++ b/util/logutil/slow_query_logger.go @@ -32,6 +32,9 @@ func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error) // copy global config and override slow query log file // if slow query log filename is empty, slow query log will behave the same as global log sqConfig := cfg.Config + // level of the global log config doesn't affect the slow query logger which determines whether to + // log by execution duration. + sqConfig.Level = LogConfig{}.Level if len(cfg.SlowQueryFile) != 0 { sqConfig.File = log.FileLogConfig{ MaxSize: cfg.File.MaxSize,