Improve loggers performance (#5452)

* Add benchmarks for current code

* Optimise logging

internal/slogadapter/gokit.go

@@ -19,25 +19,58 @@ type slogAdapter struct {
 	h slog.Handler
 }
 
+var (
+	_ log.Logger = (*slogAdapter)(nil)
+)
+
+// Enabled implements logging.EnabledAware interface.
+func (sa slogAdapter) Enabled(ctx context.Context, l slog.Level) bool {
+	return sa.h.Enabled(ctx, l)
+}
+
 func (sa slogAdapter) Log(kvps ...interface{}) error {
-	// We don't know what the log level or message are yet, so we set them to
-	// defaults until we iterate through kvps.
-	//
+	// Find the log level first, starting with the default.
+	recordLevel := slog.LevelInfo
+	for i := 0; i < len(kvps); i += 2 {
+		if kvps[i] == level.Key() {
+			if i+1 < len(kvps) {
+				value := kvps[i+1]
+				levelValue, _ := value.(level.Value)
+				switch levelValue {
+				case level.DebugValue():
+					recordLevel = slog.LevelDebug
+				case level.InfoValue():
+					recordLevel = slog.LevelInfo
+				case level.WarnValue():
+					recordLevel = slog.LevelWarn
+				case level.ErrorValue():
+					recordLevel = slog.LevelError
+				}
+				break
+			}
+		}
+	}
+
+	// Do not build the record if the level is not enabled.
+	if !sa.h.Enabled(context.Background(), recordLevel) {
+		return nil
+	}
+
 	// Since there's a pattern of wrapping loggers at different depths in go-kit,
 	// we can't consistently know who the caller is, so we set no value for pc
 	// here.
-	rec := slog.NewRecord(time.Now(), slog.LevelInfo, "", 0)
+	rec := slog.NewRecord(time.Now(), recordLevel, "", 0)
 
 	for i := 0; i < len(kvps); i += 2 {
 		var key, value any
 
 		if i+1 < len(kvps) {
-			key = kvps[i+0]
+			key = kvps[i]
 			value = kvps[i+1]
 		} else {
 			// Mismatched pair
 			key = "!BADKEY"
-			value = kvps[i+0]
+			value = kvps[i]
 		}
 
 		if key == "msg" || key == "message" {
@@ -46,19 +79,7 @@ func (sa slogAdapter) Log(kvps ...interface{}) error {
 		}
 
 		if key == level.Key() {
-			levelValue, _ := value.(level.Value)
-
-			switch levelValue {
-			case level.DebugValue():
-				rec.Level = slog.LevelDebug
-			case level.InfoValue():
-				rec.Level = slog.LevelInfo
-			case level.WarnValue():
-				rec.Level = slog.LevelWarn
-			case level.ErrorValue():
-				rec.Level = slog.LevelError
-			}
-
+			// Already handled
 			continue
 		}
 
@@ -68,8 +89,5 @@ func (sa slogAdapter) Log(kvps ...interface{}) error {
 		})
 	}
 
-	if !sa.h.Enabled(context.Background(), rec.Level) {
-		return nil
-	}
 	return sa.h.Handle(context.Background(), rec)
 }

pkg/flow/logging/level/level.go

@@ -0,0 +1,51 @@
+package level
+
+import (
+	"context"
+	"log/slog"
+
+	"github.com/go-kit/log"
+	"github.com/grafana/agent/pkg/flow/logging"
+)
+
+const (
+	levelKey = "level"
+)
+
+// Error returns a logger that includes a Key/ErrorValue pair.
+func Error(logger log.Logger) log.Logger {
+	return toLevel(logger, "error", slog.LevelError)
+}
+
+// Warn returns a logger that includes a Key/WarnValue pair.
+func Warn(logger log.Logger) log.Logger {
+	return toLevel(logger, "warn", slog.LevelWarn)
+}
+
+// Info returns a logger that includes a Key/InfoValue pair.
+func Info(logger log.Logger) log.Logger {
+	return toLevel(logger, "info", slog.LevelInfo)
+}
+
+// Debug returns a logger that includes a Key/DebugValue pair.
+func Debug(logger log.Logger) log.Logger {
+	return toLevel(logger, "debug", slog.LevelDebug)
+}
+
+func toLevel(logger log.Logger, level string, slogLevel slog.Level) log.Logger {
+	switch l := logger.(type) {
+	case logging.EnabledAware:
+		if !l.Enabled(context.Background(), slogLevel) {
+			return disabledLogger
+		}
+	}
+	return log.WithPrefix(logger, levelKey, level)
+}
+
+var disabledLogger = &noopLogger{}
+
+type noopLogger struct{}
+
+func (d *noopLogger) Log(_ ...interface{}) error {
+	return nil
+}

pkg/flow/logging/logger.go

@@ -1,6 +1,7 @@
 package logging
 
 import (
+	"context"
 	"fmt"
 	"io"
 	"log/slog"
@@ -13,6 +14,10 @@ import (
 	"github.com/prometheus/common/model"
 )
 
+type EnabledAware interface {
+	Enabled(context.Context, slog.Level) bool
+}
+
 // Logger is the logging subsystem of Flow. It supports being dynamically
 // updated at runtime.
 type Logger struct {
@@ -24,6 +29,13 @@ type Logger struct {
 	handler *handler       // Handler which handles logs.
 }
 
+var _ EnabledAware = (*Logger)(nil)
+
+// Enabled implements EnabledAware interface.
+func (l *Logger) Enabled(ctx context.Context, level slog.Level) bool {
+	return l.handler.Enabled(ctx, level)
+}
+
 // New creates a New logger with the default log level and format.
 func New(w io.Writer, o Options) (*Logger, error) {
 	var (

pkg/flow/logging/logger_test.go

@@ -0,0 +1,138 @@
+package logging_test
+
+import (
+	"fmt"
+	"io"
+	"log/slog"
+	"testing"
+	"time"
+
+	gokitlevel "github.com/go-kit/log/level"
+	"github.com/grafana/agent/pkg/flow/logging"
+	flowlevel "github.com/grafana/agent/pkg/flow/logging/level"
+	"github.com/stretchr/testify/require"
+)
+
+/* Most recent performance results on M2 Macbook Air:
+$ go test -count=1 -benchmem ./pkg/flow/logging -run ^$ -bench BenchmarkLogging_
+goos: darwin
+goarch: arm64
+pkg: github.com/grafana/agent/pkg/flow/logging
+BenchmarkLogging_NoLevel_Prints-8             	  797337	      1492 ns/op	     368 B/op	      11 allocs/op
+BenchmarkLogging_NoLevel_Drops-8              	44667505	        27.06 ns/op	       8 B/op	       0 allocs/op
+BenchmarkLogging_GoKitLevel_Drops_Sprintf-8   	 3569900	       336.1 ns/op	     320 B/op	       8 allocs/op
+BenchmarkLogging_GoKitLevel_Drops-8           	 6698175	       180.7 ns/op	     472 B/op	       5 allocs/op
+BenchmarkLogging_GoKitLevel_Prints-8          	  705537	      1688 ns/op	     849 B/op	      16 allocs/op
+BenchmarkLogging_Slog_Drops-8                 	79589450	        15.10 ns/op	       8 B/op	       0 allocs/op
+BenchmarkLogging_Slog_Prints-8                	 1000000	      1127 ns/op	      32 B/op	       2 allocs/op
+BenchmarkLogging_FlowLevel_Drops-8            	20856249	        55.64 ns/op	     168 B/op	       2 allocs/op
+BenchmarkLogging_FlowLevel_Prints-8           	  701811	      1713 ns/op	     849 B/op	      16 allocs/op
+*/
+
+const testStr = "this is a test string"
+
+func BenchmarkLogging_NoLevel_Prints(b *testing.B) {
+	logger, err := logging.New(io.Discard, debugLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		logger.Log("msg", "test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_NoLevel_Drops(b *testing.B) {
+	logger, err := logging.New(io.Discard, warnLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		logger.Log("msg", "test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_GoKitLevel_Drops_Sprintf(b *testing.B) {
+	logger, err := logging.New(io.Discard, debugLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		gokitlevel.Debug(logger).Log("msg", fmt.Sprintf("test message %d, error=%v, str=%s, duration=%v", i, testErr, testStr, time.Second))
+	}
+}
+
+func BenchmarkLogging_GoKitLevel_Drops(b *testing.B) {
+	logger, err := logging.New(io.Discard, debugLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		gokitlevel.Debug(logger).Log("msg", "test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_GoKitLevel_Prints(b *testing.B) {
+	logger, err := logging.New(io.Discard, debugLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	testStr := "this is a test string"
+	for i := 0; i < b.N; i++ {
+		gokitlevel.Warn(logger).Log("msg", "test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_Slog_Drops(b *testing.B) {
+	logger := slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{
+		Level: slog.LevelInfo,
+	}))
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		logger.Debug("test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_Slog_Prints(b *testing.B) {
+	logger := slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{
+		Level: slog.LevelInfo,
+	}))
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		logger.Info("test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_FlowLevel_Drops(b *testing.B) {
+	logger, err := logging.New(io.Discard, debugLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		flowlevel.Debug(logger).Log("msg", "test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func BenchmarkLogging_FlowLevel_Prints(b *testing.B) {
+	logger, err := logging.New(io.Discard, debugLevelOptions())
+	require.NoError(b, err)
+
+	testErr := fmt.Errorf("test error")
+	for i := 0; i < b.N; i++ {
+		flowlevel.Info(logger).Log("msg", "test message", "i", i, "err", testErr, "str", testStr, "duration", time.Second)
+	}
+}
+
+func debugLevelOptions() logging.Options {
+	opts := logging.Options{}
+	opts.SetToDefault()
+	opts.Level = logging.LevelInfo
+	return opts
+}
+
+func warnLevelOptions() logging.Options {
+	opts := debugLevelOptions()
+	opts.Level = logging.LevelWarn
+	return opts
+}