Noisy logging from dumpFileGcChecker

[dveeden]

Bug Report

1. Minimal reproduce step (Required)

make server && ./bin/tidb-server

This is with the unistore.

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

Logging from startup and server activity. (almost) no logging when there is no activity.

3. What did you see instead (Required)

[2023/06/28 08:21:22.628 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open replayer: no such file or directory"]
[2023/06/28 08:21:22.629 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open /tmp/optimizer_trace/302198: no such file or directory"]
[2023/06/28 08:21:22.629 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open extract: no such file or directory"]
[2023/06/28 08:31:22.629 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open replayer: no such file or directory"]
[2023/06/28 08:31:22.630 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open /tmp/optimizer_trace/302198: no such file or directory"]
[2023/06/28 08:31:22.630 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open extract: no such file or directory"]
[2023/06/28 08:41:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open replayer: no such file or directory"]
[2023/06/28 08:41:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open /tmp/optimizer_trace/302198: no such file or directory"]
[2023/06/28 08:41:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open extract: no such file or directory"]
[2023/06/28 08:51:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open replayer: no such file or directory"]
[2023/06/28 08:51:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open /tmp/optimizer_trace/302198: no such file or directory"]
[2023/06/28 08:51:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open extract: no such file or directory"]
[2023/06/28 09:01:22.621 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open replayer: no such file or directory"]
[2023/06/28 09:01:22.622 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open /tmp/optimizer_trace/302198: no such file or directory"]
[2023/06/28 09:01:22.622 +02:00] [WARN] [plan_replayer.go:91] ["[dumpFileGcChecker] open plan replayer directory failed"] [error="open extract: no such file or directory"]

$ find /tmp/optimizer_trace
find: ‘/tmp/optimizer_trace’: No such file or directory

4. What is your TiDB version? (Required)

Release Version: v7.3.0-alpha-68-gceccc1fc6f
Edition: Community
Git Commit Hash: ceccc1fc6fbd997aaaef843b354387368a885e19
Git Branch: master
UTC Build Time: 2023-06-28 06:04:37
GoVersion: go1.20.5
Race Enabled: false
Check Table Before Drop: false
Store: unistore

[dveeden]

This might have be related to bcad5b8 (#44752)

diff --git a/domain/plan_replayer.go b/domain/plan_replayer.go
index e1d2fba75a..31af6f061f 100644
--- a/domain/plan_replayer.go
+++ b/domain/plan_replayer.go
@@ -17,7 +17,6 @@ package domain
 import (
        "context"
        "fmt"
-       "io/ioutil"
        "os"
        "path/filepath"
        "strconv"
@@ -87,16 +86,18 @@ func (p *dumpFileGcChecker) setupSctx(sctx sessionctx.Context) {
 }
 
 func (p *dumpFileGcChecker) gcDumpFilesByPath(path string, gcDurationDefault, gcDurationForCapture time.Duration) {
-       files, err := ioutil.ReadDir(path)
+       entries, err := os.ReadDir(path)
        if err != nil {
-               if !os.IsNotExist(err) {
-                       logutil.BgLogger().Warn("[dumpFileGcChecker] open plan replayer directory failed", zap.Error(err))
-               }
+               logutil.BgLogger().Warn("[dumpFileGcChecker] open plan replayer directory failed", zap.Error(err))
        }
 
        gcTargetTimeDefault := time.Now().Add(-gcDurationDefault)
        gcTargetTimeForCapture := time.Now().Add(-gcDurationForCapture)
-       for _, f := range files {
+       for _, entry := range entries {
+               f, err := entry.Info()
+               if err != nil {
+                       logutil.BgLogger().Warn("[dumpFileGcChecker] open plan replayer directory failed", zap.Error(err))
+               }
                fileName := f.Name()
                createTime, err := parseTime(fileName)
                if err != nil {

[dveeden]

Looks like gcDumpFilesByPath() is called before generateOptimizerTraceFile() is called, so the non-existent directory is expected.

[dveeden]

The warning from plan_replayer.go:91 seems to have 3 different errors:

[error="open replayer: no such file or directory"]
[error="open /tmp/optimizer_trace/302198: no such file or directory"]
[error="open extract: no such file or directory"]

replayer comes from util/replayer/replayer.go:

// GetPlanReplayerDirName returns plan replayer directory path.
// The path is related to the process id.
func GetPlanReplayerDirName() string {
        tidbLogDir := filepath.Dir(config.GetGlobalConfig().Log.File.Filename)
        return filepath.Join(tidbLogDir, "replayer")
}

/tmp/optimizer_trace/302198 comes from domain/optimize_trace.go:

// GetOptimizerTraceDirName returns optimizer trace directory path.
// The path is related to the process id.
func GetOptimizerTraceDirName() string {
	return filepath.Join(os.TempDir(), "optimizer_trace", strconv.Itoa(os.Getpid()))
}

extract comes from domain/extract.go:

// GetExtractTaskDirName get extract dir name
func GetExtractTaskDirName() string {
        tidbLogDir := filepath.Dir(config.GetGlobalConfig().Log.File.Filename)
        return filepath.Join(tidbLogDir, "extract")
}

And tidbLogDir seems to come from:

tidbLogDir := filepath.Dir(config.GetGlobalConfig().Log.File.Filename)

1. Logging is noisy
2. The use of non-absolute paths could be a problem.