simplified, self-contained Logger

[pohly]

/kind feature

Describe the solution you'd like

In Kubernetes, we currently use the traditional klog output handling code, with all the cruft that has accumulated there. Since the deprecation of klog flags, none of that code does anything anymore, but we also cannot remove it because it is part of klog/v2.

What would be useful for Kubernetes would be a klogr Logger which:

• has its own, simple output handling, with support for buffering of info messages just as in zapr (new feature)
• support vmodule (feature parity)
• same output format (no usability changes)

The restructuring of klog into separate packages for vmodule and formatting should make the implementation of such a logger relatively easy.

[dims]

can't believe it took us this long to get to the point where we can talk about this :)

[pohly]

/assign

A first implementation is showing signs of life...

[pohly]

Actually, there is already k8s.io/klog/v2/textlogger. I just reimplemented it in a slightly different (and better) way... 😅

I'll update it instead of adding a new logger.

[pohly]

The solution that I came up with installs textlogger with klog.SetLoggerWithOptions(logger, klog.ContextualLogger(contextualLoggingEnabled)). That means that klog.Background().Info("msg") will be handled entirely by the textlogger. Together with some optimizations, that increases encoding performance (= format, then write to io.Discard) for structured logging (unit is messages/s):

Encoding/kind-worker-kubelet/structured-36          318k ± 1%      364k ± 0%   +14.52%

But this approach has one drawback: a traditional klog.Infof first gets handled by klog, then the textlogger's Info is called to output the message string. The result is a drop in performance:

Encoding/kind-worker-kubelet/printf-36              642k ± 0%      228k ± 0%   -64.42%

In other words, such a switch only makes sense once most of the log calls in a component have been converted to structured logging.

[pohly]

Writing with an info buffer definitely improves performance:

Writing/tmp-files/structured/single-stream-36          106k ± 0%      132k ± 1%   +25.01%
Writing/tmp-files/structured/split-stream-36           105k ± 1%      245k ± 1%  +132.94%

[pohly]

PR #362 contains the changes for split output. The buffering of the info stream is implemented in the io.Writer used by k8s.io/component-base/logs. I don't have a PR open for that yet (depends on kubernetes/kubernetes#114609).

[pohly]

PR #362 contains the changes for split output.

Actually, I had used a different approach for that there: by looking at the first byte of a write, the io.Writer implementation can determine whether it is an info or error message and redirect the write accordingly. No changes needed in klog for that...