Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
202 changes: 40 additions & 162 deletions bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,19 +3,11 @@ package log_test
import (
"context"
"io"
stdlogpkg "log"
"log/slog"
"os"
"testing"

"github.com/go-coldbrew/log"
"github.com/go-coldbrew/log/loggers"
"github.com/go-coldbrew/log/loggers/gokit"
"github.com/go-coldbrew/log/loggers/logrus"
cbslog "github.com/go-coldbrew/log/loggers/slog"
"github.com/go-coldbrew/log/loggers/stdlog"
"github.com/go-coldbrew/log/loggers/zap"
"github.com/go-coldbrew/log/wrap"
)

// Common options: JSON output, no caller info (to isolate serialization cost).
Expand All @@ -30,82 +22,27 @@ var (
}
)

// discardStdout redirects os.Stdout to /dev/null for the duration of a
// benchmark. This is necessary for backends (gokit, zap, logrus, stdlog)
// that unconditionally write to os.Stdout.
func discardStdout(b *testing.B) {
func setupHandler(b *testing.B, inner slog.Handler, opts ...loggers.Option) {
b.Helper()
devNull, err := os.OpenFile(os.DevNull, os.O_WRONLY, 0)
if err != nil {
b.Fatalf("failed to open /dev/null: %v", err)
}
origStdout := os.Stdout
os.Stdout = devNull
b.Cleanup(func() {
os.Stdout = origStdout
devNull.Close()
})
}

func setupLogger(b *testing.B, backend loggers.BaseLogger) {
b.Helper()
log.SetLogger(log.NewLogger(backend))
h := log.NewHandlerWithInner(inner, opts...)
log.SetDefault(h)
b.ResetTimer()
}

// --- Backend benchmarks: log.Info() with each backend ---

func BenchmarkBackend_Gokit_JSON(b *testing.B) {
discardStdout(b)
setupLogger(b, gokit.NewLogger(jsonNoCaller...))
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Zap_JSON(b *testing.B) {
discardStdout(b)
setupLogger(b, zap.NewLogger(jsonNoCaller...))
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Logrus_JSON(b *testing.B) {
discardStdout(b)
setupLogger(b, logrus.NewLogger(jsonNoCaller...))
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}
// --- Backend benchmarks: log.Info() with ColdBrew Handler ---

func BenchmarkBackend_Slog_JSON(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupLogger(b, cbslog.NewLoggerWithHandler(handler, jsonNoCaller...))
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupHandler(b, inner, jsonNoCaller...)
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Slog_Text(b *testing.B) {
handler := slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupLogger(b, cbslog.NewLoggerWithHandler(handler, loggers.WithJSONLogs(false), loggers.WithCallerInfo(false)))
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Stdlog(b *testing.B) {
discardStdout(b)
origWriter := stdlogpkg.Writer()
stdlogpkg.SetOutput(io.Discard)
b.Cleanup(func() { stdlogpkg.SetOutput(origWriter) })
setupLogger(b, stdlog.NewLogger())
inner := slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupHandler(b, inner, loggers.WithJSONLogs(false), loggers.WithCallerInfo(false))
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
Expand All @@ -114,18 +51,9 @@ func BenchmarkBackend_Stdlog(b *testing.B) {

// --- Backend benchmarks with caller info ---

func BenchmarkBackend_Gokit_JSON_Caller(b *testing.B) {
discardStdout(b)
setupLogger(b, gokit.NewLogger(jsonWithCaller...))
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Slog_JSON_Caller(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupLogger(b, cbslog.NewLoggerWithHandler(handler, jsonWithCaller...))
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupHandler(b, inner, jsonWithCaller...)
ctx := context.Background()
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
Expand All @@ -134,33 +62,9 @@ func BenchmarkBackend_Slog_JSON_Caller(b *testing.B) {

// --- Backend benchmarks with context fields ---

func BenchmarkBackend_Gokit_JSON_CtxFields(b *testing.B) {
discardStdout(b)
setupLogger(b, gokit.NewLogger(jsonNoCaller...))
ctx := context.Background()
ctx = loggers.AddToLogContext(ctx, "trace_id", "abc-123")
ctx = loggers.AddToLogContext(ctx, "service", "bench-svc")
ctx = loggers.AddToLogContext(ctx, "request_id", "req-456")
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Slog_JSON_CtxFields(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupLogger(b, cbslog.NewLoggerWithHandler(handler, jsonNoCaller...))
ctx := context.Background()
ctx = loggers.AddToLogContext(ctx, "trace_id", "abc-123")
ctx = loggers.AddToLogContext(ctx, "service", "bench-svc")
ctx = loggers.AddToLogContext(ctx, "request_id", "req-456")
for b.Loop() {
log.Info(ctx, "msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkBackend_Zap_JSON_CtxFields(b *testing.B) {
discardStdout(b)
setupLogger(b, zap.NewLogger(jsonNoCaller...))
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupHandler(b, inner, jsonNoCaller...)
ctx := context.Background()
ctx = loggers.AddToLogContext(ctx, "trace_id", "abc-123")
ctx = loggers.AddToLogContext(ctx, "service", "bench-svc")
Expand All @@ -170,53 +74,50 @@ func BenchmarkBackend_Zap_JSON_CtxFields(b *testing.B) {
}
}

// --- Frontend benchmarks: slog.Info() through the bridge ---
// --- Backend benchmarks with typed context attrs ---

func BenchmarkFrontend_SlogBridge_GokitBackend(b *testing.B) {
discardStdout(b)
log.SetLogger(log.NewLogger(gokit.NewLogger(jsonNoCaller...)))
sl := wrap.ToSlogLogger(log.GetLogger())
func BenchmarkBackend_Slog_JSON_CtxAttrs(b *testing.B) {
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupHandler(b, inner, jsonNoCaller...)
ctx := context.Background()
b.ResetTimer()
ctx = log.AddAttrsToContext(ctx,
slog.String("trace_id", "abc-123"),
slog.String("service", "bench-svc"),
slog.String("request_id", "req-456"),
)
for b.Loop() {
sl.InfoContext(ctx, "benchmark message", "key1", "value1", "key2", 42)
slog.InfoContext(ctx, "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkFrontend_SlogBridge_SlogBackend(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
log.SetLogger(log.NewLogger(cbslog.NewLoggerWithHandler(handler, jsonNoCaller...)))
sl := wrap.ToSlogLogger(log.GetLogger())
ctx := context.Background()
b.ResetTimer()
for b.Loop() {
sl.InfoContext(ctx, "benchmark message", "key1", "value1", "key2", 42)
}
}
// --- Native slog benchmarks: slog.InfoContext() through ColdBrew Handler ---

func BenchmarkFrontend_SlogBridge_WithAttrs(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
log.SetLogger(log.NewLogger(cbslog.NewLoggerWithHandler(handler, jsonNoCaller...)))
sl := wrap.ToSlogLogger(log.GetLogger()).With("service", "bench-svc", "version", "1.0")
func BenchmarkFrontend_NativeSlog_ColdBrewHandler(b *testing.B) {
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
h := log.NewHandlerWithInner(inner, jsonNoCaller...)
log.SetDefault(h)
ctx := context.Background()
b.ResetTimer()
for b.Loop() {
sl.InfoContext(ctx, "benchmark message", "key1", "value1")
slog.InfoContext(ctx, "benchmark message", "key1", "value1", "key2", 42)
}
}

func BenchmarkFrontend_SlogBridge_WithGroup(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
log.SetLogger(log.NewLogger(cbslog.NewLoggerWithHandler(handler, jsonNoCaller...)))
sl := wrap.ToSlogLogger(log.GetLogger()).WithGroup("request")
func BenchmarkFrontend_NativeSlog_ColdBrewHandler_CtxFields(b *testing.B) {
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
h := log.NewHandlerWithInner(inner, jsonNoCaller...)
log.SetDefault(h)
ctx := context.Background()
ctx = loggers.AddToLogContext(ctx, "trace_id", "abc-123")
ctx = loggers.AddToLogContext(ctx, "service", "bench-svc")
ctx = loggers.AddToLogContext(ctx, "request_id", "req-456")
b.ResetTimer()
for b.Loop() {
sl.InfoContext(ctx, "benchmark message", "method", "GET", "path", "/api/v1")
slog.InfoContext(ctx, "benchmark message", "key1", "value1", "key2", 42)
}
}

// --- Frontend benchmark: native slog (baseline, no ColdBrew overhead) ---
// --- Baseline: native slog without ColdBrew (no overhead) ---

func BenchmarkFrontend_NativeSlog_JSON(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
Expand All @@ -238,34 +139,11 @@ func BenchmarkFrontend_NativeSlog_Text(b *testing.B) {
}
}

// --- Frontend benchmark: go-kit wrapped (existing pattern) ---

func BenchmarkFrontend_GoKitWrap(b *testing.B) {
discardStdout(b)
log.SetLogger(log.NewLogger(gokit.NewLogger(jsonNoCaller...)))
gk := wrap.ToGoKitLogger(log.GetLogger())
b.ResetTimer()
for b.Loop() {
_ = gk.Log("msg", "benchmark message", "key1", "value1", "key2", 42)
}
}

// --- Filtered (disabled level) benchmarks ---

func BenchmarkFiltered_Gokit(b *testing.B) {
discardStdout(b)
setupLogger(b, gokit.NewLogger(jsonNoCaller...))
log.SetLevel(loggers.ErrorLevel)
ctx := context.Background()
b.ResetTimer()
for b.Loop() {
log.Debug(ctx, "msg", "should be filtered")
}
}

func BenchmarkFiltered_Slog(b *testing.B) {
handler := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupLogger(b, cbslog.NewLoggerWithHandler(handler, jsonNoCaller...))
inner := slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})
setupHandler(b, inner, jsonNoCaller...)
log.SetLevel(loggers.ErrorLevel)
ctx := context.Background()
b.ResetTimer()
Expand All @@ -282,4 +160,4 @@ func BenchmarkFiltered_NativeSlog(b *testing.B) {
for b.Loop() {
sl.DebugContext(ctx, "should be filtered")
}
}
}
69 changes: 48 additions & 21 deletions documentation.go
Original file line number Diff line number Diff line change
@@ -1,36 +1,63 @@
/*
Package log provides a minimal interface for structured logging in services. ColdBrew uses this log package for all logs.
It provides a simple interface to log errors, warnings, info and debug messages.
It also provides a mechanism to add contextual information to logs.
available implementations of BaseLogger are in loggers package. You can also implement your own BaseLogger to use with this package.
Package log provides structured logging for ColdBrew microservices.

# How To Use
It uses a custom slog.Handler that automatically injects per-request context
fields (added via [AddToContext] or [AddAttrsToContext]) into every log record.

The simplest way to use this package is by calling static log functions to report particular level (error/warning/info/debug)
# Quick Start

log.Error(...)
log.Warn(...)
log.Info(...)
log.Debug(...)
Use the package-level functions for simple logging:

You can also initialize a new logger by calling 'log.NewLogger' and passing a loggers.BaseLogger implementation (loggers package provides a number of pre built implementations)
log.Info(ctx, "msg", "order processed", "order_id", "ORD-123")
log.Error(ctx, "msg", "connection failed", "host", "db.internal")

logger := log.NewLogger(gokit.NewLogger())
logger.Info(ctx, "key", "value")
# Native slog Support

Note:
After calling [SetDefault], native slog calls automatically get ColdBrew
context fields:

Preferred logging output is in either logfmt or json format, so to facilitate these log function arguments should be in pairs of key-value
log.SetDefault(log.NewHandler())
ctx := context.Background()
ctx = log.AddToContext(ctx, "trace_id", "abc-123")
slog.InfoContext(ctx, "request handled", "status", 200) // includes trace_id
Comment thread
coderabbitai[bot] marked this conversation as resolved.

# Contextual Logs
# Adding Context Fields

log package uses context.Context to pass additional information to logs, you can use 'loggers.AddToLogContext' function to add additional information to logs. For example in access log from service
Use [AddAttrsToContext] to add typed slog.Attr fields, or [AddToContext] for
untyped key-value pairs. Both are included in all subsequent logs for that
request:

{"@timestamp":"2018-07-30T09:58:18.262948679Z","caller":"http/http.go:66","error":null,"grpcMethod":"/AuthSvc.AuthService/Authenticate","level":"info","method":"POST","path":"/2.0/authenticate/","took":"1.356812ms","trace":"15592e1b-93df-11e8-bdfd-0242ac110002","transport":"http"}
ctx := context.Background()
ctx = log.AddAttrsToContext(ctx,
slog.String("trace_id", id),
slog.Int("user_id", uid),
)

we pass 'grpcMethod' from context, this information gets automatically added to all log calls called inside the service and makes debugging services much easier.
ColdBrew also generates a 'trace' ID per request, this can be used to trace an entire request path in logs.
[AddAttrsToContext] stores each slog.Attr in the context. At log time, the
Handler recovers the typed Attr and emits it directly. Context storage goes
through an any-typed API internally (one boxing per field per request), but
the Attr's type information is preserved for emission.

this package is based on https://github.com/carousell/Orion/tree/master/utils/log
# High-Performance Logging

Combine [AddAttrsToContext] with [slog.LogAttrs] for the lowest-overhead path.
Per-call attributes passed to [slog.LogAttrs] avoid interface boxing entirely:

slog.LogAttrs(ctx, slog.LevelInfo, "request handled",
slog.Int("status", 200),
slog.Duration("latency", elapsed),
)

# Custom Handlers

Use [NewHandlerWithInner] to compose ColdBrew's context injection with any
slog.Handler:

multi := slogmulti.Fanout(jsonHandler, textHandler)
h := log.NewHandlerWithInner(multi)
log.SetDefault(h)

ColdBrew interceptors automatically add grpcMethod, trace ID, and HTTP path
to the context, so these fields appear in all service logs.
*/
package log
Loading
Loading