Avoid expensive log.Valuer evaluation for disallowed levels

Signed-off-by: Xiaochao Dong (@damnever) <[email protected]>

CHANGELOG.md

@@ -4,6 +4,7 @@
 * [CHANGE] Alertmanager: Validating new fields on the PagerDuty AM config. #5290
 * [CHANGE] Ingester: Creating label `native-histogram-sample` on the `cortex_discarded_samples_total` to keep track of discarded native histogram samples. #5289
 * [FEATURE] Store Gateway: Add `max_downloaded_bytes_per_request` to limit max bytes to download per store gateway request.
+* [ENHANCEMENT] Log: Avoid expensive log.Valuer evaluation for disallowed levels. #5297
 * [BUGFIX] Ruler: Validate if rule group can be safely converted back to rule group yaml from protobuf message #5265
 * [BUGFIX] Querier: Convert gRPC `ResourceExhausted` status code from store gateway to 422 limit error. #5286
 * [BUGFIX] Alertmanager: Route web-ui requests to the alertmanager distributor when sharding is enabled. #5293

pkg/util/log/log.go

@@ -49,19 +49,16 @@ func init() {
 // InitLogger initialises the global gokit logger (util_log.Logger) and overrides the
 // default logger for the server.
 func InitLogger(cfg *server.Config) {
-	l, err := NewPrometheusLogger(cfg.LogLevel, cfg.LogFormat)
-	if err != nil {
-		panic(err)
-	}
+	l := newLoggerWithFormat(cfg.LogFormat)
 
-	// when use util_log.Logger, skip 3 stack frames.
-	Logger = log.With(l, "caller", log.Caller(3))
+	// when use util_log.Logger, skip 6 stack frames.
+	Logger = newPrometheusLoggerFrom(l, cfg.LogLevel, "caller", log.Caller(6))
 
-	// cfg.Log wraps log function, skip 4 stack frames to get caller information.
+	// cfg.Log wraps log function, skip 7 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)))
+	cfg.Log = logging.GoKit(newPrometheusLoggerFrom(l, cfg.LogLevel, "caller", log.Caller(7)))
 }
 
 // PrometheusLogger exposes Prometheus counters for each of go-kit's log levels.
@@ -72,24 +69,32 @@ type PrometheusLogger struct {
 // NewPrometheusLogger creates a new instance of PrometheusLogger which exposes
 // Prometheus counters for various log levels.
 func NewPrometheusLogger(l logging.Level, format logging.Format) (log.Logger, error) {
+	logger := newLoggerWithFormat(format)
+	return newPrometheusLoggerFrom(logger, l), nil
+}
+
+func newLoggerWithFormat(format logging.Format) log.Logger {
 	logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
 	if format.String() == "json" {
 		logger = log.NewJSONLogger(log.NewSyncWriter(os.Stderr))
 	}
-	logger = level.NewFilter(logger, LevelFilter(l.String()))
+	return logger
+}
+
+func newPrometheusLoggerFrom(logger log.Logger, logLevel logging.Level, keyvals ...interface{}) log.Logger {
+	// Sort the logger chain to avoid expensive log.Valuer evaluation for disallowed level.
+	// Ref: https://github.com/go-kit/log/issues/14#issuecomment-945038252
+	logger = log.With(logger, "ts", log.DefaultTimestampUTC)
+	logger = log.With(logger, keyvals...)
+	logger = level.NewFilter(logger, LevelFilter(logLevel.String()))
 
 	// Initialise counters for all supported levels:
 	for _, level := range supportedLevels {
 		logMessages.WithLabelValues(level.String())
 	}
-
-	logger = &PrometheusLogger{
+	return &PrometheusLogger{
 		logger: logger,
 	}
-
-	// return a Logger without caller information, shouldn't use directly
-	logger = log.With(logger, "ts", log.DefaultTimestampUTC)
-	return logger, nil
 }
 
 // Log increments the appropriate Prometheus counter depending on the log level.

pkg/util/log/log_test.go

@@ -2,10 +2,14 @@ package log
 
 import (
 	"context"
+	"io"
 	"net/http"
+	"os"
 	"testing"
 
+	"github.com/go-kit/log/level"
 	"github.com/stretchr/testify/require"
+	"github.com/weaveworks/common/server"
 	"google.golang.org/grpc/metadata"
 )
 
@@ -63,3 +67,35 @@ func TestInjectHeadersIntoHTTPRequest(t *testing.T) {
 	require.Equal(t, "ContentsOfTestHeader2", header2[0])
 
 }
+
+func TestInitLogger(t *testing.T) {
+	stderr := os.Stderr
+	r, w, err := os.Pipe()
+	require.NoError(t, err)
+	os.Stderr = w
+	defer func() { os.Stderr = stderr }()
+
+	cfg := &server.Config{}
+	require.NoError(t, cfg.LogLevel.Set("debug"))
+	InitLogger(cfg)
+
+	level.Debug(Logger).Log("hello", "world")
+	cfg.Log.Debugf("%s %s", "hello", "world")
+
+	require.NoError(t, w.Close())
+	logs, err := io.ReadAll(r)
+	require.NoError(t, err)
+	require.Contains(t, string(logs), "caller=log_test.go:82 level=debug hello=world")
+	require.Contains(t, string(logs), "caller=log_test.go:83 level=debug msg=\"hello world\"")
+}
+
+func BenchmarkDisallowedLogLevels(b *testing.B) {
+	cfg := &server.Config{}
+	require.NoError(b, cfg.LogLevel.Set("warn"))
+	InitLogger(cfg)
+
+	for i := 0; i < b.N; i++ {
+		level.Info(Logger).Log("hello", "world", "number", i)
+		level.Debug(Logger).Log("hello", "world", "number", i)
+	}
+}