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

Remove JSON logging performance regression #107035

Merged
merged 1 commit into from Dec 15, 2021
Merged

Remove JSON logging performance regression #107035

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
45 changes: 10 additions & 35 deletions staging/src/k8s.io/component-base/logs/json/json.go
View file
Open in desktop
Expand Up @@ -40,28 +40,16 @@ func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer) (logr.Logger, fu
encoder := zapcore.NewJSONEncoder(encoderConfig)
var core zapcore.Core
if errorStream == nil {
core = zapcore.NewCore(encoder, zapcore.AddSync(infoStream), zapcore.Level(-127))
core = zapcore.NewCore(encoder, infoStream, zapcore.Level(-127))
} else {
// Set up writing of error messages to stderr and info messages
// to stdout. Info messages get optionally buffered and flushed
// - through klog.FlushLogs -> zapr Flush -> zap Sync
// - when an error gets logged
//
// The later is important when both streams get merged into a single
// stream by the consumer (same console for a command line tool, pod
// log for a container) because without it, messages get reordered.
flushError := writeWithFlushing{
WriteSyncer: errorStream,
other: infoStream,
}
Copy link
Contributor

Choose a reason for hiding this comment

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

Removing this is a loss of functionality that isn't described explicitly. Are you sure that this is better? If you remove the code, the comment also would need to be updated.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'm looking into implementing buffer flushing instead of syncing whole pipeline, however I don't think this would achieve proper ordering as described in comment. I don't think that keeping logs ordered was ever goal, it's good property for human readable logs. It's good that we maintain this property by default, however when splitting stream is enabled I don't see a reason to sacrifice throughput as most log processing solutions don't care about order. It's even expected that logs are processed out of order, for example I have seen this behavior in Fluentbit.

Copy link
Contributor

Choose a reason for hiding this comment

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

I was thinking of the case where stdout and stderr get redirected into the same file or pipe and then get processed. But you are probably right, what matters in the end is just the time stamp attached to each message, not the order. So dropping the syncing between the two streams can indeed be dropped if we can't make it faster.

That it is this slow is a bit surprising. I'd like to understand better where the slowdown really comes from (mutex contention? slow Sync()).

Copy link
Contributor

Choose a reason for hiding this comment

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

Another thought: when both streams go to the same file descriptor, can we guarantee that log messages are written atomically?

Otherwise we could end up with interleaved log messages (<start of message 1><message 2><end of message 1>).

Copy link
Contributor

Choose a reason for hiding this comment

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

writeWithFlushing didn't handle that because no lock is held while writing.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Another thought: when both streams go to the same file descriptor, can we guarantee that log messages are written atomically?

I don't think so. It's up to log consumer to merge streams, if it not able to keep up with producer generating to much data to one of the streams it is expected to interleave streams to avoid starving the other one. This is what I expect to happen from bash pipe merging, there will be no interleaving as long as volume of logs is reasonable, however it cannot guarantee this in high load scenarios.

The only way to handle it would be to have application log aware merger that will be able to recognize when single log message starts and end. We technically could implement such functionality in kube-log-runner, however I don't think it's worth it. As splitting streams is an optional feature, it's much more reasonable to document this behavior so users are aware of this behavior when enabling this feature.

Copy link
Contributor

Choose a reason for hiding this comment

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

So we document that split stream assumes independent streams. Works for me.

I'm wondering whether we then want another mode: single stream with buffering of info messages. That might provide some performance benefit (to be measured) at the risk of loosing in-memory messages in case of a crash.

highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
return lvl >= zapcore.ErrorLevel
})
lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
return lvl < zapcore.ErrorLevel
})
core = zapcore.NewTee(
zapcore.NewCore(encoder, flushError, highPriority),
zapcore.NewCore(encoder, errorStream, highPriority),
zapcore.NewCore(encoder, infoStream, lowPriority),
)
}
Expand Down Expand Up @@ -92,36 +80,23 @@ type Factory struct{}
var _ registry.LogFormatFactory = Factory{}

func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
stderr := zapcore.Lock(os.Stderr)
if options.JSON.SplitStream {
// stdout for info messages, stderr for errors.
infoStream := zapcore.Lock(os.Stdout)
stdout := zapcore.Lock(os.Stdout)
size := options.JSON.InfoBufferSize.Value()
if size > 0 {
// Prevent integer overflow.
if size > 2*1024*1024*1024 {
size = 2 * 1024 * 1024 * 1024
}
infoStream = &zapcore.BufferedWriteSyncer{
WS: infoStream,
stdout = &zapcore.BufferedWriteSyncer{
WS: stdout,
Size: int(size),
}
}
return NewJSONLogger(infoStream, zapcore.Lock(os.Stderr))
// stdout for info messages, stderr for errors.
return NewJSONLogger(stdout, stderr)
}
// The default is to write to stderr (same as in klog's text output,
// doesn't get mixed with normal program output).
out := zapcore.Lock(os.Stderr)
return NewJSONLogger(out, out)
Copy link
Contributor

Choose a reason for hiding this comment

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

This part is clearly a bug. It's the result of a last-minute API change of NewJSONLogger from "pass two identical streams to avoid split streams" to "pass nil as second stream".

So passing nil here achieves the stated goal of this commit and PR. However, explaining that in the commit message and PR description would be useful.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Will do

}

// writeWithFlushing is a wrapper around an output stream which flushes another
// output stream before each write.
type writeWithFlushing struct {
zapcore.WriteSyncer
other zapcore.WriteSyncer
}

func (f writeWithFlushing) Write(bs []byte) (int, error) {
f.other.Sync()
return f.WriteSyncer.Write(bs)
// Write info messages and errors to stderr to prevent mixing with normal program output.
return NewJSONLogger(stderr, nil)
}