Speed up debug logging, when filtered out

logging/gokit.go

@@ -17,8 +17,13 @@ func NewGoKitFormat(l Level, f Format) Interface {
 	} else {
 		logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
 	}
+	return addStandardFields(logger, l)
+}
+
+// stand-alone for test purposes
+func addStandardFields(logger log.Logger, l Level) Interface {
+	logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5))
 	logger = level.NewFilter(logger, l.Gokit)
-	logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
 	return gokit{logger}
 }
 
@@ -36,32 +41,52 @@ type gokit struct {
 	log.Logger
 }
 
+// Helper to defer sprintf until it is needed.
+type sprintf struct {
+	format string
+	args   []interface{}
+}
+
+func (s *sprintf) String() string {
+	return fmt.Sprintf(s.format, s.args...)
+}
+
+// Helper to defer sprint until it is needed.
+// Note we don't use Sprintln because the output is passed to go-kit as one value among many on a line
+type sprint struct {
+	args []interface{}
+}
+
+func (s *sprint) String() string {
+	return fmt.Sprint(s.args...)
+}
+
 func (g gokit) Debugf(format string, args ...interface{}) {
-	level.Debug(g.Logger).Log("msg", fmt.Sprintf(format, args...))
+	level.Debug(g.Logger).Log("msg", &sprintf{format: format, args: args})
 }
 func (g gokit) Debugln(args ...interface{}) {
-	level.Debug(g.Logger).Log("msg", fmt.Sprintln(args...))
+	level.Debug(g.Logger).Log("msg", &sprint{args: args})
 }
 
 func (g gokit) Infof(format string, args ...interface{}) {
-	level.Info(g.Logger).Log("msg", fmt.Sprintf(format, args...))
+	level.Info(g.Logger).Log("msg", &sprintf{format: format, args: args})
 }
 func (g gokit) Infoln(args ...interface{}) {
-	level.Info(g.Logger).Log("msg", fmt.Sprintln(args...))
+	level.Info(g.Logger).Log("msg", &sprint{args: args})
 }
 
 func (g gokit) Warnf(format string, args ...interface{}) {
-	level.Warn(g.Logger).Log("msg", fmt.Sprintf(format, args...))
+	level.Warn(g.Logger).Log("msg", &sprintf{format: format, args: args})
 }
 func (g gokit) Warnln(args ...interface{}) {
-	level.Warn(g.Logger).Log("msg", fmt.Sprintln(args...))
+	level.Warn(g.Logger).Log("msg", &sprint{args: args})
 }
 
 func (g gokit) Errorf(format string, args ...interface{}) {
-	level.Error(g.Logger).Log("msg", fmt.Sprintf(format, args...))
+	level.Error(g.Logger).Log("msg", &sprintf{format: format, args: args})
 }
 func (g gokit) Errorln(args ...interface{}) {
-	level.Error(g.Logger).Log("msg", fmt.Sprintln(args...))
+	level.Error(g.Logger).Log("msg", &sprint{args: args})
 }
 
 func (g gokit) WithField(key string, value interface{}) Interface {

logging/gokit_test.go

@@ -0,0 +1,25 @@
+package logging
+
+import (
+	"testing"
+
+	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
+)
+
+func BenchmarkDebugf(b *testing.B) {
+	lvl := Level{Gokit: level.AllowInfo()}
+	g := log.NewNopLogger()
+	logger := addStandardFields(g, lvl)
+	// Simulate the parameters used in middleware/logging.go
+	var (
+		method     = "method"
+		uri        = "https://example.com/foobar"
+		statusCode = 404
+		duration   = 42
+	)
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		logger.Debugf("%s %s (%d) %s", method, uri, statusCode, duration)
+	}
+}