Attention is currently required from: Alan Donovan.
Jonathan Amsterdam would like Alan Donovan to review this change.
slog: FromContext delivers context to Handler
This CL provides a way for a Handler to obtain a context, by using the
FromContext method to add it to the Logger it returns.
It is often asked that Handler.Handle be given access to the context
of the log line. The main reason is to allow logs to contain a trace
ID, so they can be correlated with tracing. Observability systems like
Open Telemetry store trace information in the context.
The usual suggestion is to add a context argument to log methods:
slog.Info(ctx, "message")
But that imposes a burden on all users, even those who don't need
the context.
Another solution is to create a new Logger each time a new trace
element ("span" in Open Telemetry terminology) is created, with an
attribute containing the span (or the context). This means that
everyone who creates a span must remember to create a Logger as well,
or it requires wrapping this package in another, context-aware one.
This CL implements an alternative: slog.FromContext(ctx) both
retrieves a Logger from ctx and arranges matters so that subsequent
uses of that Logger install ctx in the generated Record, where it is
available to Handlers.
The changes are:
- The Logger struct now includes a context as well as a Handler.
- FromContext(ctx) retrieves a Logger from ctx (or gets the default
logger), as it always has. Then it creates and returns a new
Logger that contains the same Handler as the retrieved one, but
whose context is FromContext's argument, ctx.
- To avoid allocation in the above, Logger is changed from a pointer
type to a value type. Since it is immutable, its semantics are
unchanged.
- Record has a new ctx field and a Context method to retrieve it.
- NewRecord gains an additional argument for the context.
- When a Logger l creates a Record r to pass to a Handler, it
sets r.ctx to l.ctx.
The great advantage of this feature is that it delivers contexts to
Handlers "for free," with no calls other than the ones that would
normally take place: retrieving a Logger from a context and invoking a
logging method like Info or Log.
Some disadvantages:
- FromContext is overloaded to perform two conceptually unrelated
tasks: fetch a Logger from a context, and deliver that context to a
Handler. There is no a priori reason why a program that passes
Loggers via contexts would need those contexts for anything else, or
that a program that wants its Handler to see contexts must also pass
Loggers around in contexts. But though these two properties need not
be linked, they often are. One way to look at it is that we treat a
call to FromContext as a signal that Handlers want contexts.
- The context delivered to the Handler comes from the Logger, not the
log line. If a new context is established between the call to
FromContext and the call to the logging method, then the Handler
will get the old context. We believe that this is an unlikely footgun:
usually calls to FromContext will be close to logging calls, and
we expect that often the two calls will be chained.
- Changing Logger to a value type quadruples its size (from a one-word
pointer to a four-word struct). Our benchmarks show small slowdowns
for the fastest operations (that make unrealistically optimistic
assumptions), and none for slower (and more practical) ones.
Change-Id: I552b722c118d11406a05412e999c0b629b50228c
---
M slog/benchmarks/handlers_test.go
M slog/benchmarks/slog-pc.bench
M slog/benchmarks/slog.bench
M slog/context.go
A slog/context_test.go
M slog/handler_test.go
M slog/json_handler_test.go
M slog/logger.go
M slog/logger_test.go
M slog/record.go
M slog/record_test.go
M slog/text_handler_test.go
12 files changed, 330 insertions(+), 197 deletions(-)
diff --git a/slog/benchmarks/handlers_test.go b/slog/benchmarks/handlers_test.go
index 223bfca..623a588 100644
--- a/slog/benchmarks/handlers_test.go
+++ b/slog/benchmarks/handlers_test.go
@@ -9,7 +9,7 @@
)
func TestHandlers(t *testing.T) {
- r := slog.NewRecord(TestTime, slog.InfoLevel, TestMessage, 0)
+ r := slog.NewRecord(TestTime, slog.InfoLevel, TestMessage, 0, nil)
r.AddAttrs(TestAttrs...)
t.Run("text", func(t *testing.T) {
var b bytes.Buffer
diff --git a/slog/benchmarks/slog-pc.bench b/slog/benchmarks/slog-pc.bench
index 899db0c..ec5773e 100644
--- a/slog/benchmarks/slog-pc.bench
+++ b/slog/benchmarks/slog-pc.bench
@@ -2,80 +2,80 @@
goarch: amd64
pkg: golang.org/x/exp/slog/benchmarks
cpu: Intel(R) Xeon(R) CPU @ 2.20GHz
-BenchmarkAttrs/disabled/5_args-8 100000000 10.02 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 120896504 9.981 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 100000000 10.23 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 100000000 10.06 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 120556380 9.942 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 62952199 17.94 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 63987754 18.04 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 62148806 18.09 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 60456765 18.01 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 63532894 18.07 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18832660 63.05 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18503997 63.05 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18793000 63.33 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18851764 62.90 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18620378 63.33 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 3081579 386.9 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 2594556 389.4 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 3092631 387.6 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 3095012 396.3 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 3090172 389.4 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 1816550 682.2 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 1721044 692.5 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 1749418 674.9 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 1728466 712.4 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 1780058 676.4 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 510950 2316 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 489726 2332 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 464305 2298 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 499432 2455 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 462938 2300 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 2519834 481.5 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 2521468 481.4 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 2465902 486.9 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 2511697 474.6 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 2455657 497.1 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 1217221 922.8 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 1303630 920.9 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 1331846 915.3 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 1300803 905.6 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 1342477 908.3 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 370690 3211 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 382737 3269 ns/op 1413 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 397886 3160 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 389143 3125 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 395041 3141 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1205694 985.4 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1000000 1013 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1214325 977.5 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1202088 985.5 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1000000 1017 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 771573 1641 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 805484 1651 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 756583 1652 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 811674 1642 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 812188 1630 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 223544 5286 ns/op 1477 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 243157 5573 ns/op 1477 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 226200 5568 ns/op 1477 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 231757 5341 ns/op 1477 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 230116 5308 ns/op 1477 B/op 17 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1347787 893.8 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1340078 880.7 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1333688 899.6 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1440332 825.5 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1390076 851.6 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 865652 1498 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 857676 1501 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 895814 1483 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 943058 1497 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 888254 1452 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 232080 5004 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 262764 4974 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 249297 4970 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 230474 4990 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 248367 4970 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/disabled/5_args-8 94554660 10.92 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 110078395 11.51 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 97356754 10.92 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 109926368 11.52 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 94894854 10.96 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 63471238 18.92 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 60327856 19.22 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 55228566 18.96 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 54294288 18.91 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 57756232 18.97 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 16174478 63.81 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17836287 63.96 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17780865 64.14 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17860651 63.88 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17956210 67.09 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 2984052 391.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3018878 391.8 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3027650 392.0 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3052399 412.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3034406 392.1 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1681460 720.0 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1695465 708.2 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1681596 710.2 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1671854 697.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1536596 712.3 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 518540 2317 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 497006 2314 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 511555 2373 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 491882 2313 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 455605 2380 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2461558 481.0 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2382208 524.1 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2142504 505.6 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2471672 511.5 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2250338 488.6 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1280070 959.5 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1283004 936.4 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1275009 941.7 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1280342 932.2 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1274240 936.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 350898 3161 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 366386 3196 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 353715 3235 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 350161 3257 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 344983 3230 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1109584 1008 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1000000 1011 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1200480 1003 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1204640 1013 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1211356 1004 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 660295 1650 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 726811 1684 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 687387 1666 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 690567 1647 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 640334 1634 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 221350 5293 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 211747 5233 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 215983 5321 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 217386 5355 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 226888 5358 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1388722 848.0 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1380024 863.4 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1457356 829.5 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1463515 866.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1393197 832.6 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 754570 1519 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 763770 1512 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 753477 1454 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 616820 1662 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 689314 1523 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 221842 5128 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 244838 4973 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 249529 4953 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 218718 4969 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 230138 4936 ns/op 1412 B/op 1 allocs/op
PASS
-ok golang.org/x/exp/slog/benchmarks 113.516s
+ok golang.org/x/exp/slog/benchmarks 115.554s
diff --git a/slog/benchmarks/slog.bench b/slog/benchmarks/slog.bench
index 5a520a3..d0a2480 100644
--- a/slog/benchmarks/slog.bench
+++ b/slog/benchmarks/slog.bench
@@ -2,80 +2,80 @@
goarch: amd64
pkg: golang.org/x/exp/slog/benchmarks
cpu: Intel(R) Xeon(R) CPU @ 2.20GHz
-BenchmarkAttrs/disabled/5_args-8 120793970 10.09 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 120658738 9.899 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 100000000 10.01 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 100000000 10.01 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/5_args-8 120536524 9.989 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 64657927 18.04 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 63846556 18.06 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 63629414 18.02 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 64100286 19.21 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/10_args-8 65766166 18.12 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18972454 63.28 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18783354 64.29 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18715994 63.11 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18988142 63.22 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/disabled/40_args-8 18678668 63.03 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 15315618 78.12 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 15137607 78.32 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 15149436 78.73 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 15181647 81.45 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/5_args-8 15160042 77.58 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 4704374 274.1 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 4397641 268.1 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 4408592 276.0 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 4068620 289.2 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/10_args-8 4362400 268.4 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 1282314 949.3 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 1282678 953.8 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 1288890 938.6 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 1325292 976.2 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/async_discard/40_args-8 1298730 921.9 ns/op 1408 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 7389552 157.3 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 7859308 172.5 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 5420155 233.2 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 6782334 173.1 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/5_args-8 5866044 210.0 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 2312252 518.3 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 2258119 532.0 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 2281345 512.9 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 2327382 512.6 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/10_args-8 2330041 518.1 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 633972 1977 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 609144 1960 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 607858 2006 ns/op 1412 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 637404 1948 ns/op 1411 B/op 1 allocs/op
-BenchmarkAttrs/fastText_discard/40_args-8 645720 1982 ns/op 1411 B/op 1 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1742284 687.7 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1761308 679.4 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1678760 706.1 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1644138 726.8 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/5_args-8 1725314 719.6 ns/op 8 B/op 2 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 1000000 1305 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 1000000 1249 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 1000000 1246 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 1000000 1247 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/10_args-8 1000000 1261 ns/op 224 B/op 5 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 256171 4429 ns/op 1476 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 301150 4270 ns/op 1476 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 252357 4238 ns/op 1476 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 328380 4245 ns/op 1476 B/op 17 allocs/op
-BenchmarkAttrs/Text_discard/40_args-8 301352 4192 ns/op 1477 B/op 17 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1827435 635.1 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1804364 652.4 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1928208 627.1 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1893918 574.8 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/5_args-8 1791198 664.7 ns/op 0 B/op 0 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 1000000 1168 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 1000000 1153 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 1000000 1130 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 1000000 1118 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/10_args-8 1000000 1163 ns/op 208 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 319970 3941 ns/op 1411 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 304051 4078 ns/op 1411 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 310402 3868 ns/op 1411 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 332454 4042 ns/op 1411 B/op 1 allocs/op
-BenchmarkAttrs/JSON_discard/40_args-8 326292 3939 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/disabled/5_args-8 109706182 11.07 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 109895538 10.92 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 95186716 10.98 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 109625517 10.94 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 109824247 10.86 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 55718899 19.92 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 54884460 18.98 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 54375565 18.94 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 55062667 18.97 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 55031552 18.97 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17677623 64.45 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17164767 67.86 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17483728 64.10 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17273491 64.42 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 17822889 64.35 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13549754 82.44 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13660240 82.61 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 14187956 81.81 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13945921 82.44 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 12832858 82.92 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4449036 290.1 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4457036 273.9 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4369323 271.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4303984 275.6 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4384927 279.9 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1283209 938.4 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1313527 927.5 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1248141 984.6 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1287324 937.0 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1251534 894.9 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 4309944 254.3 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 5463175 222.0 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 5785550 198.3 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 5637102 251.3 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 7133055 169.0 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2294208 527.1 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2285610 531.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2292446 514.5 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2261302 534.6 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2307585 527.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 595398 2002 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 538484 2037 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 599130 1971 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 600004 1993 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 568270 1932 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1661556 737.2 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1675798 714.8 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1723910 702.7 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1720911 691.1 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1667749 698.6 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 1000000 1243 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 944620 1280 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 993868 1231 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 873902 1256 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 909956 1252 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 265416 4281 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 283650 4361 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 281052 4388 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 258106 4358 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 281142 4194 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1853120 624.3 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1891280 641.6 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1819586 625.9 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1845736 640.5 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1903868 576.3 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 954238 1162 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 991620 1151 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 964339 1192 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1158 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1138 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 307032 4066 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 309223 4004 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 298754 4053 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 287901 4080 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 274047 4023 ns/op 1411 B/op 1 allocs/op
PASS
-ok golang.org/x/exp/slog/benchmarks 111.625s
+ok golang.org/x/exp/slog/benchmarks 111.981s
diff --git a/slog/context.go b/slog/context.go
index 7d5b98e..2cb036a 100644
--- a/slog/context.go
+++ b/slog/context.go
@@ -10,15 +10,18 @@
// NewContext returns a context that contains the given Logger.
// Use FromContext to retrieve the Logger.
-func NewContext(ctx context.Context, l *Logger) context.Context {
+func NewContext(ctx context.Context, l Logger) context.Context {
return context.WithValue(ctx, contextKey{}, l)
}
-// FromContext returns the Logger stored in ctx by NewContext, or the default
-// Logger if there is none.
-func FromContext(ctx context.Context) *Logger {
- if l, ok := ctx.Value(contextKey{}).(*Logger); ok {
- return l
+// FromContext retrieves the Logger stored in ctx by NewContext, or the default
+// Logger if there is none, and adds ctx to it. Handlers can retrieve the
+// context with [Record.Context].
+func FromContext(ctx context.Context) Logger {
+ l, ok := ctx.Value(contextKey{}).(Logger)
+ if !ok {
+ l = Default()
}
- return Default()
+ l.ctx = ctx
+ return l
}
diff --git a/slog/context_test.go b/slog/context_test.go
new file mode 100644
index 0000000..665c5a5
--- /dev/null
+++ b/slog/context_test.go
@@ -0,0 +1,34 @@
+// Copyright 2022 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package slog
+
+import (
+ "context"
+ "testing"
+)
+
+func TestContext(t *testing.T) {
+ // If there is no Logger in the context, FromContext returns the default
+ // Logger.
+ ctx := context.Background()
+ gotl := FromContext(ctx)
+ if _, ok := gotl.Handler().(*defaultHandler); !ok {
+ t.Error("did not get default Logger")
+ }
+
+ // If there is a Logger in the context, FromContext returns it, with the ctx
+ // arg.
+ h := &captureHandler{}
+ ctx = context.WithValue(ctx, "ID", 1)
+ ctx = NewContext(ctx, New(h))
+ gotl = FromContext(ctx)
+ if gotl.Handler() != h {
+ t.Fatal("did not get the right logger")
+ }
+ gotl.Info("")
+ if g, w := h.r.Context().Value("ID"), 1; g != w {
+ t.Errorf("got ID %v, want %v", g, w)
+ }
+}
diff --git a/slog/handler_test.go b/slog/handler_test.go
index b956d81..6219991 100644
--- a/slog/handler_test.go
+++ b/slog/handler_test.go
@@ -97,7 +97,7 @@
if test.with != nil {
h = test.with(h)
}
- r := NewRecord(time.Time{}, InfoLevel, "message", 0)
+ r := NewRecord(time.Time{}, InfoLevel, "message", 0, nil)
r.AddAttrs(test.attrs...)
if err := h.Handle(r); err != nil {
t.Fatal(err)
@@ -261,7 +261,7 @@
wantJSON: `{"msg":"message","p1":1,"s1":{"s2":{"a":"one","b":2}}}`,
},
} {
- r := NewRecord(testTime, InfoLevel, "message", 1)
+ r := NewRecord(testTime, InfoLevel, "message", 1, nil)
r.AddAttrs(test.attrs...)
var buf bytes.Buffer
opts := HandlerOptions{ReplaceAttr: test.replace}
diff --git a/slog/json_handler_test.go b/slog/json_handler_test.go
index df0628b..4a3d4fe 100644
--- a/slog/json_handler_test.go
+++ b/slog/json_handler_test.go
@@ -39,7 +39,7 @@
t.Run(test.name, func(t *testing.T) {
var buf bytes.Buffer
h := test.opts.NewJSONHandler(&buf)
- r := NewRecord(testTime, InfoLevel, "m", 0)
+ r := NewRecord(testTime, InfoLevel, "m", 0, nil)
r.AddAttrs(Int("a", 1), Any("m", map[string]int{"b": 2}))
if err := h.Handle(r); err != nil {
t.Fatal(err)
diff --git a/slog/logger.go b/slog/logger.go
index e79c3b4..06728fa 100644
--- a/slog/logger.go
+++ b/slog/logger.go
@@ -5,6 +5,7 @@
package slog
import (
+ "context"
"log"
"sync/atomic"
"time"
@@ -13,18 +14,18 @@
var defaultLogger atomic.Value
func init() {
- defaultLogger.Store(&Logger{
+ defaultLogger.Store(Logger{
handler: newDefaultHandler(log.Output),
})
}
// Default returns the default Logger.
-func Default() *Logger { return defaultLogger.Load().(*Logger) }
+func Default() Logger { return defaultLogger.Load().(Logger) }
// SetDefault makes l the default Logger.
// After this call, output from the log package's default Logger
// (as with [log.Print], etc.) will be logged at InfoLevel using l's Handler.
-func SetDefault(l *Logger) {
+func SetDefault(l Logger) {
defaultLogger.Store(l)
// If the default's handler is a defaultHandler, then don't use a handleWriter,
// or we'll deadlock as try to acquire the log default mutex.
@@ -53,7 +54,7 @@
if len(buf) > 0 && buf[len(buf)-1] == '\n' {
buf = buf[:len(buf)-1]
}
- r := NewRecord(time.Now(), InfoLevel, string(buf), depth)
+ r := NewRecord(time.Now(), InfoLevel, string(buf), depth, nil)
return origLen, w.h.Handle(r)
}
@@ -64,15 +65,16 @@
// Loggers are immutable; to create a new one, call [New] or [Logger.With].
type Logger struct {
handler Handler // for structured logging
+ ctx context.Context
}
// Handler returns l's Handler.
-func (l *Logger) Handler() Handler { return l.handler }
+func (l Logger) Handler() Handler { return l.handler }
// With returns a new Logger whose handler's attributes are a concatenation of
// l's attributes and the given arguments, converted to Attrs as in
// [Logger.Log].
-func (l *Logger) With(args ...any) *Logger {
+func (l Logger) With(args ...any) Logger {
var (
attr Attr
attrs []Attr
@@ -81,7 +83,7 @@
attr, args = argsToAttr(args)
attrs = append(attrs, attr)
}
- return &Logger{handler: l.handler.With(attrs)}
+ return Logger{handler: l.handler.With(attrs)}
}
// WithScope returns a new Logger with the named scope.
@@ -89,20 +91,20 @@
// to the given name. Two loggers with different scope names
// but identical Attr keys will result in output without
// duplicate keys.
-func (l *Logger) WithScope(name string) *Logger {
- return &Logger{handler: l.handler.WithScope(name)}
+func (l Logger) WithScope(name string) Logger {
+ return Logger{handler: l.handler.WithScope(name)}
}
// New creates a new Logger with the given Handler.
-func New(h Handler) *Logger { return &Logger{handler: h} }
+func New(h Handler) Logger { return Logger{handler: h} }
// With calls Logger.With on the default logger.
-func With(args ...any) *Logger {
+func With(args ...any) Logger {
return Default().With(args...)
}
// Enabled reports whether l emits log records at the given level.
-func (l *Logger) Enabled(level Level) bool {
+func (l Logger) Enabled(level Level) bool {
return l.Handler().Enabled(level)
}
@@ -116,14 +118,14 @@
// the following argument is treated as the value and the two are combined
// into an Attr.
// - Otherwise, the argument is treated as a value with key "!BADKEY".
-func (l *Logger) Log(level Level, msg string, args ...any) {
+func (l Logger) Log(level Level, msg string, args ...any) {
l.LogDepth(0, level, msg, args...)
}
// LogDepth is like [Logger.Log], but accepts a call depth to adjust the
// file and line number in the log record. 0 refers to the caller
// of LogDepth; 1 refers to the caller's caller; and so on.
-func (l *Logger) LogDepth(calldepth int, level Level, msg string, args ...any) {
+func (l Logger) LogDepth(calldepth int, level Level, msg string, args ...any) {
if !l.Enabled(level) {
return
}
@@ -138,21 +140,21 @@
// Eventually, getting the pc should be fast.
func disableSourceLine() { useSourceLine = false }
-func (l *Logger) makeRecord(msg string, level Level, depth int) Record {
+func (l Logger) makeRecord(msg string, level Level, depth int) Record {
if useSourceLine {
depth += 5
}
- return NewRecord(time.Now(), level, msg, depth)
+ return NewRecord(time.Now(), level, msg, depth, l.ctx)
}
// LogAttrs is a more efficient version of [Logger.Log] that accepts only Attrs.
-func (l *Logger) LogAttrs(level Level, msg string, attrs ...Attr) {
+func (l Logger) LogAttrs(level Level, msg string, attrs ...Attr) {
l.LogAttrsDepth(0, level, msg, attrs...)
}
// LogAttrsDepth is like [Logger.LogAttrs], but accepts a call depth argument
// which it interprets like [Logger.LogDepth].
-func (l *Logger) LogAttrsDepth(calldepth int, level Level, msg string, attrs ...Attr) {
+func (l Logger) LogAttrsDepth(calldepth int, level Level, msg string, attrs ...Attr) {
if !l.Enabled(level) {
return
}
@@ -162,24 +164,24 @@
}
// Debug logs at DebugLevel.
-func (l *Logger) Debug(msg string, args ...any) {
+func (l Logger) Debug(msg string, args ...any) {
l.LogDepth(0, DebugLevel, msg, args...)
}
// Info logs at InfoLevel.
-func (l *Logger) Info(msg string, args ...any) {
+func (l Logger) Info(msg string, args ...any) {
l.LogDepth(0, InfoLevel, msg, args...)
}
// Warn logs at WarnLevel.
-func (l *Logger) Warn(msg string, args ...any) {
+func (l Logger) Warn(msg string, args ...any) {
l.LogDepth(0, WarnLevel, msg, args...)
}
// Error logs at ErrorLevel.
// If err is non-nil, Error appends Any("err", err)
// to the list of attributes.
-func (l *Logger) Error(msg string, err error, args ...any) {
+func (l Logger) Error(msg string, err error, args ...any) {
if err != nil {
// TODO: avoid the copy.
args = append(args[:len(args):len(args)], Any("err", err))
diff --git a/slog/logger_test.go b/slog/logger_test.go
index 83a10d7..6ebddf8 100644
--- a/slog/logger_test.go
+++ b/slog/logger_test.go
@@ -158,7 +158,7 @@
func TestAlloc(t *testing.T) {
dl := New(discardHandler{})
- defer func(d *Logger) { SetDefault(d) }(Default())
+ defer func(d Logger) { SetDefault(d) }(Default())
SetDefault(dl)
t.Run("Info", func(t *testing.T) {
@@ -265,7 +265,7 @@
{[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}},
{[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}},
} {
- r := NewRecord(time.Time{}, 0, "", 0)
+ r := NewRecord(time.Time{}, 0, "", 0, nil)
r.setAttrsFromArgs(test.args)
got := attrsSlice(r)
if !attrsEqual(got, test.want) {
diff --git a/slog/record.go b/slog/record.go
index 7e58b87..792f511 100644
--- a/slog/record.go
+++ b/slog/record.go
@@ -5,6 +5,7 @@
package slog
import (
+ "context"
"runtime"
"time"
@@ -27,6 +28,9 @@
// The level of the event.
level Level
+ // The Logger's context, non-nil if the Logger was obtained with FromContext.
+ ctx context.Context
+
// The pc at the time the record was constructed, as determined
// by runtime.Callers using the calldepth argument to NewRecord.
pc uintptr
@@ -54,7 +58,7 @@
//
// NewRecord is intended for logging APIs that want to support a [Handler] as
// a backend.
-func NewRecord(t time.Time, level Level, msg string, calldepth int) Record {
+func NewRecord(t time.Time, level Level, msg string, calldepth int, ctx context.Context) Record {
var p uintptr
if calldepth > 0 {
p = pc(calldepth + 1)
@@ -63,6 +67,7 @@
time: t,
message: msg,
level: level,
+ ctx: ctx,
pc: p,
}
}
@@ -76,6 +81,12 @@
// Level returns the level of the log event.
func (r Record) Level() Level { return r.level }
+// Context returns the context in the Record.
+// A Record will have a non-nil context only if
+// it was created by a Logger that was obtained
+// with [FromContext].
+func (r Record) Context() context.Context { return r.ctx }
+
// SourceLine returns the file and line of the log event.
// If the Record was created without the necessary information,
// or if the location is unavailable, it returns ("", 0).
diff --git a/slog/record_test.go b/slog/record_test.go
index afbd142..08e3a09 100644
--- a/slog/record_test.go
+++ b/slog/record_test.go
@@ -36,7 +36,7 @@
{-16, "", false},
{1, "record.go", true},
} {
- r := NewRecord(time.Time{}, 0, "", test.depth)
+ r := NewRecord(time.Time{}, 0, "", test.depth, nil)
gotFile, gotLine := r.SourceLine()
if i := strings.LastIndexByte(gotFile, '/'); i >= 0 {
gotFile = gotFile[i+1:]
@@ -67,7 +67,7 @@
// Create a record whose Attrs overflow the inline array,
// creating a slice in r.back.
- r1 := NewRecord(time.Time{}, 0, "", 0)
+ r1 := NewRecord(time.Time{}, 0, "", 0, nil)
r1.AddAttrs(intAttrs(0, nAttrsInline+1)...)
// Ensure that r1.back's capacity exceeds its length.
b := make([]Attr, len(r1.back), len(r1.back)+1)
@@ -90,7 +90,7 @@
}
func newRecordWithAttrs(as []Attr) Record {
- r := NewRecord(time.Now(), InfoLevel, "", 0)
+ r := NewRecord(time.Now(), InfoLevel, "", 0, nil)
r.AddAttrs(as...)
return r
}
@@ -117,7 +117,7 @@
}
func BenchmarkSourceLine(b *testing.B) {
- r := NewRecord(time.Now(), InfoLevel, "", 5)
+ r := NewRecord(time.Now(), InfoLevel, "", 5, nil)
b.Run("alone", func(b *testing.B) {
for i := 0; i < b.N; i++ {
file, line := r.SourceLine()
@@ -144,7 +144,7 @@
var a Attr
for i := 0; i < b.N; i++ {
- r := NewRecord(time.Time{}, InfoLevel, "", 0)
+ r := NewRecord(time.Time{}, InfoLevel, "", 0, nil)
for j := 0; j < nAttrs; j++ {
r.AddAttrs(Int("k", j))
}
diff --git a/slog/text_handler_test.go b/slog/text_handler_test.go
index dc75c91..8628ba5 100644
--- a/slog/text_handler_test.go
+++ b/slog/text_handler_test.go
@@ -72,7 +72,7 @@
t.Run(opts.name, func(t *testing.T) {
var buf bytes.Buffer
h := opts.opts.NewTextHandler(&buf)
- r := NewRecord(testTime, InfoLevel, "a message", 0)
+ r := NewRecord(testTime, InfoLevel, "a message", 0, nil)
r.AddAttrs(test.attr)
if err := h.Handle(r); err != nil {
t.Fatal(err)
@@ -114,7 +114,7 @@
func TestTextHandlerSource(t *testing.T) {
var buf bytes.Buffer
h := HandlerOptions{AddSource: true}.NewTextHandler(&buf)
- r := NewRecord(testTime, InfoLevel, "m", 2)
+ r := NewRecord(testTime, InfoLevel, "m", 2, nil)
if err := h.Handle(r); err != nil {
t.Fatal(err)
}
@@ -142,7 +142,7 @@
var h Handler = NewTextHandler(&buf)
h = h.With([]Attr{Duration("dur", time.Minute), Bool("b", true)})
// Also test omitting time.
- r := NewRecord(time.Time{}, 0 /* 0 Level is INFO */, "m", 0)
+ r := NewRecord(time.Time{}, 0 /* 0 Level is INFO */, "m", 0, nil)
r.AddAttrs(Int("a", 1))
if err := h.Handle(r); err != nil {
t.Fatal(err)
@@ -155,7 +155,7 @@
}
func TestTextHandlerAlloc(t *testing.T) {
- r := NewRecord(time.Now(), InfoLevel, "msg", 0)
+ r := NewRecord(time.Now(), InfoLevel, "msg", 0, nil)
for i := 0; i < 10; i++ {
r.AddAttrs(Int("x = y", i))
}
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Alan Donovan, Jonathan Amsterdam, Russ Cox.
Set Ready For Review
Attention is currently required from: Alan Donovan, Russ Cox.
1 comment:
Patchset:
Ready for review.
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Jonathan Amsterdam, Russ Cox.
3 comments:
Patchset:
Sorry for the delay.
File slog/logger.go:
Patch Set #3, Line 67: // Loggers are immutable; to create a new one, call [New] or Logger method
Handlers can have state (as can Contexts, though that's frowned upon), so perhaps this statement is not strictly accurate.
Might we want to add mutable fields to a Logger in future? By eliminating the pointer in all the function signatures, we rule that out permanently.
File slog/record.go:
Patch Set #3, Line 61: func NewRecord(t time.Time, level Level, msg string, calldepth int, ctx context.Context) Record {
Explain the purpose of the Context, especially as it is quite different to the norm. Contexts are usually for controlling cancellation of a task, or for providing key/value pairs, but here it is decidedly not for either of those purposes: we expect log Records to outlive their contexts, and to use Attrs for most k/v pairs.
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Alan Donovan, Jonathan Amsterdam, Russ Cox.
Jonathan Amsterdam uploaded patch set #4 to this change.
The following approvals got outdated and were removed: Run-TryBot+1 by Jonathan Amsterdam, TryBot-Result+1 by Gopher Robot
slog: Loggers hold contexts
This CL provides a way to pass contexts to Handlers.
It is often asked that Handler.Handle be given access to the context
of the log line. The main reason is to allow logs to contain a trace
ID, so they can be correlated with tracing. Observability systems like
Open Telemetry store trace information in the context.
The usual suggestion is to add a context argument to log methods:
slog.Info(ctx, "message")
But that imposes a burden on all users, even those who don't need
the context.
Another solution is to create a new Logger each time a new trace
element ("span" in Open Telemetry terminology) is created, with an
attribute containing the span (or the context). This means that
everyone who creates a span must remember to create a Logger as well,
or it requires wrapping this package in another, context-aware one.
This CL implements the following alternative:
- A Logger now holds a context as well as a Handler.
- Logger.Context returns this context.
- Logger.WithContext returns a new Logger with a given context.
- To avoid allocation in WithContext, Logger is changed from a pointer
type to a value type. Since it is immutable, its semantics are
unchanged. Its size is quadrupled (from a one-word pointer to a
four-word struct); our benchmarks show small slowdowns for the
fastest operations (that make unrealistically optimistic
assumptions), and none for slower (and more practical) ones.
- Record has a new ctx field and a Context method to retrieve it.
- NewRecord gains an additional argument for the context.
- When a Logger l creates a Record r to pass to a Handler, it
sets r.ctx to l.ctx.
- The top-level Ctx function both retrieves a Logger from a given
context, and adds that context to the logger: it is equivalent to
FromContext(ctx).WithContext(ctx)
Change-Id: I552b722c118d11406a05412e999c0b629b50228c
---
M slog/benchmarks/handlers_test.go
M slog/benchmarks/slog-pc.bench
M slog/benchmarks/slog.bench
M slog/context.go
A slog/context_test.go
M slog/handler_test.go
M slog/json_handler_test.go
M slog/logger.go
M slog/logger_test.go
M slog/record.go
M slog/record_test.go
M slog/text_handler_test.go
12 files changed, 332 insertions(+), 195 deletions(-)
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Alan Donovan, Jonathan Amsterdam, Russ Cox.
2 comments:
File slog/logger.go:
Patch Set #3, Line 67: // Loggers are immutable; to create a new one, call [New] or Logger method
Handlers can have state (as can Contexts, though that's frowned upon), so perhaps this statement is […]
Removed "immutable."
I don't understand your second point. Couldn't we add later a method with a *Logger receiver?
File slog/record.go:
Patch Set #3, Line 61: func NewRecord(t time.Time, level Level, msg string, calldepth int, ctx context.Context) Record {
Explain the purpose of the Context, especially as it is quite different to the norm. […]
I added a line to the doc, but I think this _is_ for providing key/value pairs.
Also, I'll move this doc up to the doc for the Context field when I export it later (upstack).
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Jonathan Amsterdam, Russ Cox.
Patch set 4:Code-Review +2
2 comments:
File slog/logger.go:
Patch Set #3, Line 67: // Loggers are immutable; to create a new one, call [New] or Logger method
Couldn't we add later a method with a *Logger receiver?
Not really, because in general later additions that make the value mutable will mean that making copies of it is no longer valid (for example, because it leads to aliasing problems), and lots of functions will by then exist in our code and in user code that copy Logger values.
File slog/record.go:
Patch Set #4, Line 60: // the context's values.
s/with //
Perhaps add: "Cancellation of the context does not affect record processing."
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
File slog/logger.go:
Patch Set #3, Line 67: // Loggers are immutable; to create a new one, call [New] or Logger method
> Couldn't we add later a method with a *Logger receiver? […]
So you're saying that if we have a method with a pointer receiver, users should expect and guard against mutation.
However, doesn't that somewhat contradict the principle of providing a consistent view of a type (either value with value receivers, or pointer with pointer receivers)?
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Alan Donovan, Jonathan Amsterdam, Russ Cox.
Jonathan Amsterdam uploaded patch set #5 to this change.
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Alan Donovan, Jonathan Amsterdam, Russ Cox.
1 comment:
File slog/record.go:
Patch Set #4, Line 60: // the context's values.
s/with // […]
Done
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Jonathan Amsterdam submitted this change.
4 is the latest approved patch-set.
The change was submitted with unreviewed changes in the following files:
```
The name of the file: slog/record.go
Insertions: 2, Deletions: 2.
@@ -56,8 +56,8 @@
// return the file and line number at that depth,
// where 1 means the caller of NewRecord.
//
-// A Record stores a context solely to provide Handlers with access to
-// the context's values.
+// A Record stores a context solely to provide Handlers access to the context's
+// values. Cancellation of the context does not affect record processing.
//
// NewRecord is intended for logging APIs that want to support a [Handler] as
// a backend.
```
Reviewed-on: https://go-review.googlesource.com/c/exp/+/439059
Run-TryBot: Jonathan Amsterdam <j...@google.com>
Reviewed-by: Alan Donovan <adon...@google.com>
---
M slog/benchmarks/handlers_test.go
M slog/benchmarks/slog-pc.bench
M slog/benchmarks/slog.bench
M slog/context.go
A slog/context_test.go
M slog/handler_test.go
M slog/json_handler_test.go
M slog/logger.go
M slog/logger_test.go
M slog/record.go
M slog/record_test.go
M slog/text_handler_test.go
12 files changed, 335 insertions(+), 195 deletions(-)
diff --git a/slog/benchmarks/handlers_test.go b/slog/benchmarks/handlers_test.go
index 223bfca..623a588 100644
--- a/slog/benchmarks/handlers_test.go
+++ b/slog/benchmarks/handlers_test.go
@@ -9,7 +9,7 @@
)
func TestHandlers(t *testing.T) {
- r := slog.NewRecord(TestTime, slog.InfoLevel, TestMessage, 0)
+ r := slog.NewRecord(TestTime, slog.InfoLevel, TestMessage, 0, nil)
r.AddAttrs(TestAttrs...)
t.Run("text", func(t *testing.T) {
var b bytes.Buffer
diff --git a/slog/benchmarks/slog-pc.bench b/slog/benchmarks/slog-pc.bench
index 899db0c..c4372f7 100644+BenchmarkAttrs/disabled/5_args-8 100000000 10.97 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 100000000 11.03 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 100000000 10.83 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 97441850 10.84 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 95607450 10.82 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 62498384 18.88 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 61121353 18.86 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 62246416 18.88 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 60799956 18.89 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 59061819 18.88 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18597520 64.12 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18031036 64.39 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18696117 63.94 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18752000 63.81 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18493252 63.88 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3089053 402.2 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3071889 389.2 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3114163 386.9 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3103900 386.4 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 3092712 385.4 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1747160 695.9 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1705131 696.5 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1718131 689.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1705776 706.5 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 1695583 704.3 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 462394 2350 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 495303 2381 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 535171 2326 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 457449 2331 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 540910 2323 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2504246 487.5 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2470434 492.9 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2494670 484.9 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2475620 487.3 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 2399865 498.9 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1257261 946.4 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1279915 929.7 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1272433 935.2 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1000000 1002 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 1243527 975.8 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 365814 3315 ns/op 1413 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 336776 3290 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 354438 3241 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 377692 3275 ns/op 1413 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 326116 3290 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 988131 1076 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 983840 1042 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1000000 1028 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 990825 1064 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1000000 1028 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 741379 1727 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 768871 1736 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 712422 1726 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 761432 1715 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 768960 1743 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 224613 5627 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 226648 5848 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 212464 5621 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 219996 5690 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 198876 5662 ns/op 1477 B/op 17 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1322396 876.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1359752 940.1 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1297011 918.5 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1387628 882.2 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1382520 892.2 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 826593 1558 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 815361 1554 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 829800 1551 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 854877 1539 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 835476 1563 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 257505 5145 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 231441 5103 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 236878 5033 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 230604 4987 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 231382 5082 ns/op 1412 B/op 1 allocs/op
PASS
-ok golang.org/x/exp/slog/benchmarks 113.516s
+ok golang.org/x/exp/slog/benchmarks 107.152s
diff --git a/slog/benchmarks/slog.bench b/slog/benchmarks/slog.bench
index 5a520a3..0b58079 100644
+BenchmarkAttrs/disabled/5_args-8 100000000 10.86 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 100000000 10.84 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 100000000 10.83 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 100000000 10.85 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/5_args-8 96611278 10.84 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 57230637 18.90 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 62919320 18.88 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 60301082 19.08 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 61005656 19.00 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/10_args-8 60954086 18.90 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18576979 63.79 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18501492 63.94 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18704040 63.76 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18194610 63.67 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/disabled/40_args-8 18648174 63.85 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13214536 89.16 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 14343093 85.63 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13142229 88.27 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13435146 87.02 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/5_args-8 13708140 88.69 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4533420 280.7 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4527133 274.6 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4155231 283.7 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4192006 282.4 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/10_args-8 4219160 278.0 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1283365 930.1 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1301449 943.2 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1261256 914.3 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1298919 887.4 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/async_discard/40_args-8 1342897 889.1 ns/op 1408 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 6955764 176.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 7571996 157.5 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 6186126 178.4 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 5276200 290.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/5_args-8 6722038 197.9 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2247231 511.6 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2304651 530.3 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2294930 521.2 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2327901 525.4 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/10_args-8 2202255 530.2 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 608607 1982 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 645728 1967 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 600284 1986 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 595011 2067 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/fastText_discard/40_args-8 554013 2037 ns/op 1412 B/op 1 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1675130 728.9 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1702803 744.2 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1592347 754.2 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1658474 737.4 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/5_args-8 1641886 742.2 ns/op 8 B/op 2 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 1000000 1286 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 985032 1301 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 1000000 1285 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 937164 1285 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/10_args-8 1000000 1256 ns/op 224 B/op 5 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 291607 4362 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 276548 4369 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 274687 4354 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 299493 4397 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/Text_discard/40_args-8 283070 4328 ns/op 1476 B/op 17 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1918728 645.7 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 2024074 606.1 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1769748 657.8 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1868710 640.6 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/5_args-8 1965302 627.2 ns/op 0 B/op 0 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1191 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1190 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1240 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1195 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/10_args-8 1000000 1203 ns/op 208 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 349972 4133 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 298383 4087 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 324619 4116 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 302998 4223 ns/op 1411 B/op 1 allocs/op
+BenchmarkAttrs/JSON_discard/40_args-8 323319 4187 ns/op 1411 B/op 1 allocs/op
PASS
-ok golang.org/x/exp/slog/benchmarks 111.625s
+ok golang.org/x/exp/slog/benchmarks 109.134s
diff --git a/slog/context.go b/slog/context.go
index 7d5b98e..538e350 100644
--- a/slog/context.go
+++ b/slog/context.go
@@ -10,15 +10,21 @@
// NewContext returns a context that contains the given Logger.
// Use FromContext to retrieve the Logger.
-func NewContext(ctx context.Context, l *Logger) context.Context {
+func NewContext(ctx context.Context, l Logger) context.Context {
return context.WithValue(ctx, contextKey{}, l)
}
// FromContext returns the Logger stored in ctx by NewContext, or the default
// Logger if there is none.
-func FromContext(ctx context.Context) *Logger {
- if l, ok := ctx.Value(contextKey{}).(*Logger); ok {
+func FromContext(ctx context.Context) Logger {
+ if l, ok := ctx.Value(contextKey{}).(Logger); ok {
return l
}
return Default()
}
+
+// Ctx retrieves a Logger from the given context using FromContext. Then it adds
+// the given context to the Logger using WithContext and returns the result.
+func Ctx(ctx context.Context) Logger {
+ return FromContext(ctx).WithContext(ctx)
+}
diff --git a/slog/context_test.go b/slog/context_test.go
new file mode 100644
index 0000000..126bd1e
--- /dev/null
+++ b/slog/context_test.go
@@ -0,0 +1,49 @@
+// Copyright 2022 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package slog
+
+import (
+ "context"
+ "testing"
+)
+
+func TestContext(t *testing.T) {
+ // If there is no Logger in the context, FromContext returns the default
+ // Logger.
+ ctx := context.Background()
+ gotl := FromContext(ctx)
+ if _, ok := gotl.Handler().(*defaultHandler); !ok {
+ t.Error("did not get default Logger")
+ }
+
+ // If there is a Logger in the context, FromContext returns it, with the ctx
+ // arg.
+ h := &captureHandler{}
+ ctx = NewContext(ctx, New(h))
+ ctx = context.WithValue(ctx, "ID", 1)
+ gotl = FromContext(ctx)
+ if gotl.Handler() != h {
+ t.Fatal("wrong handler")
+ }
+ // FromContext preserves the context of the Logger that was stored
+ // with NewContext, in this case nil.
+ gotl.Info("")
+ if g := h.r.Context(); g != nil {
+ t.Errorf("got %v, want nil", g)
+ }
+ gotl = Ctx(ctx)
+ if gotl.Handler() != h {
+ t.Fatal("wrong handler")
+ }
+ // Ctx adds the argument context to the Logger.
+ gotl.Info("")
+ c := h.r.Context()
+ if c == nil {
+ t.Fatal("got nil Context")
+ }
+ if g, w := c.Value("ID"), 1; g != w {
+ t.Errorf("got ID %v, want %v", g, w)
+ }
+}
diff --git a/slog/handler_test.go b/slog/handler_test.go
index eaa230f..8a967ef 100644
--- a/slog/handler_test.go
+++ b/slog/handler_test.go
@@ -88,7 +88,7 @@
if test.with != nil {
h = test.with(h)
}
- r := NewRecord(time.Time{}, InfoLevel, "message", 0)
+ r := NewRecord(time.Time{}, InfoLevel, "message", 0, nil)
r.AddAttrs(test.attrs...)
if err := h.Handle(r); err != nil {
t.Fatal(err)
@@ -271,7 +271,7 @@
wantJSON: `{"msg":"message","p1":1,"s1":{"s2":{"a":"one","b":2}}}`,
},
} {
- r := NewRecord(testTime, InfoLevel, "message", 1)
+ r := NewRecord(testTime, InfoLevel, "message", 1, nil)
r.AddAttrs(test.attrs...)
var buf bytes.Buffer
opts := HandlerOptions{ReplaceAttr: test.replace}
diff --git a/slog/json_handler_test.go b/slog/json_handler_test.go
index df0628b..4a3d4fe 100644
--- a/slog/json_handler_test.go
+++ b/slog/json_handler_test.go
@@ -39,7 +39,7 @@
t.Run(test.name, func(t *testing.T) {
var buf bytes.Buffer
h := test.opts.NewJSONHandler(&buf)
- r := NewRecord(testTime, InfoLevel, "m", 0)
+ r := NewRecord(testTime, InfoLevel, "m", 0, nil)
r.AddAttrs(Int("a", 1), Any("m", map[string]int{"b": 2}))
if err := h.Handle(r); err != nil {
t.Fatal(err)
diff --git a/slog/logger.go b/slog/logger.go
index 8ac87a6..34e1bd7 100644// or we'll deadlock as they both try to acquire the log default mutex.
@@ -55,7 +56,7 @@
if len(buf) > 0 && buf[len(buf)-1] == '\n' {
buf = buf[:len(buf)-1]
}
- r := NewRecord(time.Now(), InfoLevel, string(buf), depth)
+ r := NewRecord(time.Now(), InfoLevel, string(buf), depth, nil)
return origLen, w.h.Handle(r)
}
@@ -63,18 +64,23 @@
// Log, Debug, Info, Warn, and Error methods.
// For each call, it creates a Record and passes it to a Handler.
//
-// Loggers are immutable; to create a new one, call [New] or [Logger.With].
+// To create a new Logger, call [New] or a Logger method
+// that begins "With".
type Logger struct {
handler Handler // for structured logging
+ ctx context.Context
}
// Handler returns l's Handler.
-func (l *Logger) Handler() Handler { return l.handler }
+func (l Logger) Handler() Handler { return l.handler }
+
+// Context returns l's context.
+func (l Logger) Context() context.Context { return l.ctx }
// With returns a new Logger whose handler's attributes are a concatenation of
// l's attributes and the given arguments, converted to Attrs as in
// [Logger.Log].
-func (l *Logger) With(args ...any) *Logger {
+func (l Logger) With(args ...any) Logger {
var (
attr Attr
attrs []Attr
@@ -83,7 +89,8 @@
attr, args = argsToAttr(args)
attrs = append(attrs, attr)
}
- return &Logger{handler: l.handler.With(attrs)}
+ l.handler = l.handler.With(attrs)
+ return l
}
// WithScope returns a new Logger with the named scope.
@@ -91,20 +98,28 @@
// to the given name. Two loggers with different scope names
// but identical Attr keys will result in output without
// duplicate keys.
-func (l *Logger) WithScope(name string) *Logger {
- return &Logger{handler: l.handler.WithScope(name)}
+func (l Logger) WithScope(name string) Logger {
+ l.handler = l.handler.WithScope(name)
+ return l
+}
+
+// WithContext returns a new Logger with the same handler
+// as the receiver and the given context.
+func (l Logger) WithContext(ctx context.Context) Logger {
+ l.ctx = ctx
+ return l
}
// New creates a new Logger with the given Handler.
-func New(h Handler) *Logger { return &Logger{handler: h} }
+func New(h Handler) Logger { return Logger{handler: h} }
// With calls Logger.With on the default logger.
-func With(args ...any) *Logger {
+func With(args ...any) Logger {
return Default().With(args...)
}
// Enabled reports whether l emits log records at the given level.
-func (l *Logger) Enabled(level Level) bool {
+func (l Logger) Enabled(level Level) bool {
return l.Handler().Enabled(level)
}
@@ -118,14 +133,14 @@
// the following argument is treated as the value and the two are combined
// into an Attr.
// - Otherwise, the argument is treated as a value with key "!BADKEY".
-func (l *Logger) Log(level Level, msg string, args ...any) {
+func (l Logger) Log(level Level, msg string, args ...any) {
l.LogDepth(0, level, msg, args...)
}
// LogDepth is like [Logger.Log], but accepts a call depth to adjust the
// file and line number in the log record. 0 refers to the caller
// of LogDepth; 1 refers to the caller's caller; and so on.
-func (l *Logger) LogDepth(calldepth int, level Level, msg string, args ...any) {
+func (l Logger) LogDepth(calldepth int, level Level, msg string, args ...any) {
if !l.Enabled(level) {
return
}
@@ -134,19 +149,18 @@
_ = l.Handler().Handle(r)
}
-func (l *Logger) makeRecord(msg string, level Level, depth int) Record {
- depth += 5
- return NewRecord(time.Now(), level, msg, depth)
+func (l Logger) makeRecord(msg string, level Level, depth int) Record {
+ return NewRecord(time.Now(), level, msg, depth+5, l.ctx)
}
// LogAttrs is a more efficient version of [Logger.Log] that accepts only Attrs.
-func (l *Logger) LogAttrs(level Level, msg string, attrs ...Attr) {
+func (l Logger) LogAttrs(level Level, msg string, attrs ...Attr) {
l.LogAttrsDepth(0, level, msg, attrs...)
}
// LogAttrsDepth is like [Logger.LogAttrs], but accepts a call depth argument
// which it interprets like [Logger.LogDepth].
-func (l *Logger) LogAttrsDepth(calldepth int, level Level, msg string, attrs ...Attr) {
+func (l Logger) LogAttrsDepth(calldepth int, level Level, msg string, attrs ...Attr) {
if !l.Enabled(level) {
return
}
@@ -156,24 +170,24 @@
}
// Debug logs at DebugLevel.
-func (l *Logger) Debug(msg string, args ...any) {
+func (l Logger) Debug(msg string, args ...any) {
l.LogDepth(0, DebugLevel, msg, args...)
}
// Info logs at InfoLevel.
-func (l *Logger) Info(msg string, args ...any) {
+func (l Logger) Info(msg string, args ...any) {
l.LogDepth(0, InfoLevel, msg, args...)
}
// Warn logs at WarnLevel.
-func (l *Logger) Warn(msg string, args ...any) {
+func (l Logger) Warn(msg string, args ...any) {
l.LogDepth(0, WarnLevel, msg, args...)
}
// Error logs at ErrorLevel.
// If err is non-nil, Error appends Any("err", err)
// to the list of attributes.
-func (l *Logger) Error(msg string, err error, args ...any) {
+func (l Logger) Error(msg string, err error, args ...any) {
if err != nil {
// TODO: avoid the copy.
args = append(args[:len(args):len(args)], Any("err", err))
diff --git a/slog/logger_test.go b/slog/logger_test.go
index ddcf4fa..f502537 100644
--- a/slog/logger_test.go
+++ b/slog/logger_test.go
@@ -158,7 +158,7 @@
func TestAlloc(t *testing.T) {
dl := New(discardHandler{})
- defer func(d *Logger) { SetDefault(d) }(Default())
+ defer func(d Logger) { SetDefault(d) }(Default())
SetDefault(dl)
t.Run("Info", func(t *testing.T) {
@@ -265,7 +265,7 @@
{[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}},
{[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}},
} {
- r := NewRecord(time.Time{}, 0, "", 0)
+ r := NewRecord(time.Time{}, 0, "", 0, nil)
r.setAttrsFromArgs(test.args)
got := attrsSlice(r)
if !attrsEqual(got, test.want) {
diff --git a/slog/record.go b/slog/record.go
index 7e58b87..852ed2e 100644
--- a/slog/record.go
+++ b/slog/record.go
@@ -5,6 +5,7 @@
package slog
import (
+ "context"
"runtime"
"time"
@@ -27,6 +28,9 @@
// The level of the event.
level Level
+ // The Logger's context.
+ ctx context.Context
+
// The pc at the time the record was constructed, as determined
// by runtime.Callers using the calldepth argument to NewRecord.
pc uintptr
@@ -52,9 +56,12 @@
// return the file and line number at that depth,
// where 1 means the caller of NewRecord.
//
+// A Record stores a context solely to provide Handlers access to the context's
+// values. Cancellation of the context does not affect record processing.
+//
// NewRecord is intended for logging APIs that want to support a [Handler] as
// a backend.
-func NewRecord(t time.Time, level Level, msg string, calldepth int) Record {
+func NewRecord(t time.Time, level Level, msg string, calldepth int, ctx context.Context) Record {
var p uintptr
if calldepth > 0 {
p = pc(calldepth + 1)
@@ -63,6 +70,7 @@
time: t,
message: msg,
level: level,
+ ctx: ctx,
pc: p,
}
}
@@ -76,6 +84,11 @@
// Level returns the level of the log event.
func (r Record) Level() Level { return r.level }
+// Context returns the context in the Record.
+// If the Record was created from a Logger,
+// this will be the Logger's context.
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Jonathan Amsterdam.
1 comment:
File slog/logger.go:
Patch Set #3, Line 67: // Loggers are immutable; to create a new one, call [New] or Logger method
So you're saying that if we have a method with a pointer receiver, users should expect and guard against mutation.
However, doesn't that somewhat contradict the principle of providing a consistent view of a type (either value with value receivers, or pointer with pointer receivers)?
There's nothing theoretically wrong with providing a mix of (T) and (*T) methods for accessors and mutators, but it can be confusing to the reader, so it's common to use *T for all methods if any one of them needs it. But if we use (T) everywhere, we're basically promising that we'll never make Loggers mutable, since the copy implied by (T) methods would lead to aliasing problems.
Even if Loggers remain shallowly immutable, there may be advantages to always using a pointer to refer to them: for example, less argument copying in function calls, and no allocation required for interface conversions. We can still have methods of "functional update" form, `(*T).WithFoo() *T`, that return a new variable rather than mutating the original, while reserving the possibility of adding mutator methods (and Clone) later.
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.
1 comment:
File slog/logger.go:
Patch Set #3, Line 67: // Loggers are immutable; to create a new one, call [New] or Logger method
> So you're saying that if we have a method with a pointer receiver, users should expect and guard a […]
Now I remember: we made Logger a value type so that Logger.WithContext doesn't allocate. It needs to be fast.
To view, visit change 439059. To unsubscribe, or for help writing mail filters, visit settings.