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.

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

TiDB doesn't log any slow log if log.level >= "error" #30309

Closed
youjiali1995 opened this issue Dec 1, 2021 · 3 comments · Fixed by #30461
Closed

TiDB doesn't log any slow log if log.level >= "error" #30309

youjiali1995 opened this issue Dec 1, 2021 · 3 comments · Fixed by #30461
Assignees
Labels
affects-5.1 This bug affects 5.1.x versions. affects-5.2 This bug affects 5.2.x versions. affects-5.3 This bug affects 5.3.x versions. severity/critical sig/sql-infra SIG: SQL Infra type/bug The issue is confirmed as a bug.

Comments

@youjiali1995
Copy link
Contributor

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

  1. Deploy a nightly cluster with config below:
[log]
level = "error"
slow-threshold = 0
  1. Execute any query.
  2. See whether there is the tidb_slow_query.log file.

2. What did you expect to see? (Required)

slow logs show.

3. What did you see instead (Required)

No slow logs.

4. What is your TiDB version? (Required)

[v5.1-v5.3], nightly

@youjiali1995 youjiali1995 added type/bug The issue is confirmed as a bug. affects-5.1 This bug affects 5.1.x versions. affects-5.2 This bug affects 5.2.x versions. affects-5.3 This bug affects 5.3.x versions. labels Dec 1, 2021
@youjiali1995
Copy link
Contributor Author

youjiali1995 commented Dec 1, 2021

Introduced by #23534 which uses the same config of the server logger to initialize the slow query logger:
https://github.com/pingcap/tidb/pull/23534/files#diff-800042943fbf571b5e1b46f93f2ebab487a70873fd3c9708b00b39b9d59ce278R20.

The slow query logger uses default config before https://github.com/pingcap/tidb/pull/23534/files#diff-163bbfde1f383898e507b5ca82bd6bec58809a82f6b8352d991f50962f7f472aL277-L285 and it uses Debug or Warn to log:

tidb/executor/adapter.go

Lines 1028 to 1031 in e97e8c0

if costTime < threshold {
logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(slowItems))
} else {
logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(slowItems))

@youjiali1995
Copy link
Contributor Author

youjiali1995 commented Dec 6, 2021

We can use the default value of level to init the slow query logger here:

sqConfig := cfg.Config

Slow query logger can always use Warn() to log slow query because it determines whether to log by execution duration, not by log level:

tidb/executor/adapter.go

Lines 1028 to 1031 in dfd7157

if costTime < threshold {
logutil.SlowQueryLogger.Debug(sessVars.SlowLogFormat(slowItems))
} else {
logutil.SlowQueryLogger.Warn(sessVars.SlowLogFormat(slowItems))

If so, we can add a test case here to check the level of slow query logger is always less than warn level:
func TestSlowQueryLoggerCreation(t *testing.T) {

@TonsnakeLin

@github-actions
Copy link

github-actions bot commented Dec 7, 2021

Please check whether the issue should be labeled with 'affects-x.y' or 'fixes-x.y.z', and then remove 'needs-more-info' label.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
affects-5.1 This bug affects 5.1.x versions. affects-5.2 This bug affects 5.2.x versions. affects-5.3 This bug affects 5.3.x versions. severity/critical sig/sql-infra SIG: SQL Infra type/bug The issue is confirmed as a bug.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants