Skip to content

Commit

Permalink
WIP: try some perf ideas
Browse files Browse the repository at this point in the history
Before:
```
$ go test -bench='.' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkInfoOneArg-6        	  483949	      2420 ns/op
BenchmarkInfoSeveralArgs-6   	  359826	      3302 ns/op
BenchmarkV0Info-6            	  352570	      3399 ns/op
BenchmarkV9Info-6            	 9096120	       130.3 ns/op
BenchmarkError-6             	  366549	      3280 ns/op
BenchmarkWithValues-6        	 9936550	       120.1 ns/op
BenchmarkWithName-6          	22592770	        53.38 ns/op
```

After:
```
$ go test -bench='.' ./benchmark/
goos: linux
goarch: amd64
pkg: github.com/go-logr/logr/benchmark
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkInfoOneArg-6        	  514122	      2291 ns/op
BenchmarkInfoSeveralArgs-6   	  380796	      3153 ns/op
BenchmarkV0Info-6            	  376472	      3150 ns/op
BenchmarkV9Info-6            	15167118	        79.13 ns/op
BenchmarkError-6             	  358990	      3336 ns/op
BenchmarkWithValues-6        	 7674392	       155.9 ns/op
BenchmarkWithName-6          	23391848	        50.33 ns/op
```

Logs that actually write are dominated by the cost of preparing the
message.  Logs which do not write (e.g. `V(9)`) are much faster here
(thog glog raw is much faster still).  The main difference is the
variadic slice setup.  This is a candidate for Go to optimize - it now
knows that the args are only used inside the conditional (`Enabled()`),
and when that path is not executed, it can elide that work.
  • Loading branch information
thockin committed Apr 21, 2021
1 parent 5612240 commit 84e8b50
Show file tree
Hide file tree
Showing 3 changed files with 91 additions and 60 deletions.
18 changes: 7 additions & 11 deletions discard.go
Original file line number Diff line number Diff line change
Expand Up @@ -19,33 +19,29 @@ package logr
// Discard returns a valid Logger that discards all messages logged to it.
// It can be used whenever the caller is not interested in the logs.
func Discard() Logger {
return DiscardLogger{}
return Logger{0, DiscardLogger{}}
}

// DiscardLogger is a Logger that discards all messages.
type DiscardLogger struct{}

func (l DiscardLogger) Enabled() bool {
func (l DiscardLogger) Enabled(int) bool {
return false
}

func (l DiscardLogger) Info(msg string, keysAndValues ...interface{}) {
func (l DiscardLogger) Info(int, string, ...interface{}) {
}

func (l DiscardLogger) Error(err error, msg string, keysAndValues ...interface{}) {
func (l DiscardLogger) Error(error, string, ...interface{}) {
}

func (l DiscardLogger) V(level int) Logger {
func (l DiscardLogger) WithValues(...interface{}) LogSink {
return l
}

func (l DiscardLogger) WithValues(keysAndValues ...interface{}) Logger {
return l
}

func (l DiscardLogger) WithName(name string) Logger {
func (l DiscardLogger) WithName(string) LogSink {
return l
}

// Verify that it actually implements the interface
var _ Logger = DiscardLogger{}
var _ LogSink = DiscardLogger{}
50 changes: 25 additions & 25 deletions funcr/funcr.go
Original file line number Diff line number Diff line change
Expand Up @@ -33,14 +33,15 @@ import (

// New returns a logr.Logger which is implemented by a function.
func New(fn func(prefix, args string), opts Options) logr.Logger {
return fnlogger{
level: 0,
fnl := fnlogger{
prefix: "",
values: nil,
depth: 0,
write: fn,
logCaller: opts.LogCaller,
verbosity: opts.Verbosity,
}
return logr.New(0, fnl)
}

type Options struct {
Expand All @@ -63,9 +64,9 @@ const (
)

type fnlogger struct {
level int
prefix string
values []interface{}
depth int
write func(prefix, args string)
logCaller MessageClass
verbosity int
Expand Down Expand Up @@ -269,29 +270,27 @@ func (l fnlogger) caller() callerID {
// +1 for this frame, +1 for logr itself.
// FIXME: Maybe logr should offer a clue as to how many frames are
// needed here? Or is it part of the contract to LogSinks?
_, file, line, ok := runtime.Caller(framesToCaller() + 2)
_, file, line, ok := runtime.Caller(framesToCaller() + l.depth + 2)
if !ok {
return callerID{"<unknown>", 0}
}
return callerID{filepath.Base(file), line}
}

func (l fnlogger) Enabled() bool {
return l.level <= l.verbosity
func (l fnlogger) Enabled(level int) bool {
return level <= l.verbosity
}

func (l fnlogger) Info(msg string, kvList ...interface{}) {
if l.Enabled() {
args := make([]interface{}, 0, 64) // using a constant here impacts perf
if l.logCaller == All || l.logCaller == Info {
args = append(args, "caller", l.caller())
}
args = append(args, "level", l.level, "msg", msg)
args = append(args, l.values...)
args = append(args, kvList...)
argsStr := flatten(args...)
l.write(l.prefix, argsStr)
func (l fnlogger) Info(level int, msg string, kvList ...interface{}) {
args := make([]interface{}, 0, 64) // using a constant here impacts perf
if l.logCaller == All || l.logCaller == Info {
args = append(args, "caller", l.caller())
}
args = append(args, "level", level, "msg", msg)
args = append(args, l.values...)
args = append(args, kvList...)
argsStr := flatten(args...)
l.write(l.prefix, argsStr)
}

func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
Expand All @@ -311,27 +310,28 @@ func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
l.write(l.prefix, argsStr)
}

func (l fnlogger) V(level int) logr.Logger {
l.level += level
return l
}

// WithName returns a new Logger with the specified name appended. funcr
// uses '/' characters to separate name elements. Callers should not pass '/'
// in the provided name string, but this library does not actually enforce that.
func (l fnlogger) WithName(name string) logr.Logger {
func (l fnlogger) WithName(name string) logr.LogSink {
if len(l.prefix) > 0 {
l.prefix = l.prefix + "/"
}
l.prefix += name
return l
}

func (l fnlogger) WithValues(kvList ...interface{}) logr.Logger {
func (l fnlogger) WithValues(kvList ...interface{}) logr.LogSink {
// Three slice args forces a copy.
n := len(l.values)
l.values = append(l.values[:n:n], kvList...)
return l
}

var _ logr.Logger = fnlogger{}
func (l fnlogger) WithCallDepth(depth int) logr.LogSink {
l.depth += depth
return l
}

var _ logr.LogSink = fnlogger{}
var _ logr.CallDepthLogSink = fnlogger{}
83 changes: 59 additions & 24 deletions logr.go
Original file line number Diff line number Diff line change
Expand Up @@ -140,24 +140,20 @@ import (
"context"
)

// TODO: consider adding back in format strings if they're really needed
// TODO: consider other bits of zap/zapcore functionality like ObjectMarshaller (for arbitrary objects)
// TODO: consider other bits of glog functionality like Flush, OutputStats

// Logger represents the ability to log messages, both errors and not.
type Logger interface {
// Enabled tests whether this Logger is enabled. For example, commandline
// LogSink represents the ability to log messages, both errors and not.
type LogSink interface {
// Enabled tests whether this LogSink is enabled. For example, commandline
// flags might be used to set the logging verbosity and disable some info
// logs.
Enabled() bool
Enabled(level int) bool

// Info logs a non-error message with the given key/value pairs as context.
//
// The msg argument should be used to add some constant description to
// the log line. The key/value pairs can then be used to add additional
// variable information. The key/value pairs should alternate string
// keys and arbitrary values.
Info(msg string, keysAndValues ...interface{})
Info(level int, msg string, keysAndValues ...interface{})

// Error logs an error, with the given message and key/value pairs as context.
// It functions similarly to calling Info with the "error" named value, but may
Expand All @@ -169,22 +165,62 @@ type Logger interface {
// triggered this log line, if present.
Error(err error, msg string, keysAndValues ...interface{})

// V returns an Logger value for a specific verbosity level, relative to
// this Logger. In other words, V values are additive. V higher verbosity
// level means a log message is less important. It's illegal to pass a log
// level less than zero.
V(level int) Logger

// WithValues adds some key-value pairs of context to a logger.
// See Info for documentation on how key/value pairs work.
WithValues(keysAndValues ...interface{}) Logger
WithValues(keysAndValues ...interface{}) LogSink

// WithName adds a new element to the logger's name.
// Successive calls with WithName continue to append
// suffixes to the logger's name. It's strongly recommended
// that name segments contain only letters, digits, and hyphens
// (see the package documentation for more information).
WithName(name string) Logger
WithName(name string) LogSink
}

func New(level int, sink LogSink) Logger {
return Logger{
level: level,
sink: sink,
}
}

// Logger is a concrete type, for performance reasons, but all the real work is
// passed on to a LogSink. Implementations of LogSink should provide their own
// constructors thsat return Logger, not LogSink.
type Logger struct {
level int
sink LogSink
}

func (l Logger) Enabled() bool {
return l.sink.Enabled(l.level)
}

func (l Logger) Info(msg string, keysAndValues ...interface{}) {
if l.Enabled() {
l.sink.Info(l.level, msg, keysAndValues...)
}
}

func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) {
if l.Enabled() {
l.sink.Error(err, msg, keysAndValues...)
}
}

func (l Logger) V(level int) Logger {
l.level += level
return l
}

func (l Logger) WithValues(keysAndValues ...interface{}) Logger {
l.sink = l.sink.WithValues(keysAndValues...)
return l
}

func (l Logger) WithName(name string) Logger {
l.sink = l.sink.WithName(name)
return l
}

// InfoLogger provides compatibility with code that relies on the v0.1.0
Expand All @@ -204,7 +240,8 @@ func FromContext(ctx context.Context) Logger {
return v
}

return nil
//FIXME: what to do here? Could switch to pointers, but yuck?
return Logger{}
}

// FromContextOrDiscard returns a Logger constructed from ctx or a Logger
Expand Down Expand Up @@ -232,15 +269,13 @@ func NewContext(ctx context.Context, l Logger) context.Context {
//
// This is an optional interface and implementations are not required to
// support it.
type CallDepthLogger interface {
Logger

type CallDepthLogSink interface {
// WithCallDepth returns a Logger that will offset the call stack by the
// specified number of frames when logging call site information. If depth
// is 0 the attribution should be to the direct caller of this method. If
// depth is 1 the attribution should skip 1 call frame, and so on.
// Successive calls to this are additive.
WithCallDepth(depth int) Logger
WithCallDepth(depth int) LogSink
}

// WithCallDepth returns a Logger that will offset the call stack by the
Expand All @@ -259,8 +294,8 @@ type CallDepthLogger interface {
// Callers which care about whether this was supported or not should test for
// CallDepthLogger support themselves.
func WithCallDepth(logger Logger, depth int) Logger {
if decorator, ok := logger.(CallDepthLogger); ok {
return decorator.WithCallDepth(depth)
if decorator, ok := logger.sink.(CallDepthLogSink); ok {
logger.sink = decorator.WithCallDepth(depth)
}
return logger
}

0 comments on commit 84e8b50

Please sign in to comment.