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,util: write slow query to slow log no matter what log level #30461

Merged
merged 12 commits into from
Dec 7, 2021
Merged

executor,util: write slow query to slow log no matter what log level #30461

Show file tree
Hide file tree
Changes from 11 commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
bfc9682
ddl: Do not consider the clustered index when checking the length of …
TonsnakeLin Nov 10, 2021
e1c3410
Merge branch 'master' of https://github.com/TonsnakeLin/tidb
TonsnakeLin Nov 10, 2021
662871c
Merge branch 'master' into master
TonsnakeLin Nov 10, 2021
dce8ef4
Merge branch 'master' into master
TonsnakeLin Nov 10, 2021
68a32a0
ddl: Do not consider the clustered index when checking the length of the
TonsnakeLin Nov 22, 2021
4918824
Merge branch 'master' into master
ti-chi-bot Dec 1, 2021
4d6c1b0
Merge branch 'master' into master
ti-chi-bot Dec 1, 2021
665924d
Merge branch 'pingcap:master' into master
TonsnakeLin Dec 7, 2021
8f12990
fix the bug TiDB doesn't log any slow log if log level higher than
TonsnakeLin Dec 7, 2021
ea25b28
Merge branch 'master' of https://github.com/TonsnakeLin/tidb
TonsnakeLin Dec 7, 2021
5b02862
fix the bug TiDB doesn't log any slow log(#30461)
TonsnakeLin Dec 7, 2021
4a002d7
Merge branch 'master' into master
ti-chi-bot Dec 7, 2021
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
9 changes: 4 additions & 5 deletions executor/adapter.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1022,13 +1022,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())
Expand Down
8 changes: 6 additions & 2 deletions util/logutil/log_test.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/pingcap/log"
"github.com/stretchr/testify/require"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)

func TestZapLoggerWithKeys(t *testing.T) {
Expand Down Expand Up @@ -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) {
Expand Down
3 changes: 3 additions & 0 deletions util/logutil/slow_query_logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,9 @@ func newSlowQueryLogger(cfg *LogConfig) (*zap.Logger, *log.ZapProperties, error)
// copy the global log config to slow log config
// if the filename of slow log config is empty, slow 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
Copy link
Contributor

@SabaPing SabaPing Dec 7, 2021 •
edited
Loading

Choose a reason for hiding this comment

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

LogConfig{}.Level set slowlogger to info level implicitly. Since executor/adapter.go logs slowlog with warn() method, this implicit setting could hide necessary information from developers.
IMHO it's better to explicitly set to info level.

Suggested change
sqConfig.Level = LogConfig{}.Level
sqConfig.Level = zap.InfoLevel.String()

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, I fixed the bug just like you at begin. But I talked about it with @youjiali1995 and We two think that It‘s best not to expose zap.InfoLevel here.
Anyway, I think the two fixed methods all can work.

Copy link
Member

Choose a reason for hiding this comment

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

I would prefer to explicitly indicate that the default log level is INFO, and slow log will always use WARN to log so that it is always printed out.

Otherwise as a reader I will have no idea about how slow log will be outputted. What do you think? @youjiali1995

Copy link
Contributor

Choose a reason for hiding this comment

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

Using the default value indicates slow logger doesn't care about log level. I would like to delete the Level field of the config if I could.

There is a test to cover the constraint that the default log level is less than warn level.

if len(cfg.SlowQueryFile) != 0 {
sqConfig.File = cfg.File
sqConfig.File.Filename = cfg.SlowQueryFile
Expand Down