Skip to content
Merged
Show file tree
Hide file tree
Changes from 1 commit
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")
}
}
}
61 changes: 40 additions & 21 deletions documentation.go
Original file line number Diff line number Diff line change
@@ -1,36 +1,55 @@
/*
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 [loggers.AddToLogContext]) 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 := 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
# Typed Attrs (Zero-Boxing Path)

Use [AddAttrsToContext] with [slog.LogAttrs] for the highest performance path,
avoiding interface boxing for both context fields and per-call attributes:
Comment thread
ankurs marked this conversation as resolved.
Outdated

ctx = log.AddAttrsToContext(ctx,
slog.String("trace_id", id),
slog.Int("user_id", uid),
)
slog.LogAttrs(ctx, slog.LevelInfo, "request handled", slog.Int("status", 200))

# Custom Handlers

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 [NewHandlerWithInner] to compose ColdBrew's context injection with any
slog.Handler:

// Fan-out to multiple destinations
multi := slogmulti.Fanout(jsonHandler, textHandler)
h := log.NewHandlerWithInner(multi)
log.SetDefault(h)

# Contextual Logs

{"@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"}
Use [AddToContext] to add per-request fields that appear in all subsequent logs:

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.
ctx = log.AddToContext(ctx, "request_id", "abc-123")
ctx = log.AddToContext(ctx, "user_id", "user-42")
log.Info(ctx, "msg", "processing request") // includes request_id and user_id

this package is based on https://github.com/carousell/Orion/tree/master/utils/log
ColdBrew interceptors automatically add grpcMethod, trace ID, and HTTP path
to the context, so these fields appear in all service logs.
*/
package log
14 changes: 14 additions & 0 deletions example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package log_test

import (
"context"
"log/slog"

"github.com/go-coldbrew/log"
)
Expand All @@ -27,3 +28,16 @@ func ExampleError() {
ctx := context.Background()
log.Error(ctx, "msg", "database connection failed", "host", "db.internal", "port", 5432, "retry_in", "5s")
}

func ExampleAddAttrsToContext() {
ctx := context.Background()

// Typed attrs avoid interface boxing for high-performance paths
ctx = log.AddAttrsToContext(ctx,
slog.String("trace_id", "abc-123"),
slog.Int("user_id", 42),
)

// Both context fields and per-call attrs use typed values
slog.LogAttrs(ctx, slog.LevelInfo, "request handled", slog.Int("status", 200))
Comment thread
ankurs marked this conversation as resolved.
Outdated
}
Loading
Loading