perf(logging): eliminate hot-path allocations

.github/workflows/ci.yml

@@ -65,8 +65,10 @@ jobs:
       - name: golangci-lint
         run: make lint
 
-      - name: Deterministic guard allocation ceilings
-        run: go test -count=1 -run '^TestPromptGuardAllocationCeilings$' ./pkg/promptguard
+      - name: Deterministic allocation ceilings
+        run: |
+          go test -count=1 -run '^TestPromptGuardAllocationCeilings$' ./pkg/promptguard
+          go test -count=1 -run '^TestLoggingAllocationCeilings$' ./pkg/logging
 
       - name: go test race
         run: go test -race -count=1 ./...

pkg/logging/allocation_test.go

@@ -0,0 +1,52 @@
+//go:build !race
+
+package logging
+
+import (
+	"context"
+	"io"
+	"log/slog"
+	"testing"
+)
+
+func TestLoggingAllocationCeilings(t *testing.T) {
+	logger := slog.New(newFormatHandler(slog.LevelInfo, io.Discard))
+	ctx := WithRequestID(WithRuntime(context.Background(), "bot"), "req-1")
+
+	tests := []struct {
+		name      string
+		maxAllocs float64
+		call      func()
+	}{
+		{
+			name:      "log common path",
+			maxAllocs: 5,
+			call: func() {
+				Log(ctx, logger, slog.LevelInfo, "request.completed", "request completed",
+					slog.String("method", "GET"), slog.Int("status", 200))
+			},
+		},
+		{
+			name:      "log and wrap error",
+			maxAllocs: 12,
+			call: func() {
+				_ = LogAndWrapError(ctx, logger, "op", context.DeadlineExceeded, slog.String("a", "b"))
+			},
+		},
+		{
+			name:      "log warn with error attrs",
+			maxAllocs: 12,
+			call: func() {
+				LogWarnWithErrorAttrs(ctx, logger, "event", "message", context.DeadlineExceeded, slog.String("a", "b"))
+			},
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			if got := testing.AllocsPerRun(200, test.call); got > test.maxAllocs {
+				t.Fatalf("%s allocs = %v, want <= %v", test.name, got, test.maxAllocs)
+			}
+		})
+	}
+}

pkg/logging/context.go

@@ -6,15 +6,22 @@ import (
 	"strings"
 )
 
-type contextKey string
+type contextKey uint8
 
 const (
-	requestIDContextKey contextKey = "hololive.logging.request_id"
-	jobIDContextKey     contextKey = "hololive.logging.job_id"
-	runtimeContextKey   contextKey = "hololive.logging.runtime"
-	componentContextKey contextKey = "hololive.logging.component"
+	requestIDContextKey contextKey = iota
+	jobIDContextKey
+	runtimeContextKey
+	componentContextKey
 )
 
+type contextValues struct {
+	runtime   string
+	component string
+	requestID string
+	jobID     string
+}
+
 func WithRequestID(ctx context.Context, requestID string) context.Context {
 	return withString(ctx, requestIDContextKey, requestID)
 }
@@ -48,27 +55,76 @@ func componentFromContext(ctx context.Context) string {
 }
 
 func ContextAttrs(ctx context.Context) []slog.Attr {
-	if ctx == nil {
+	values := contextValuesFrom(ctx)
+	count := values.count()
+	if count == 0 {
 		return nil
 	}
 
-	attrs := make([]slog.Attr, 0, 4)
-	if value := runtimeFromContext(ctx); value != "" {
-		attrs = append(attrs, Runtime(value))
+	return values.appendTo(make([]slog.Attr, 0, count))
+}
+
+func contextValuesFrom(ctx context.Context) contextValues {
+	if ctx == nil {
+		return contextValues{}
+	}
+
+	return contextValues{
+		runtime:   runtimeFromContext(ctx),
+		component: componentFromContext(ctx),
+		requestID: requestIDFromContext(ctx),
+		jobID:     jobIDFromContext(ctx),
+	}
+}
+
+func (v contextValues) count() int {
+	count := 0
+	if v.runtime != "" {
+		count++
 	}
-	if value := componentFromContext(ctx); value != "" {
-		attrs = append(attrs, componentAttr(value))
+	if v.component != "" {
+		count++
 	}
-	if value := requestIDFromContext(ctx); value != "" {
-		attrs = append(attrs, RequestID(value))
+	if v.requestID != "" {
+		count++
 	}
-	if value := jobIDFromContext(ctx); value != "" {
-		attrs = append(attrs, jobIDAttr(value))
+	if v.jobID != "" {
+		count++
 	}
+	return count
+}
 
+func (v contextValues) appendTo(attrs []slog.Attr) []slog.Attr {
+	if v.runtime != "" {
+		attrs = append(attrs, Runtime(v.runtime))
+	}
+	if v.component != "" {
+		attrs = append(attrs, componentAttr(v.component))
+	}
+	if v.requestID != "" {
+		attrs = append(attrs, RequestID(v.requestID))
+	}
+	if v.jobID != "" {
+		attrs = append(attrs, jobIDAttr(v.jobID))
+	}
 	return attrs
 }
 
+func (v contextValues) addToRecord(record *slog.Record) {
+	if v.runtime != "" {
+		record.AddAttrs(Runtime(v.runtime))
+	}
+	if v.component != "" {
+		record.AddAttrs(componentAttr(v.component))
+	}
+	if v.requestID != "" {
+		record.AddAttrs(RequestID(v.requestID))
+	}
+	if v.jobID != "" {
+		record.AddAttrs(jobIDAttr(v.jobID))
+	}
+}
+
 func withString(ctx context.Context, key contextKey, value string) context.Context {
 	if ctx == nil {
 		ctx = context.Background()

pkg/logging/format.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"io"
 	"log/slog"
+	"strconv"
 	"strings"
 )
 
@@ -38,16 +39,22 @@ func shortenSource(groups []string, attr slog.Attr) slog.Attr {
 	if !ok {
 		return attr
 	}
-	return slog.Any(slog.SourceKey, &slog.Source{
-		Function: source.Function,
-		File:     lastPathSegments(source.File),
-		Line:     source.Line,
-	})
+	// PC 0 record는 빈 Source를 낳는다. 빈 Attr을 돌려줘야 slog이 통째로 생략한다.
+	// 평탄화 판본은 이 가드가 없으면 ":0"을 실어 생략을 되살리지 못한다.
+	if source.File == "" && source.Line == 0 {
+		return slog.Attr{}
+	}
+
+	var buf [128]byte
+	out := append(buf[:0], lastPathSegments(source.File)...)
+	out = append(out, ':')
+	out = strconv.AppendInt(out, int64(source.Line), 10)
+	return slog.String(slog.SourceKey, string(out))
 }
 
 // filepath.Join은 Clean 때문에 record마다 할당한다. 여기서는 substring slice로 충분하다.
-// 빈 경로에 ""를 돌려주는 것이 load-bearing이다. filepath 판본은 "."를 만들어, PC 0 record가
-// 낳는 빈 Source를 slog이 생략하지 못하게 되살린다.
+// 빈 경로에 ""를 돌려주는 것이 load-bearing이다. filepath 판본은 "."를 만들어, File만
+// 비어 있고 Line이 살아 있는 record에 ".:42" 같은 허위 경로를 남긴다.
 func lastPathSegments(path string) string {
 	base := strings.LastIndexByte(path, '/')
 	if base < 0 {

pkg/logging/format_test.go

@@ -2,6 +2,7 @@ package logging
 
 import (
 	"bytes"
+	"context"
 	"encoding/json"
 	"io"
 	"log/slog"
@@ -10,6 +11,7 @@ import (
 	"reflect"
 	"strings"
 	"testing"
+	"time"
 )
 
 const (
@@ -356,19 +358,35 @@ func TestJSONFormat_ShortensSourcePath(t *testing.T) {
 	slog.New(newFormatHandler(slog.LevelInfo, &buf)).Info("format_probe_source")
 
 	record := probeJSONRecord(t, "json/source", buf.String())
-	source, ok := record[slog.SourceKey].(map[string]any)
+	source, ok := record[slog.SourceKey].(string)
 	if !ok {
-		t.Fatalf("source is not an object: %v", record[slog.SourceKey])
+		t.Fatalf("source is not a string: %v", record[slog.SourceKey])
+	}
+	file, line, found := strings.Cut(source, ":")
+	if !found {
+		t.Fatalf("source = %q, want \"file:line\"", source)
 	}
-	file, _ := source["file"].(string)
 	if filepath.IsAbs(file) {
-		t.Fatalf("source.file is an absolute build path: %q", file)
+		t.Fatalf("source file is an absolute build path: %q", file)
 	}
 	if want := "logging/format_test.go"; file != want {
-		t.Fatalf("source.file = %q, want %q", file, want)
+		t.Fatalf("source file = %q, want %q", file, want)
+	}
+	if line == "" || line == "0" {
+		t.Fatalf("source line dropped: %q", source)
 	}
-	if _, ok := source["line"]; !ok {
-		t.Fatalf("source.line dropped: %v", source)
+}
+
+func TestJSONFormat_OmitsSourceForZeroPC(t *testing.T) {
+	var buf bytes.Buffer
+	handler := newFormatHandler(slog.LevelInfo, &buf)
+	if err := handler.Handle(context.Background(), slog.NewRecord(time.Now(), slog.LevelInfo, "format_probe_zero_pc", 0)); err != nil {
+		t.Fatalf("handle zero-PC record: %v", err)
+	}
+
+	record := probeJSONRecord(t, "json/zero-pc", buf.String())
+	if value, ok := record[slog.SourceKey]; ok {
+		t.Fatalf("PC 0 record carries a source attr: %v", value)
 	}
 }