Skip to content

Commit

Permalink
buffer: use sync.Pool
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
pohly authored and dims committed Jan 19, 2023
1 parent ff4f80f commit 1a1367c
Show file tree
Hide file tree
Showing 4 changed files with 32 additions and 60 deletions.
40 changes: 9 additions & 31 deletions internal/buffer/buffer.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
29 changes: 12 additions & 17 deletions klog.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
}
Expand All @@ -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)
Expand All @@ -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)
Expand All @@ -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)
Expand All @@ -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)
Expand Down Expand Up @@ -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.
Expand All @@ -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
Expand Down Expand Up @@ -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)
Expand Down
4 changes: 2 additions & 2 deletions klog_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -623,15 +623,15 @@ 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)
}
}

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)
}
}

Expand Down
19 changes: 9 additions & 10 deletions textlogger/textlogger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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{} {
Expand Down Expand Up @@ -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.
Expand Down

0 comments on commit 1a1367c

Please sign in to comment.