From ecb1e88d7c2e92e14a0721f2193fc69be0a3e0a9 Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Fri, 2 Apr 2021 14:20:24 -0700 Subject: [PATCH] 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 | 18 +++++------ funcr/funcr.go | 50 +++++++++++++++--------------- logr.go | 83 +++++++++++++++++++++++++++++++++++--------------- 3 files changed, 91 insertions(+), 60 deletions(-) diff --git a/discard.go b/discard.go index 2bafb13..7d3c684 100644 --- a/discard.go +++ b/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{} diff --git a/funcr/funcr.go b/funcr/funcr.go index 613a66d..923c80e 100644 --- a/funcr/funcr.go +++ b/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{"", 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,15 +310,10 @@ 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 + "/" } @@ -327,11 +321,17 @@ func (l fnlogger) WithName(name string) logr.Logger { 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{} diff --git a/logr.go b/logr.go index 842428b..1d12a3c 100644 --- a/logr.go +++ b/logr.go @@ -140,16 +140,12 @@ 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. // @@ -157,7 +153,7 @@ type Logger interface { // 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 }