WIP: try some perf ideas

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.

discard.go

@@ -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{}

funcr/funcr.go

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

logr.go

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