perf: short-circuit NR interceptors, add error-only response time logging

go.mod

@@ -5,7 +5,7 @@ go 1.25.8
 require (
 	github.com/afex/hystrix-go v0.0.0-20180502004556-fa1af6a1f4f5
 	github.com/go-coldbrew/errors v0.2.6
-	github.com/go-coldbrew/log v0.2.7
+	github.com/go-coldbrew/log v0.2.8
 	github.com/go-coldbrew/options v0.2.6
 	github.com/go-coldbrew/tracing v0.2.0
 	github.com/grpc-ecosystem/go-grpc-middleware/providers/prometheus v1.1.0
@@ -93,8 +93,6 @@ require (
 	github.com/go-git/gcfg v1.5.1-0.20230307220236-3a3c6141e376 // indirect
 	github.com/go-git/go-billy/v5 v5.8.0 // indirect
 	github.com/go-git/go-git/v5 v5.17.1 // indirect
-	github.com/go-kit/log v0.2.1 // indirect
-	github.com/go-logfmt/logfmt v0.6.1 // indirect
 	github.com/go-toolsmith/astcast v1.1.0 // indirect
 	github.com/go-toolsmith/astcopy v1.1.0 // indirect
 	github.com/go-toolsmith/astequal v1.2.0 // indirect

go.sum

@@ -171,8 +171,8 @@ github.com/gliderlabs/ssh v0.3.8 h1:a4YXD1V7xMF9g5nTkdfnja3Sxy1PVDCj1Zg4Wb8vY6c=
 github.com/gliderlabs/ssh v0.3.8/go.mod h1:xYoytBv1sV0aL3CavoDuJIQNURXkkfPA/wxQ1pL1fAU=
 github.com/go-coldbrew/errors v0.2.6 h1:rNOI+XcxuyrN/t3e7zDBVUVzcYBNmhyjatsnJg9MDZA=
 github.com/go-coldbrew/errors v0.2.6/go.mod h1:jFXeN7Q74fggbIEZu/68vhRX1ob2zfc+2sy0osVfBlY=
-github.com/go-coldbrew/log v0.2.7 h1:kRQeTYLPLcjjAWuCcGZpNn8twSY/NbsGpjIKbpXEnRA=
-github.com/go-coldbrew/log v0.2.7/go.mod h1:BB+2VecklLXTaDQdNNe2h3r5rSZL2DGvJBXAgrXq1dk=
+github.com/go-coldbrew/log v0.2.8 h1:aF+vw23zMyh5S9vhhofERiaPpSDyeJH1Tv1CYREn/a0=
+github.com/go-coldbrew/log v0.2.8/go.mod h1:RKvGzMZMt7FpQ9u36adkDigRxkOvRj1diwgAgRJZH4E=
 github.com/go-coldbrew/options v0.2.6 h1:Nr93v7PbO+EYLHhzA8biGumaTTSHLHqTYLg70n/foXE=
 github.com/go-coldbrew/options v0.2.6/go.mod h1:Os4pZwIgMHES079iOKXTlzcipWXbxw0OhsAN5D9m2mM=
 github.com/go-coldbrew/tracing v0.2.0 h1:WGfdp5PNunOGfjTZGXPFaip3G5qOOMP622JFYA90ML4=

interceptors.go

@@ -56,6 +56,7 @@ var (
 	streamClientInterceptors = []grpc.StreamClientInterceptor{}
 	useCBClientInterceptors  = true
 	responseTimeLogLevel     loggers.Level = loggers.InfoLevel
+	responseTimeLogErrorOnly bool
 	srvMetricsOpts           []grpcprom.ServerMetricsOption
 	cltMetricsOpts           []grpcprom.ClientMetricsOption
 	srvMetricsOnce           sync.Once
@@ -70,6 +71,13 @@ func SetResponseTimeLogLevel(ctx context.Context, level loggers.Level) {
 	responseTimeLogLevel = level
 }
 
+// SetResponseTimeLogErrorOnly when set to true, only logs response time when
+// the request returns an error. Successful requests are not logged.
+// Must be called during initialization, before the server starts. Not safe for concurrent use.
+func SetResponseTimeLogErrorOnly(errorOnly bool) {
+	responseTimeLogErrorOnly = errorOnly
+}
+
 // If it returns false, the given request will not be traced.
 type FilterFunc func(ctx context.Context, fullMethodName string) bool
 
@@ -395,10 +403,10 @@ func DefaultClientStreamInterceptors(defaultOpts ...interface{}) []grpc.StreamCl
 		ints = append(ints, streamClientInterceptors...)
 	}
 	if useCBClientInterceptors {
-		ints = append(ints,
-			nrgrpc.StreamClientInterceptor,
-			getClientMetrics().StreamClientInterceptor(),
-		)
+		if nrutil.GetNewRelicApp() != nil {
+			ints = append(ints, nrgrpc.StreamClientInterceptor)
+		}
+		ints = append(ints, getClientMetrics().StreamClientInterceptor())
 	}
 	return ints
 }
@@ -442,13 +450,14 @@ func DebugLoggingInterceptor() grpc.UnaryServerInterceptor {
 // ResponseTimeLoggingInterceptor logs response time for each request on server
 func ResponseTimeLoggingInterceptor(ff FilterFunc) grpc.UnaryServerInterceptor {
 	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
-		ctx = options.AddToOptions(ctx, "", "")
-		ctx = loggers.AddToLogContext(ctx, "", "")
 		ctx = loggers.AddToLogContext(ctx, "grpcMethod", info.FullMethod)
 		defer func(ctx context.Context, method string, begin time.Time) {
 			if ff != nil && !ff(ctx, method) {
 				return
 			}
+			if responseTimeLogErrorOnly && err == nil {
+				return
+			}
 			logArgs := []any{"error", err, "took", time.Since(begin)}
 			if err != nil {
 				logArgs = append(logArgs, "grpcCode", status.Code(err))
@@ -468,8 +477,15 @@ func OptionsInterceptor() grpc.UnaryServerInterceptor {
 	}
 }
 
-// NewRelicInterceptor intercepts all server actions and reports them to newrelic
+// NewRelicInterceptor intercepts all server actions and reports them to newrelic.
+// When NewRelic app is nil (no license key configured), returns a pass-through
+// interceptor to avoid overhead.
 func NewRelicInterceptor() grpc.UnaryServerInterceptor {
+	if nrutil.GetNewRelicApp() == nil {
+		return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
+			return handler(ctx, req)
+		}
+	}
 	nrh := nrgrpc.UnaryServerInterceptor(nrutil.GetNewRelicApp())
 	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
 		if defaultFilterFunc(ctx, info.FullMethod) {
@@ -522,8 +538,15 @@ func PanicRecoveryInterceptor() grpc.UnaryServerInterceptor {
 	}
 }
 
-// NewRelicClientInterceptor intercepts all client actions and reports them to newrelic
+// NewRelicClientInterceptor intercepts all client actions and reports them to newrelic.
+// When NewRelic app is nil (no license key configured), returns a pass-through
+// interceptor to avoid overhead.
 func NewRelicClientInterceptor() grpc.UnaryClientInterceptor {
+	if nrutil.GetNewRelicApp() == nil {
+		return func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
+			return invoker(ctx, method, req, reply, cc, opts...)
+		}
+	}
 	return func(ctx context.Context, method string, req, reply interface{}, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
 		if defaultFilterFunc(ctx, method) {
 			return nrgrpc.UnaryClientInterceptor(ctx, method, req, reply, cc, invoker, opts...)

interceptors_test.go

@@ -2,11 +2,13 @@ package interceptors
 
 import (
 	"context"
+	"errors"
 	"fmt"
 	"net/http"
 	"sync"
 	"testing"
 
+	"github.com/go-coldbrew/log/loggers"
 	"github.com/grpc-ecosystem/grpc-gateway/v2/runtime"
 	"google.golang.org/grpc"
 	grpcmd "google.golang.org/grpc/metadata"
@@ -37,6 +39,8 @@ func resetGlobals() {
 	unaryClientInterceptors = []grpc.UnaryClientInterceptor{}
 	streamClientInterceptors = []grpc.StreamClientInterceptor{}
 	useCBClientInterceptors = true
+	responseTimeLogErrorOnly = false
+	responseTimeLogLevel = loggers.InfoLevel
 }
 
 func TestFilterMethodsFunc(t *testing.T) {
@@ -630,3 +634,105 @@ func BenchmarkFilterMethodsFunc(b *testing.B) {
 		}
 	})
 }
+
+// noopHandler is a handler that returns immediately with no error.
+var noopHandler grpc.UnaryHandler = func(ctx context.Context, req interface{}) (interface{}, error) {
+	return "ok", nil
+}
+
+// errHandler is a handler that returns an error.
+var errHandler grpc.UnaryHandler = func(ctx context.Context, req interface{}) (interface{}, error) {
+	return nil, errors.New("test error")
+}
+
+var benchInfo = &grpc.UnaryServerInfo{FullMethod: "/test.Service/Method"}
+
+func BenchmarkNewRelicInterceptor_NilApp(b *testing.B) {
+	// NR app is nil by default (no license key). The interceptor should
+	// be a direct pass-through with zero overhead.
+	resetGlobals()
+	interceptor := NewRelicInterceptor()
+	ctx := grpcContext()
+
+	b.ResetTimer()
+	b.ReportAllocs()
+	for b.Loop() {
+		interceptor(ctx, nil, benchInfo, noopHandler)
+	}
+}
+
+func BenchmarkResponseTimeLogging(b *testing.B) {
+	resetGlobals()
+	// Use debug level — the slog default logger discards debug, so we
+	// measure interceptor + log-args-building overhead without I/O noise.
+	responseTimeLogLevel = loggers.DebugLevel
+	ctx := grpcContext()
+	ff := FilterMethodsFunc
+
+	b.Run("default/success", func(b *testing.B) {
+		responseTimeLogErrorOnly = false
+		interceptor := ResponseTimeLoggingInterceptor(ff)
+		b.ResetTimer()
+		b.ReportAllocs()
+		for b.Loop() {
+			interceptor(ctx, nil, benchInfo, noopHandler)
+		}
+	})
+
+	b.Run("default/error", func(b *testing.B) {
+		responseTimeLogErrorOnly = false
+		interceptor := ResponseTimeLoggingInterceptor(ff)
+		b.ResetTimer()
+		b.ReportAllocs()
+		for b.Loop() {
+			interceptor(ctx, nil, benchInfo, errHandler)
+		}
+	})
+
+	b.Run("error_only/success", func(b *testing.B) {
+		responseTimeLogErrorOnly = true
+		interceptor := ResponseTimeLoggingInterceptor(ff)
+		b.ResetTimer()
+		b.ReportAllocs()
+		for b.Loop() {
+			interceptor(ctx, nil, benchInfo, noopHandler)
+		}
+	})
+
+	b.Run("error_only/error", func(b *testing.B) {
+		responseTimeLogErrorOnly = true
+		interceptor := ResponseTimeLoggingInterceptor(ff)
+		b.ResetTimer()
+		b.ReportAllocs()
+		for b.Loop() {
+			interceptor(ctx, nil, benchInfo, errHandler)
+		}
+	})
+
+	// Restore default.
+	responseTimeLogErrorOnly = false
+}
+
+func BenchmarkDefaultInterceptors(b *testing.B) {
+	resetGlobals()
+	ctx := grpcContext()
+	chain := DefaultInterceptors()
+
+	// Build a chained handler that applies all interceptors.
+	var chainedHandler grpc.UnaryHandler = noopHandler
+	for i := len(chain) - 1; i >= 0; i-- {
+		next := chainedHandler
+		interceptor := chain[i]
+		chainedHandler = func(ctx context.Context, req interface{}) (interface{}, error) {
+			return interceptor(ctx, req, benchInfo, func(ctx context.Context, req interface{}) (interface{}, error) {
+				return next(ctx, req)
+			})
+		}
+	}
+
+	b.ResetTimer()
+	b.ReportAllocs()
+	for b.Loop() {
+		chainedHandler(ctx, nil)
+	}
+}