logging: do filter last, for improved performance (#3875)

* logging: add a benchmark for debug logging

Since this is normally filtered out, we want low overhead.

* logging: do filter last, for improved performance

Previously the code would find out what line it was on and format the
time, before deciding that the whole log line should be filtered out.
Moving the filter to the end avoids most of this work.

Add a test to validate that the filtering still works.

CHANGELOG.md

@@ -24,6 +24,7 @@
   * `-blocks-storage.tsdb.head-postings-for-matchers-cache-force`
 * [ENHANCEMENT] Ingester: Improved series selection performance when some of the matchers do not match any series. #3827
 * [ENHANCEMENT] Alertmanager: Add new additional template function `tenantID` returning id of the tenant owning the alert. #3758
+* [ENHANCEMENT] Reduce overhead of debug logging when filtered out. #3875
 * [BUGFIX] Log the names of services that are not yet running rather than `unsupported value type` when calling `/ready` and some services are not running. #3625
 * [BUGFIX] Alertmanager: Fix template spurious deletion with relative data dir. #3604
 * [BUGFIX] Security: update prometheus/exporter-toolkit for CVE-2022-46146. #3675

pkg/util/log/log.go

@@ -25,28 +25,33 @@ var (
 // InitLogger initialises the global gokit logger (util_log.Logger) and overrides the
 // default logger for the server.
 func InitLogger(cfg *server.Config) {
-	l := NewDefaultLogger(cfg.LogLevel, cfg.LogFormat)
-	// when using util_log.Logger, skip 3 stack frames.
-	Logger = log.With(l, "caller", log.Caller(3))
-
-	// cfg.Log wraps log function, skip 4 stack frames to get caller information.
-	// this works in go 1.12, but doesn't work in versions earlier.
-	// it will always shows the wrapper function generated by compiler
-	// marked <autogenerated> in old versions.
-	cfg.Log = logging.GoKit(log.With(l, "caller", log.Caller(4)))
+	l := newBasicLogger(cfg.LogLevel, cfg.LogFormat)
+
+	// when using util_log.Logger, skip 5 stack frames.
+	logger := log.With(l, "caller", log.Caller(5))
+	// Must put the level filter last for efficiency.
+	Logger = level.NewFilter(logger, cfg.LogLevel.Gokit)
+
+	// cfg.Log wraps log function, skip 6 stack frames to get caller information.
+	cfg.Log = logging.GoKit(level.NewFilter(log.With(l, "caller", log.Caller(6)), cfg.LogLevel.Gokit))
 }
 
-// NewDefaultLogger creates a new gokit logger with the configured level and format
-func NewDefaultLogger(l logging.Level, format logging.Format) log.Logger {
+func newBasicLogger(l logging.Level, format logging.Format) log.Logger {
 	var logger log.Logger
 	if format.String() == "json" {
 		logger = log.NewJSONLogger(log.NewSyncWriter(os.Stderr))
 	} else {
 		logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
 	}
 
-	// return a Logger without caller information, shouldn't use directly
-	return log.With(level.NewFilter(logger, l.Gokit), "ts", log.DefaultTimestampUTC)
+	// return a Logger without filter or caller information, shouldn't use directly
+	return log.With(logger, "ts", log.DefaultTimestampUTC)
+}
+
+// NewDefaultLogger creates a new gokit logger with the configured level and format
+func NewDefaultLogger(l logging.Level, format logging.Format) log.Logger {
+	logger := newBasicLogger(l, format)
+	return level.NewFilter(log.With(logger, "ts", log.DefaultTimestampUTC), l.Gokit)
 }
 
 // CheckFatal prints an error and exits with error code 1 if err is non-nil

pkg/util/log/log_test.go

@@ -0,0 +1,53 @@
+// SPDX-License-Identifier: AGPL-3.0-only
+
+package log_test
+
+import (
+	"os"
+	"testing"
+	"time"
+
+	gokitlog "github.com/go-kit/log"
+	"github.com/go-kit/log/level"
+	"github.com/weaveworks/common/server"
+
+	"github.com/grafana/mimir/pkg/util/log"
+)
+
+// Check that debug lines are correctly filtered out.
+func ExampleInitLogger() {
+	// Kludge a couple of things so we can do tests repeatably.
+	saveStderr := os.Stderr
+	os.Stderr = os.Stdout
+	saveTimestamp := gokitlog.DefaultTimestampUTC
+	gokitlog.DefaultTimestampUTC = gokitlog.TimestampFormat(
+		func() time.Time { return time.Unix(0, 0) },
+		time.RFC3339Nano,
+	)
+
+	cfg := server.Config{}
+	_ = cfg.LogLevel.Set("info")
+	log.InitLogger(&cfg)
+	level.Info(log.Logger).Log("test", "1")
+	level.Debug(log.Logger).Log("test", "2 - should not print")
+	cfg.Log.Infof("test 3")
+	cfg.Log.Debugf("test 4 - should not print")
+	// Output:
+	// ts=1970-01-01T00:00:00Z caller=log_test.go:31 level=info test=1
+	// ts=1970-01-01T00:00:00Z caller=log_test.go:33 level=info msg="test 3"
+
+	os.Stderr = saveStderr
+	gokitlog.DefaultTimestampUTC = saveTimestamp
+}
+
+// Check the overhead of debug logging which gets filtered out.
+func BenchmarkDebugLog(b *testing.B) {
+	cfg := server.Config{}
+	_ = cfg.LogLevel.Set("info")
+	log.InitLogger(&cfg)
+	b.ResetTimer()
+	dl := level.Debug(log.Logger)
+	for i := 0; i < b.N; i++ {
+		dl.Log("something", "happened")
+	}
+}