json: never call fsync for stdout or stderr

We don't need to worry about data loss once the data has been written to an
output stream. Calling fsync unnecessarily has been the reason for performance
issues in the past.
This commit is contained in:
Patrick Ohly 2022-01-10 16:07:30 +01:00
parent 9a867c555c
commit 25c646cbdd
2 changed files with 36 additions and 11 deletions

View File

@ -17,6 +17,7 @@ limitations under the License.
package logs
import (
"io"
"os"
"time"
@ -83,9 +84,17 @@ type Factory struct{}
var _ registry.LogFormatFactory = Factory{}
func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
stderr := zapcore.Lock(os.Stderr)
// We intentionally avoid all os.File.Sync calls. Output is unbuffered,
// therefore we don't need to flush, and calling the underlying fsync
// would just slow down writing.
//
// The assumption is that logging only needs to ensure that data gets
// written to the output stream before the process terminates, but
// doesn't need to worry about data not being written because of a
// system crash or powerloss.
stderr := zapcore.Lock(AddNopSync(os.Stderr))
if options.JSON.SplitStream {
stdout := zapcore.Lock(os.Stdout)
stdout := zapcore.Lock(AddNopSync(os.Stdout))
size := options.JSON.InfoBufferSize.Value()
if size > 0 {
// Prevent integer overflow.
@ -103,3 +112,16 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
// Write info messages and errors to stderr to prevent mixing with normal program output.
return NewJSONLogger(stderr, nil, nil)
}
// AddNoSync adds a NOP Sync implementation.
func AddNopSync(writer io.Writer) zapcore.WriteSyncer {
return nopSync{Writer: writer}
}
type nopSync struct {
io.Writer
}
func (f nopSync) Sync() error {
return nil
}

View File

@ -33,7 +33,6 @@ import (
"time"
"github.com/go-logr/logr"
"go.uber.org/zap/zapcore"
"k8s.io/component-base/logs"
logsjson "k8s.io/component-base/logs/json"
"k8s.io/klog/v2"
@ -173,10 +172,11 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
klog.SetOutput(out)
defer klog.SetOutput(&output)
}
generateOutput(b, config, out)
generateOutput(b, config, nil, out)
})
b.Run("JSON", func(b *testing.B) {
var logger logr.Logger
var flush func()
var out1, out2 *os.File
if !discard {
var err error
@ -193,7 +193,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
}
b.Run("single-stream", func(b *testing.B) {
if discard {
logger, _ = logsjson.NewJSONLogger(zapcore.AddSync(&output), nil, nil)
logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), nil, nil)
} else {
stderr := os.Stderr
os.Stderr = out1
@ -201,16 +201,16 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
os.Stderr = stderr
}()
options := logs.NewOptions()
logger, _ = logsjson.Factory{}.Create(options.Config.Options)
logger, flush = logsjson.Factory{}.Create(options.Config.Options)
}
klog.SetLogger(logger)
defer klog.ClearLogger()
generateOutput(b, config, out1)
generateOutput(b, config, flush, out1)
})
b.Run("split-stream", func(b *testing.B) {
if discard {
logger, _ = logsjson.NewJSONLogger(zapcore.AddSync(&output), zapcore.AddSync(&output), nil)
logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil)
} else {
stdout, stderr := os.Stdout, os.Stderr
os.Stdout, os.Stderr = out1, out2
@ -219,16 +219,16 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
}()
options := logs.NewOptions()
options.Config.Options.JSON.SplitStream = true
logger, _ = logsjson.Factory{}.Create(options.Config.Options)
logger, flush = logsjson.Factory{}.Create(options.Config.Options)
}
klog.SetLogger(logger)
defer klog.ClearLogger()
generateOutput(b, config, out1, out2)
generateOutput(b, config, flush, out1, out2)
})
})
}
func generateOutput(b *testing.B, config loadGeneratorConfig, files ...*os.File) {
func generateOutput(b *testing.B, config loadGeneratorConfig, flush func(), files ...*os.File) {
msg := strings.Repeat("X", config.messageLength)
err := errors.New("fail")
start := time.Now()
@ -257,6 +257,9 @@ func generateOutput(b *testing.B, config loadGeneratorConfig, files ...*os.File)
}
wg.Wait()
klog.Flush()
if flush != nil {
flush()
}
b.StopTimer()
// Print some information about the result.