Repository: kubernetes/klog (go)

Issue:
When disk I/O was very heavy, klog calling file sync with locking caused all log recording to be blocked for a long time.
/kind bug

**What steps did you take and what happened:**

We found an issue in our Kubernetes cluster. When disk I/O was very heavy, the node would occasionally become not ready.
We identified that this was because klog was calling fsync with locking, which caused kubelet's log writing to be blocked. This resulted in the container runtime status check time exceeding 10 seconds. As a result, kubelet considered the container runtime to be unhealthy and set the node to not ready status.

The kernel has an excellent and efficient buffered I/O mechanism. fsync can ensure that logs are persisted to disk, but we should not call fsync with locking as it would significantly impact performance and fail to take advantage of the kernel's buffered I/O mechanism, making it no different from using direct I/O (which is generally only used by databases).

A high-performance approach is to spawn a lock-free goroutine to periodically call fsync.(fsync does not block buffered I/O)

https://github.com/kubernetes/klog/blob/main/klog.go#L1224

``` go
// lockAndFlushAll is like flushAll but locks l.mu first.
func (l *loggingT) lockAndFlushAll() {
	l.mu.Lock()
	l.flushAll()
	l.mu.Unlock()
}

// flushAll flushes all the logs and attempts to "sync" their data to disk.
// l.mu is held.
func (l *loggingT) flushAll() {
	// Flush from fatal down, in case there's trouble flushing.
	for s := severity.FatalLog; s >= severity.InfoLog; s-- {
		file := l.file[s]
		if file != nil {
			_ = file.Flush() // ignore error
			_ = file.Sync()  // ignore error
		}
	}
	if logging.loggerOptions.flush != nil {
		logging.loggerOptions.flush()
	}
}
```

**What did you expect to happen:**

klog will not block normal log recording due to flushing dirty pages to disk(heavy IO).

**Anything else you would like to add:**
[Miscellaneous information that will assist in solving the issue.]


Pull request description:
Do not acquire lock for file.Sync() fsync call
<!--  Thanks for sending a pull request!  Here are some tips for you:
1. If this is your first time, read our contributor guidelines https://git.k8s.io/community/contributors/guide/pull-requests.md#the-pull-request-submit-process and developer guide https://git.k8s.io/community/contributors/devel/development.md#development-guide
2. If you want *faster* PR reviews, read how: https://git.k8s.io/community/contributors/guide/pull-requests.md#best-practices-for-faster-reviews
3. Follow the instructions for writing a release note: https://git.k8s.io/community/contributors/guide/release-notes.md
4. If the PR is unfinished, see how to mark it: https://git.k8s.io/community/contributors/guide/pull-requests.md#marking-unfinished-pull-requests
5. If this PR changes image versions, please title this PR "Bump <image name> from x.x.x to y.y.y."
-->

**What this PR does / why we need it**:

For file.Sync() (the fsync system call that flushes the kernel buffer to disk), there is no need to acquire a lock; let the kernel handle it.

**Which issue(s) this PR fixes**:

Fixes #403 

**Release note**:
<!--  Write your release note:
1. Enter your extended release note in the below block. If the PR requires additional action from users switching to the new release, include the string "action required".
2. If no release note is required, just write "NONE".
-->
```release-note
Do not acquire lock for file.Sync() fsync call
```

Patch:
diff --git a/klog.go b/klog.go
index 026be9e..16dcb3b 100644
--- a/klog.go
+++ b/klog.go
@@ -1011,7 +1011,8 @@ func (l *loggingT) exit(err error) {
 		logExitFunc(err)
 		return
 	}
-	l.flushAll()
+	files := l.flushAll()
+	l.syncAll(files)
 	OsExit(2)
 }
 
@@ -1223,24 +1224,38 @@ func StartFlushDaemon(interval time.Duration) {
 // lockAndFlushAll is like flushAll but locks l.mu first.
 func (l *loggingT) lockAndFlushAll() {
 	l.mu.Lock()
-	l.flushAll()
+	files := l.flushAll()
 	l.mu.Unlock()
+	// Some environments are slow when syncing and holding the lock might cause contention.
+	l.syncAll(files)
 }
 
-// flushAll flushes all the logs and attempts to "sync" their data to disk.
+// flushAll flushes all the logs
 // l.mu is held.
-func (l *loggingT) flushAll() {
+func (l *loggingT) flushAll() []flushSyncWriter {
+	files := make([]flushSyncWriter, 0, severity.NumSeverity)
 	// Flush from fatal down, in case there's trouble flushing.
 	for s := severity.FatalLog; s >= severity.InfoLog; s-- {
 		file := l.file[s]
 		if file != nil {
 			_ = file.Flush() // ignore error
-			_ = file.Sync()  // ignore error
 		}
+		files = append(files, file)
 	}
 	if logging.loggerOptions.flush != nil {
 		logging.loggerOptions.flush()
 	}
+	return files
+}
+
+// syncAll attempts to "sync" their data to disk.
+func (l *loggingT) syncAll(files []flushSyncWriter) {
+	// Flush from fatal down, in case there's trouble flushing.
+	for _, file := range files {
+		if file != nil {
+			_ = file.Sync() // ignore error
+		}
+	}
 }
 
 // CopyStandardLogTo arranges for messages written to the Go "log" package's


Test patch:
diff --git a/examples/output_test/output_test.go b/examples/output_test/output_test.go
index 872d8fc..e9a79d4 100644
--- a/examples/output_test/output_test.go
+++ b/examples/output_test/output_test.go
@@ -112,7 +112,7 @@ func TestKlogrStackZapr(t *testing.T) {
 		mapping[key] = value
 	}
 
-	newLogger := func(out io.Writer, v int, _ string) logr.Logger {
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
 		// Backend: zapr as configured in k8s.io/component-base/logs/json.
 		klog.SetLogger(newZaprLogger(out, v))
 
@@ -177,7 +177,7 @@ func TestKlogrInternalStackZapr(t *testing.T) {
 		mapping[key] = value
 	}
 
-	newLogger := func(out io.Writer, v int, _ string) logr.Logger {
+	newLogger := func(out io.Writer, v int, vmodule string) logr.Logger {
 		// Backend: zapr as configured in k8s.io/component-base/logs/json.
 		klog.SetLogger(newZaprLogger(out, v))
 
diff --git a/klog_test.go b/klog_test.go
index 3f427dd..c93c486 100644
--- a/klog_test.go
+++ b/klog_test.go
@@ -546,7 +546,8 @@ func TestOpenAppendOnStart(t *testing.T) {
 	}
 
 	// ensure we wrote what we expected
-	logging.flushAll()
+	files := logging.flushAll()
+	logging.syncAll(files)
 	b, err := ioutil.ReadFile(logging.logFile)
 	if err != nil {
 		t.Fatalf("unexpected error: %v", err)
@@ -817,7 +818,8 @@ func BenchmarkLogs(b *testing.B) {
 		Warning("warning")
 		Info("info")
 	}
-	logging.flushAll()
+	files := logging.flushAll()
+	logging.syncAll(files)
 }
 
 // Test the logic on checking log size limitation.