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
2 changes: 2 additions & 0 deletions docs/CHECKLIST.md
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,8 @@ Usage belongs in the utility guides. [Feature comparison](FEATURE_PARITY.md) map

## Logger

- [x] L-25: Reduce common Logger encoding and filtering overhead (#248) while preserving root order, omission rules, hooks, caller ownership, error atomicity and the main-only stack Preview. Logger regression tests, its packaged-module/standalone-consumer checks and the native Lambda SDK Logger fixture pass; the composed Lambda example builds as static Linux amd64/arm64 ELF binaries with CGO disabled. Same-source local Windows benchmarks retain output sizes: the small emitted case drops from 118 to 34 allocations, invocation-bound INFO from 193 to 53, and both unbuffered filtered cases reach zero allocations. Timing observations, source hashes and scope are recorded in [PERFORMANCE_LOGGER_248.json](PERFORMANCE_LOGGER_248.json); no AWS performance improvement or universal budget is claimed (2026-10-15).

- [x] L-24: Implement main-only structured error stacks and handler panic logging Preview (#241). Verify error-chain identity, independent join branches, lazy 64-frame stacks, opt-outs/hooks, single-line JSON, nested/concurrent cleanup, and original panic preservation under diagnostic failures. Actual typed/raw Lambda SDK and OTel exporter composition passes; [PR #242 CI](https://github.com/rambow-cloud/powertools-lambda-go/actions/runs/38706578552) passes packaged Logger/examples/integration tests, vet, tidy/isolation, consumers, Linux amd64/arm64 cross-builds and Docker Linux amd64 Lambda/streaming/Valkey acceptance. Local Docker startup was unavailable; hosted Docker supplies platform evidence. Fresh public v1.2.0 consumption retains the old behavior and rejects all three Preview APIs. A public SHA consumer and a post-merge direct-origin `@main` consumer verify the Preview; main resolves to `a179f0373577` (proxy branch caching is documented). Cloudflare Pages and GitHub Pages deployments succeed for that source. All Go checks use CGO disabled; no AWS tests or Go version publication (2026-10-15).

- [x] AUDIT-LOGGER-181-LOCAL: Complete the finite [Logger boundary matrix](reference/LOGGER.md#finite-boundary-audit-181), reusing 48 pinned action cases and adding 26 timezone/environment/sink cases plus native marshaler and short-write regressions. Reproduce and fix ignored container TextMarshaler values/errors and duplicate failed JSON/streaming marshaler calls during replacement. Preserve Go JSON v2, native diagnostic and zero-offset differences explicitly. Packaged Logger tests/vet/tidy/isolation and an independent consumer pass with CGO disabled; broader L-08/L-09, resource and multi-worker/platform gates remain separate (2026-10-13).
Expand Down
40 changes: 40 additions & 0 deletions docs/PERFORMANCE.md
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,46 @@ only to investigate a meaningful change or unresolved variability. Review
allocations and output sizes alongside time; this single-run baseline does not
define statistically justified pass/fail percentages or universal latency budgets.

## Logger hot-path comparison (#248)

The Logger optimization compares the same benchmark source against commit
`35f9d088e9ca96d5718f4ca1a793332c756c2f2c` and the updated implementation.
Both runs use Go 1.27.1, Windows amd64, `CGO_ENABLED=0`, `GOMAXPROCS=2`, a
counting writer and one 300ms measurement per case. The original baseline above
remains a separate historical measurement.

| Operation | Before ns/op | After ns/op | Before B/op | After B/op | Before allocs/op | After allocs/op |
| --- | ---: | ---: | ---: | ---: | ---: | ---: |
| Logger emitted, 208 output bytes | 9,771 | 5,249 | 5,592 | 2,752 | 118 | 34 |
| Invocation-bound INFO, 404 output bytes | 14,750 | 6,939 | 9,417 | 4,448 | 193 | 53 |
| Bind context and INFO, 404 output bytes | 14,812 | 7,764 | 9,704 | 4,737 | 194 | 54 |
| Complete wrapper and INFO, 404 output bytes | 15,696 | 7,715 | 11,377 | 6,409 | 208 | 68 |
| Logger filtered | 544.2 | 15.68 | 528 | 0 | 4 | 0 |
| Invocation-bound filtered | 285.3 | 16.45 | 432 | 0 | 5 | 0 |

All emitted cases retain their output size. The invocation benchmark also includes
a direct JSON control with identical enriched fields: 47 allocations and 2,773
bytes per operation in both runs. That control omits Logger normalization, root
ordering and synchronization. The Logger cases preserve those behaviors, error
atomicity, formatter/replacer hooks and the main-only stack Preview.

The improvements come from sharing one JSON v2 encoder, processing ordinary maps
and scalars without reflective iteration, reducing ordering/output copies, and
avoiding unused trace lookup on filtered/unbuffered paths. Source hashes and all
seven raw benchmark summaries are recorded in
[PERFORMANCE_LOGGER_248.json](PERFORMANCE_LOGGER_248.json).

Run from `logger` with CGO disabled:

```sh
CGO_ENABLED=0 GOMAXPROCS=2 go test -p 1 -run '^$' -bench '^BenchmarkLogger($|Invocation)' -benchmem -benchtime=300ms -count=1 .
```

These single-run local observations locate overhead; they do not establish a
statistical regression budget or predict Linux Lambda latency. CloudWatch/stdout
I/O, CPU quotas, GC under large-event workloads and cold starts require separate
measurements. No AWS benchmark was run for this change.

## Measurement boundaries

Construction and schema compilation happen outside the timed operations. Clocks
Expand Down
128 changes: 128 additions & 0 deletions docs/PERFORMANCE_LOGGER_248.json
Original file line number Diff line number Diff line change
@@ -0,0 +1,128 @@
{
"issue": 248,
"verified_at": "2026-10-15",
"baseline_commit": "35f9d088e9ca96d5718f4ca1a793332c756c2f2c",
"source_sha256": {
"logger/logger.go": "b4380ec8d13a43d0ca4c722cece19256db074d19ec6f10cd993008aeb98b61c3",
"logger/encoding.go": "f629d39a1068b0e97578082a225d4555e9f34bc40e9214677f10d9ac54dd9aee",
"logger/benchmark_test.go": "d6d07f03eaad83bf2ec7fa371d0d25b0a84fcdc1318139b1420156e760f773e1",
"logger/performance_regression_test.go": "145b1c348fa8ff5e4b477c2cc354924ba386b275c71e1ad105c1071e00d97dc8"
},
"environment": {
"go": "go1.27.1",
"os": "windows",
"architecture": "amd64",
"CGO_ENABLED": "0",
"GOMAXPROCS": "2",
"cpu": "12th Gen Intel Core i5-12500H"
},
"command": "go test -p 1 -run '^$' -bench '^BenchmarkLogger($|Invocation)' -benchmem -benchtime=300ms -count=1 .",
"scope": "Single local measurements of the same benchmark source before and after; counting writer, no AWS runtime or stdout I/O latency. DirectJSON shares enrichment and fields but omits Logger normalization, ordering and synchronization. This does not establish Lambda latency or statistical performance budgets.",
"results": [
{
"benchmark": "BenchmarkLoggerInvocation/DirectJSON-2",
"before": {
"ns_per_op": 5613.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 2773,
"allocations_per_op": 47
},
"after": {
"ns_per_op": 4984.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 2773,
"allocations_per_op": 47
}
},
{
"benchmark": "BenchmarkLoggerInvocation/BoundINFO-2",
"before": {
"ns_per_op": 14750.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 9417,
"allocations_per_op": 193
},
"after": {
"ns_per_op": 6939.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 4448,
"allocations_per_op": 53
}
},
{
"benchmark": "BenchmarkLoggerInvocation/BindAndINFO-2",
"before": {
"ns_per_op": 14812.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 9704,
"allocations_per_op": 194
},
"after": {
"ns_per_op": 7764.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 4737,
"allocations_per_op": 54
}
},
{
"benchmark": "BenchmarkLoggerInvocation/WrappedINFO-2",
"before": {
"ns_per_op": 15696.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 11377,
"allocations_per_op": 208
},
"after": {
"ns_per_op": 7715.0,
"output_bytes_per_op": 404.0,
"bytes_per_op": 6409,
"allocations_per_op": 68
}
},
{
"benchmark": "BenchmarkLoggerInvocation/Filtered-2",
"before": {
"ns_per_op": 285.3,
"output_bytes_per_op": 0.0,
"bytes_per_op": 432,
"allocations_per_op": 5
},
"after": {
"ns_per_op": 16.45,
"output_bytes_per_op": 0.0,
"bytes_per_op": 0,
"allocations_per_op": 0
}
},
{
"benchmark": "BenchmarkLogger/Emitted-2",
"before": {
"ns_per_op": 9771.0,
"output_bytes_per_op": 208.0,
"bytes_per_op": 5592,
"allocations_per_op": 118
},
"after": {
"ns_per_op": 5249.0,
"output_bytes_per_op": 208.0,
"bytes_per_op": 2752,
"allocations_per_op": 34
}
},
{
"benchmark": "BenchmarkLogger/Filtered-2",
"before": {
"ns_per_op": 544.2,
"output_bytes_per_op": 0.0,
"bytes_per_op": 528,
"allocations_per_op": 4
},
"after": {
"ns_per_op": 15.68,
"output_bytes_per_op": 0.0,
"bytes_per_op": 0,
"allocations_per_op": 0
}
}
]
}
80 changes: 80 additions & 0 deletions logger/benchmark_test.go
Original file line number Diff line number Diff line change
@@ -1,9 +1,13 @@
package logger

import (
"context"
json "encoding/json/v2"
"errors"
"testing"
"time"

"github.com/aws/aws-lambda-go/lambdacontext"
)

type benchmarkWriter struct{ bytes int64 }
Expand All @@ -13,6 +17,82 @@ func (w *benchmarkWriter) Write(p []byte) (int, error) {
return len(p), nil
}

// Compare identical invocation fields and output sinks. DirectJSON shares record
// enrichment but omits Logger normalization and ordered-root encoding.
func BenchmarkLoggerInvocation(b *testing.B) {
for _, mode := range []string{"DirectJSON", "BoundINFO", "BindAndINFO", "WrappedINFO", "Filtered"} {
b.Run(mode, func(b *testing.B) {
for _, key := range []string{"POWERTOOLS_DEV", "POWERTOOLS_LOG_LEVEL", "POWERTOOLS_LOGGER_SAMPLE_RATE", "AWS_LAMBDA_LOG_LEVEL", "POWERTOOLS_LOGGER_LOG_EVENT"} {
b.Setenv(key, "")
}
b.Setenv("AWS_LAMBDA_FUNCTION_NAME", "benchmark")
b.Setenv("AWS_LAMBDA_FUNCTION_MEMORY_SIZE", "256")
ctx := lambdacontext.NewContext(context.Background(), &lambdacontext.LambdaContext{
AwsRequestID: "request-123", InvokedFunctionArn: "arn:aws:lambda:ap-east-1:123456789012:function:benchmark",
})
ctx = context.WithValue(ctx, "x-amzn-trace-id", "Root=1-12345678-123456789012345678901234;Sampled=0")
var out benchmarkWriter
level := InfoLevel
if mode == "Filtered" {
level = WarnLevel
}
log := New(WithOutput(&out), WithLevel(level), WithSampleRate(0), WithServiceName("benchmark"), WithClock(func() time.Time {
return time.Date(2026, 10, 15, 0, 0, 0, 0, time.UTC)
}))
// All modes compare warm invocation records, including cold_start=false.
warmup := WrapHandler(log, func(context.Context, int) (int, error) { return 0, nil })
if _, err := warmup(ctx, 0); err != nil {
b.Fatal(err)
}
fields := Fields{"case_id": "case-123", "records": 3, "checksum": 210}
write := func(bound *Logger) error {
if mode == "DirectJSON" {
data, err := json.Marshal(bound.record(InfoLevel, "benchmark", fields))
if err != nil {
return err
}
_, err = out.Write(append(data, '\n'))
return err
}
return bound.Info("benchmark", fields)
}
b.ReportAllocs()
if mode == "WrappedINFO" {
handler := WrapHandler(log, func(ctx context.Context, _ int) (int, error) {
return 0, write(log.WithContext(ctx))
})
b.ResetTimer()
for b.Loop() {
if _, err := handler(ctx, 0); err != nil {
b.Fatal(err)
}
}
} else {
handler := WrapHandler(log, func(ctx context.Context, _ int) (int, error) {
bound := log.WithContext(ctx)
b.ResetTimer()
for b.Loop() {
current := bound
if mode == "BindAndINFO" {
current = log.WithContext(ctx)
}
if err := write(current); err != nil {
b.Fatal(err)
}
}
b.StopTimer()
return 0, nil
})
if _, err := handler(ctx, 0); err != nil {
b.Fatal(err)
}
}
b.StopTimer()
b.ReportMetric(float64(out.bytes)/float64(b.N), "output-B/op")
})
}
}

func BenchmarkErrorStack(b *testing.B) {
for _, mode := range []string{"disabled", "logging", "attached", "capture-and-log", "filtered"} {
b.Run(mode, func(b *testing.B) {
Expand Down
Loading