perf: logger performance optimization (#219)

* perf: logger performance optimization

Only pay the cost of formatting if the log is not filtered.

* doc: add example

* Update example_test.go

ExampleWithLevel

Co-authored-by: Trock <35254251+GGXXLL@users.noreply.github.com>

Author: Reasno

logging/example_test.go

@@ -2,6 +2,7 @@ package logging_test
 
 import (
 	"context"
+	"fmt"
 
 	"github.com/DoNewsCode/core/ctxmeta"
 	"github.com/DoNewsCode/core/logging"
@@ -27,7 +28,23 @@ func ExampleWithLevel() {
 	levelLogger := logging.WithLevel(logger)
 	levelLogger.Info("hello")
 	// Output:
-	// {"caller":"example_test.go:28","level":"info","msg":"hello"}
+	// {"caller":"example_test.go:29","level":"info","msg":"hello"}
+}
+
+func Example_sprintf() {
+	logger := logging.NewLogger("json")
+	// Set log level to info
+	logger = level.NewFilter(logger, level.AllowInfo())
+	levelLogger := logging.WithLevel(logger)
+
+	// Let's try to log some debug messages. They are filtered by log level, so you should see no output.
+	// The cost of fmt.Sprintf is paid event if the log is filtered out. This sometimes can be a huge performance downside.
+	levelLogger.Debugw("record some data", "data", fmt.Sprintf("%+v", []int{1, 2, 3}))
+	// Or better, we can use logging.Sprintf to avoid the cost if the log is not actually written to the output.
+	levelLogger.Debugw("record some data", "data", logging.Sprintf("%+v", []int{1, 2, 3}))
+
+	// Output:
+	//
 }
 
 func ExampleWithContext() {

logging/log.go

@@ -19,7 +19,6 @@ package logging
 
 import (
 	"context"
-	"fmt"
 	"os"
 	"strings"
 
@@ -141,23 +140,19 @@ type levelLogger struct {
 }
 
 func (l levelLogger) Debugf(s string, i ...interface{}) {
-	s = fmt.Sprintf(s, i...)
-	_ = level.Debug(l).Log("msg", s)
+	_ = level.Debug(l).Log("msg", Sprintf(s, i...))
 }
 
 func (l levelLogger) Infof(s string, i ...interface{}) {
-	s = fmt.Sprintf(s, i...)
-	_ = level.Info(l).Log("msg", s)
+	_ = level.Info(l).Log("msg", Sprintf(s, i...))
 }
 
 func (l levelLogger) Warnf(s string, i ...interface{}) {
-	s = fmt.Sprintf(s, i...)
-	_ = level.Warn(l).Log("msg", s)
+	_ = level.Warn(l).Log("msg", Sprintf(s, i...))
 }
 
 func (l levelLogger) Errf(s string, i ...interface{}) {
-	s = fmt.Sprintf(s, i...)
-	_ = level.Error(l).Log("msg", s)
+	_ = level.Error(l).Log("msg", Sprintf(s, i...))
 }
 
 func (l levelLogger) Debugw(s string, fields ...interface{}) {
@@ -181,19 +176,19 @@ func (l levelLogger) Errw(s string, fields ...interface{}) {
 }
 
 func (l levelLogger) Debug(args ...interface{}) {
-	_ = level.Debug(l).Log("msg", fmt.Sprint(args...))
+	_ = level.Debug(l).Log("msg", Sprint(args...))
 }
 
 func (l levelLogger) Info(args ...interface{}) {
-	_ = level.Info(l).Log("msg", fmt.Sprint(args...))
+	_ = level.Info(l).Log("msg", Sprint(args...))
 }
 
 func (l levelLogger) Warn(args ...interface{}) {
-	_ = level.Warn(l).Log("msg", fmt.Sprint(args...))
+	_ = level.Warn(l).Log("msg", Sprint(args...))
 }
 
 func (l levelLogger) Err(args ...interface{}) {
-	_ = level.Error(l).Log("msg", fmt.Sprint(args...))
+	_ = level.Error(l).Log("msg", Sprint(args...))
 }
 
 // WithLevel decorates the logger and returns a contract.LevelLogger.

logging/log_test.go

@@ -70,3 +70,35 @@ func TestSpanLogger(t *testing.T) {
 
 	assert.Equal(t, []interface{}{"foo", "bar", "baz", "qux"}, mock.received)
 }
+
+type mockValue struct{}
+
+func (m mockValue) String() string {
+	// potentially expensive, but the cost is avoided because we have set a higher log level.
+	panic("should not reach here")
+}
+
+func TestPerformanceOptimization(t *testing.T) {
+	var buf bytes.Buffer
+	for _, c := range []struct {
+		name   string
+		logger log.Logger
+	}{
+		{
+			"json",
+			log.NewJSONLogger(&buf),
+		},
+		{
+			"logfmt",
+			log.NewLogfmtLogger(&buf),
+		},
+	} {
+		t.Run(c.name, func(t *testing.T) {
+			l := level.NewFilter(c.logger, LevelFilter("error"))
+			ll := WithLevel(l)
+			ll.Debug(mockValue{})
+			ll.Debugw("bar", "foo", mockValue{})
+			ll.Debugf("%s", mockValue{})
+		})
+	}
+}

logging/sprintf.go

@@ -0,0 +1,38 @@
+package logging
+
+import "fmt"
+
+type sprintf struct {
+	format string
+	args   []interface{}
+}
+
+// String returns the formatted string value using fmt.Sprintf.
+func (s sprintf) String() string {
+	return fmt.Sprintf(s.format, s.args...)
+}
+
+// Sprintf returns a log entry that is formatted using fmt.Sprintf just before
+// writing to the output. This is more desirable than using fmt.Sprintf from the
+// caller's end because the cost of formatting can be avoided if the log is
+// filtered, for example, by log level.
+func Sprintf(format string, args ...interface{}) fmt.Stringer {
+	return sprintf{format: format, args: args}
+}
+
+type sprint struct {
+	args []interface{}
+}
+
+// String returns the formatted string value using fmt.Sprint.
+func (s sprint) String() string {
+	return fmt.Sprint(s.args...)
+}
+
+// Sprint returns a log entry that is formatted using fmt.Sprint just before
+// writing to the output. This is more desirable than using fmt.Sprint from the
+// caller's end because the cost of formatting can be avoided if the log is
+// filtered, for example, by log level.
+func Sprint(args ...interface{}) fmt.Stringer {
+	return sprint{args: args}
+}