From 1a1367cc64e28f8bf3dcc04cd74010cc67bdd57d Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 25 Nov 2022 12:43:34 +0100 Subject: [PATCH] buffer: use sync.Pool MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This simplifies the code. Instead of different instances, the package now maintains a global pool. This makes the text logger struct a bit smaller and thus cheaper to copy in the With* functions. Performance is about the same as before: name old time/op new time/op delta Header-36 1.68µs ± 7% 1.62µs ± 6% ~ (p=0.246 n=5+5) HeaderWithDir-36 1.63µs ± 6% 1.59µs ± 6% ~ (p=0.690 n=5+5) name old alloc/op new alloc/op delta Header-36 216B ± 0% 216B ± 0% ~ (all equal) HeaderWithDir-36 216B ± 0% 216B ± 0% ~ (all equal) name old allocs/op new allocs/op delta Header-36 2.00 ± 0% 2.00 ± 0% ~ (all equal) HeaderWithDir-36 2.00 ± 0% 2.00 ± 0% ~ (all equal) The text logger didn't actually return the buffer. Now it does. --- internal/buffer/buffer.go | 40 +++++++++------------------------------ klog.go | 29 ++++++++++++---------------- klog_test.go | 4 ++-- textlogger/textlogger.go | 19 +++++++++---------- 4 files changed, 32 insertions(+), 60 deletions(-) diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go index ac88682a2..d53b49da3 100644 --- a/internal/buffer/buffer.go +++ b/internal/buffer/buffer.go @@ -40,44 +40,22 @@ type Buffer struct { next *Buffer } -// Buffers manages the reuse of individual buffer instances. It is thread-safe. -type Buffers struct { - // mu protects the free list. It is separate from the main mutex - // so buffers can be grabbed and printed to without holding the main lock, - // for better parallelization. - mu sync.Mutex - - // freeList is a list of byte buffers, maintained under mu. - freeList *Buffer +var buffers = sync.Pool{ + New: func() interface{} { + return new(Buffer) + }, } // GetBuffer returns a new, ready-to-use buffer. -func (bl *Buffers) GetBuffer() *Buffer { - bl.mu.Lock() - b := bl.freeList - if b != nil { - bl.freeList = b.next - } - bl.mu.Unlock() - if b == nil { - b = new(Buffer) - } else { - b.next = nil - b.Reset() - } +func GetBuffer() *Buffer { + b := buffers.Get().(*Buffer) + b.Reset() return b } // PutBuffer returns a buffer to the free list. -func (bl *Buffers) PutBuffer(b *Buffer) { - if b.Len() >= 256 { - // Let big buffers die a natural death. - return - } - bl.mu.Lock() - b.next = bl.freeList - bl.freeList = b - bl.mu.Unlock() +func PutBuffer(b *Buffer) { + buffers.Put(b) } // Some custom tiny helper functions to print the log header efficiently. diff --git a/klog.go b/klog.go index bcf60cf97..c5d98ad38 100644 --- a/klog.go +++ b/klog.go @@ -532,11 +532,6 @@ func (s settings) deepCopy() settings { type loggingT struct { settings - // bufferCache maintains the free list. It uses its own mutex - // so buffers can be grabbed and printed to without holding the main lock, - // for better parallelization. - bufferCache buffer.Buffers - // flushD holds a flushDaemon that frequently flushes log file buffers. // Uses its own mutex. flushD *flushDaemon @@ -664,7 +659,7 @@ func (l *loggingT) header(s severity.Severity, depth int) (*buffer.Buffer, strin // formatHeader formats a log header using the provided file name and line number. func (l *loggingT) formatHeader(s severity.Severity, file string, line int) *buffer.Buffer { - buf := l.bufferCache.GetBuffer() + buf := buffer.GetBuffer() if l.skipHeaders { return buf } @@ -682,8 +677,8 @@ func (l *loggingT) printlnDepth(s severity.Severity, logger *logr.Logger, filter // if logger is set, we clear the generated header as we rely on the backing // logger implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -701,8 +696,8 @@ func (l *loggingT) printDepth(s severity.Severity, logger *logr.Logger, filter L // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -723,8 +718,8 @@ func (l *loggingT) printfDepth(s severity.Severity, logger *logr.Logger, filter // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { format, args = filter.FilterF(format, args) @@ -744,8 +739,8 @@ func (l *loggingT) printWithFileLine(s severity.Severity, logger *logr.Logger, f // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.bufferCache.PutBuffer(buf) - buf = l.bufferCache.GetBuffer() + buffer.PutBuffer(buf) + buf = buffer.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -785,7 +780,7 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s // set log severity by s func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, keysAndValues ...interface{}) { // Only create a new buffer if we don't have one cached. - b := l.bufferCache.GetBuffer() + b := buffer.GetBuffer() // The message is always quoted, even if it contains line breaks. // If developers want multi-line output, they should use a small, fixed // message and put the multi-line output into a value. @@ -796,7 +791,7 @@ func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, serialize.KVListFormat(&b.Buffer, keysAndValues...) l.printDepth(s, logging.logger, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. - l.bufferCache.PutBuffer(b) + buffer.PutBuffer(b) } // redirectBuffer is used to set an alternate destination for the logs @@ -948,7 +943,7 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf timeoutFlush(ExitFlushTimeout) OsExit(255) // C++ uses -1, which is silly because it's anded with 255 anyway. } - l.bufferCache.PutBuffer(buf) + buffer.PutBuffer(buf) if stats := severityStats[s]; stats != nil { atomic.AddInt64(&stats.lines, 1) diff --git a/klog_test.go b/klog_test.go index e6e8922cc..96f337ac5 100644 --- a/klog_test.go +++ b/klog_test.go @@ -623,7 +623,7 @@ func TestLogBacktraceAt(t *testing.T) { func BenchmarkHeader(b *testing.B) { for i := 0; i < b.N; i++ { buf, _, _ := logging.header(severity.InfoLog, 0) - logging.bufferCache.PutBuffer(buf) + buffer.PutBuffer(buf) } } @@ -631,7 +631,7 @@ func BenchmarkHeaderWithDir(b *testing.B) { logging.addDirHeader = true for i := 0; i < b.N; i++ { buf, _, _ := logging.header(severity.InfoLog, 0) - logging.bufferCache.PutBuffer(buf) + buffer.PutBuffer(buf) } } diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 3c6cda645..360888cc8 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -56,19 +56,17 @@ var ( // later release. The behavior of the returned Logger may change. func NewLogger(c *Config) logr.Logger { return logr.New(&tlogger{ - prefix: "", - values: nil, - config: c, - bufferCache: &buffer.Buffers{}, + prefix: "", + values: nil, + config: c, }) } type tlogger struct { - callDepth int - prefix string - values []interface{} - config *Config - bufferCache *buffer.Buffers + callDepth int + prefix string + values []interface{} + config *Config } func copySlice(in []interface{}) []interface{} { @@ -103,7 +101,8 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []interface{}) { // Only create a new buffer if we don't have one cached. - b := l.bufferCache.GetBuffer() + b := buffer.GetBuffer() + defer buffer.PutBuffer(b) // Determine caller. // +1 for this frame, +1 for Info/Error.