WIP: log values from context #158
Closed
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
|
Here's a comparison of all benchmarks between master (b3dc695) and this PR: |
This was referenced Nov 18, 2022
thockin
reviewed
Nov 18, 2022
logr.go
Outdated
| // given a context through WithContext later, the logger will extract the | ||
| // values for these keys and log them as additional key/value pairs. | ||
| func (l Logger) WithContextValues(keys ...ContextKey) Logger { | ||
| l.contextKeys = &keys |
There was a problem hiding this comment.
Shouldn't this be an append, rather than a replace (which requires a full copy of the array)?
There was a problem hiding this comment.
Semantic aside (set vs. append), even if we append we have to do a full copy. Otherwise we may end up with the situation where an append in one Logger overwrites a value stored by the append in another Logger. Here's an example where that happens: https://go.dev/play/p/Ze2zhR0U2VS
It all depends on the capacity of the slice. We don't have control over how much append increases that when it needs to reallocate, so this can happen.
Besides that, append to a shared slice is not thread-safe, is it?
There was a problem hiding this comment.
Oh, yes, my sentence was unclear. append absolutely requires us to copy the array. That's really what I mean but it was poorly phrased.
"""
Shouldn't this be an append (which requires a manual copy of the existing data), rather than a replace?
"""
There was a problem hiding this comment.
I agree, let's append the new keys. It is then consistent with WithValues which also adds instead of sets the new values.
thockin
reviewed
Nov 18, 2022
There was a problem hiding this comment.
I prefer the first model, myself. The main advantage of pushing this down to the Sink is that the ContextKeys don't get copied? If so, why not keep the Logger.WithContextValues() but pass the keys down to the Sink to store?
We may finally want to add some sort of Logger.CanX() for each of the optional interfaces...
I redid the performance comparison after using the funcr optimization for both and there's no clear winner. The semantic is slightly different, too, at least in the current implementation. By appending at the end of the |
|
So there's a few points to close on:
|
The approach where Logger is smaller is a bit faster in traditional benchmarks that rely on copying Logger and slower in the new benchmarks that use context values: Compared to the baseline (= current master), my preferred solution (= Logger.WithContextValues + LogSink.WithValues for the extra values) has this overhead: I think it's acceptable.
There's probably not a single "right" solution, but the one where both works is more flexible.
I prefer WithValues - see my arguments above and in the new commit message for the variant of the Logger implementation. |
pohly
force-pushed
the
with-context
branch
3 times, most recently
from
612ba9f
to
dc20a30
Compare
thockin
reviewed
Nov 20, 2022
|
I force-pushed with the changes discussed above and also added one new commit for Discard: it might be useful to keep it unchanged also when WithContext and WithContextValues are called for it. |
pohly
commented
Nov 21, 2022
thockin
reviewed
Nov 21, 2022
| // WithContext stores a context in the Logger. If the Logger also has keys set | ||
| // that it is meant to log from a context, then the values for those keys from | ||
| // the given context will be added to all log entries. | ||
| func (l Logger) WithContext(ctx context.Context) Logger { |
There was a problem hiding this comment.
Can you add some example to example_test.go, too ?
logr.go
Outdated
| // given a context through WithContext later, the Logger will extract the | ||
| // values for these keys and log them as additional key/value pairs | ||
| // as if they had been passed to WithValues. | ||
| func (l Logger) WithContextValues(keys ...ContextKey) Logger { |
There was a problem hiding this comment.
Can you add some example to example_test.go, too ?
discard_test.go
Outdated
| @@ -46,4 +47,12 @@ func TestComparable(t *testing.T) { | |||
| if a != b { | |||
| t.Fatal("any two discardLogSink must be equal") | |||
| } | |||
|
|
|||
| if b := Discard().WithContextValues(ContextKey{Key: 1, Name: "one"}); b != a { | |||
There was a problem hiding this comment.
This seems like it should read as a.WithContextValues(..., no? same below.
There was a problem hiding this comment.
Ultimately it's the same, but you are right, starting with a is a bit closer to the intent. Will change.
This was referenced Nov 23, 2022
|
I have added several commits at the end to support logging of context values with helper functions. I'll continue with performance investigations. As it stands now, this API is sufficient for the original goal (logging of OpenTelemetry span and trace ID, see kubernetes/kubernetes#114088). |
thockin
reviewed
Nov 23, 2022
There was a problem hiding this comment.
This PR now carries multiple ideas, which probably deserve their own PRs to consider. Juat looking at KeysAndValues now, we need to justify the use-case well, since it becomes another optional thing that many LogSinks will not support.
- I don't love the name. I thought PseudoStruct was a cute name, but maybe too cute.
- This starts to feel like a poor-man's version of slog Attr - should we borrow some aspects of that to make eventual transitions a bit easier?
- We should consider Logger.CanX() methods
I will look at the rest of the commits next
thockin
reviewed
Nov 23, 2022
logr.go
Outdated
| copy(cp, *l.contextKeys) | ||
| copy(cp[len(*l.contextKeys):], keys) | ||
| l.contextKeys = &cp | ||
| cp := make([]ContextHandler, len(*l.contextHandlers)+len(handlers)) |
There was a problem hiding this comment.
you may have been correct that append was easier to read :)
logr.go
Outdated
| // We don't really know how large this has to be. Let's | ||
| // assume that each handler returns at most two key/value | ||
| // pairs, of which each needs two entries. | ||
| keysAndValues := make([]interface{}, 0, 4*len(*l.contextHandlers)) |
There was a problem hiding this comment.
There's almost no cost to over-estimating (within reason) so I'd go for like 64 instead of 4
There was a problem hiding this comment.
I had my math wrong: I meant 2 * (len(*l.contextHandlers) + 1) = "one value might be an error, which then adds one more extra field with two values". But I agree, we can make that larger, just in case.
There was a problem hiding this comment.
Never mind, I had the context (sic!) wrong. Pure multiplications is right here.
logr.go
Outdated
| keysAndValues := make([]interface{}, 0, 4*len(*l.contextHandlers)) | ||
| for _, handler := range *l.contextHandlers { | ||
| for _, keyAndValue := range handler(l.ctx) { | ||
| keysAndValues = append(keysAndValues, keyAndValue.Key, keyAndValue.Value) |
There was a problem hiding this comment.
Because these are opaque functions, my other comments about optimization don't apply here. They could be "impure" functions, and we would have cached the wrong values. That's an unfortunate pessimization when they almost certainly ARE cacheable, but we can't prove it.
Can/should we make assertions about these functions to enable optimization?
There was a problem hiding this comment.
The assumption that they always return the same result for the same input values makes sense.
logr.go
Outdated
| Name string | ||
| } | ||
| // ContextHandler retrieves certain values from the context. | ||
| type ContextHandler func(ctx context.Context) KeysAndValues |
There was a problem hiding this comment.
I think you want to return []KeyAndValue - the KeysAndValues (pseudostruct) type implies that it will be rendered as a struct, but it is not. In fact, I don't see why this is not just []interface{} as the return type.
There was a problem hiding this comment.
[]KeyAndValue makes sense to me. I don't like []interface{} because then we are back at having to handle odd number of entries, cast the keys to string or even deal with non-string keys. We don't need such freedom here.
But on the other hand, if []interface{} then just gets passed through to WithValues, then it is the better type after all. I'll check...
There was a problem hiding this comment.
I switched to []interface{} and removed the KeysAndValues type from this PR. We can discuss it separately (no PR yet).
Yes, it has become my playground for everything that might change the logr API because it isn't clear yet how much of that is related. This will have to be sorted out.
Perhaps
I'll check.
As replacement for casting the sink? Does that mean that |
pohly
force-pushed
the
with-context
branch
2 times, most recently
from
8821923
to
d4ec6c8
Compare
|
I think I have found an approach that minimizes the size of Logger and allows caching of the context retrieval + WithValues - see the last two commits. Performance seems okay, but at the cost of increased complexity. I removed the KeysAndValues type from this PR, it's not needed here. I cleaned up the PR and probably would not squash it further because each commit explains why a change is done. |
thockin
reviewed
Nov 26, 2022
| func logSomeEntries(j, mod, v int) func(ctx context.Context) { | ||
| return func(ctx context.Context) { | ||
| if j%mod == 0 { | ||
| logger := logr.FromContextOrDiscard(ctx) |
There was a problem hiding this comment.
Why ...OrDiscard instead of something like
func loggerFromContextOrDie(ctx context.Context) logr.Logger {
logger, err := logr.FromContext(ctx)
if err != nil {
panic("failed to get Logger from Context")
}
return logger
}
There was a problem hiding this comment.
Because it was simple and actually getting a discard logger would have been detected by the output check. But loggerFromContextOrDie is better - changed.
| value1 := ctx.Value(contextKey1{}) | ||
| value2 := ctx.Value(contextKey2{}) | ||
| switch { | ||
| case value1 != nil && value2 != nil: |
There was a problem hiding this comment.
For the purposes of the benchmark, shouldn't we assert that both values are ALWAYS found, otherwise fail?
There was a problem hiding this comment.
Yes, that's better. I think I wanted to have some flexibility with regards to tests, but then never took advantage of that. Changed.
logr.go
Outdated
| } | ||
|
|
||
| // We don't really know how large this has to be. Let's | ||
| // assume that each handler returns at most two key/value |
There was a problem hiding this comment.
comment doesn't match code any more wrt size?
logr.go
Outdated
| sync.Pool | ||
| } | ||
|
|
||
| func (pool *contextKVPoolType) Get(ctx context.Context, handlers []ContextHandler) *contextKV { |
There was a problem hiding this comment.
Don't you need to trap Put() and clear the fields? You're not reusing the allocated values, just preventing them from being released.
Is this pool optimization really important? What did the numbers look like without it?
There was a problem hiding this comment.
Having an item in a sync.Pool does not prevent its being garbage collected. So if the contextKV instance in the pool gets garbage-collected, the context and sink also will be (potentially...). Because of that I hadn't bother with clearing the struct on Put. There may be value in dropping pointers to them on Put because that makes these instance available for garbage-collection sooner. I'll try whether it makes a noticeable difference.
I'll also try without it. The amount of allocations will go up, so I expect the difference to be notiecable.
There was a problem hiding this comment.
Clearing on Put made no difference. I'm using it anyway because it feels cleaner.
Using the pool is faster than not using it:
NewContext100PercentDisabled/simple-36 72.2µs ± 1% 66.8µs ± 3% -7.48% (p=0.008 n=5+5)
NewContext100PercentDisabled/simple-36 32.0kB ± 0% 27.2kB ± 0% -14.88% (p=0.008 n=5+5)
NewContext100PercentDisabled/simple-36 500 ± 0% 400 ± 0% -20.00% (p=0.008 n=5+5)
It's not a huge difference, but IMHO worthwhile.
There was a problem hiding this comment.
After taking a more thorough look at this change I noticed that contextKV instances were getting cleared on Put that were still in use by other Logger instances. This implies that Put got called too early, I just hadn't noticed.
With hindsight, that makes sense: when one Logger instance stops using a certain contextKV instance, it has no knowledge of other Logger instances.
To avoid the extra alloc during FromContext (the subjectively most frequent call that currently triggers a recreation of contextKV), at least the ctx field would have to be in Logger again. When adding caching, With* calls also need a new instance. So perhaps storing everything in Logger is the right approach after all - I'll have to do a final comparison at the end.
There was a problem hiding this comment.
yeah, I was trying to put my finger on what didn't feel right still, and this might be it. It feels like thebest we can do is 1 alloc per WithContext() (assuming we use a small fixed array for small sets of handlers)
logr.go
Outdated
| @@ -352,18 +359,33 @@ func (l Logger) Info(msg string, keysAndValues ...interface{}) { | |||
| // triggered this log line, if present. The err parameter is optional | |||
| // and nil may be passed instead of an error instance. | |||
| func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) { | |||
| if l.sink == nil { | |||
| if l.sink == nil || l.sink == discardLogSinkInstance { | |||
There was a problem hiding this comment.
should we make the same short0circuit in Info() ?
There was a problem hiding this comment.
DiscardLogSink.Enabled() always returns false, so it didn't seem necessary. I've added it anyway, for the sake of consistency. I also added a Logger.skipSink helper function for clarity - at least I hope the name makes it clearer...
There was a problem hiding this comment.
l.Info() calls l.Enabled() calls l.Sink.Enabled(). This crosses the interface boundary, so possible optimizations are defeated. I think checking it explicitly makes sense.
You say "I've added it anyway" but I don't see it here?
There was a problem hiding this comment.
I haven't pushed my latest state yet. I was still working on performance comparisons yesterday.
| // We have done the steps below already, no need to repeat | ||
| // them. | ||
| return value.(LogSink) // nolint: forcetypeassert | ||
| } | ||
| sink := l.sink | ||
| contextKeysAndValues := l.valuesFromContext() | ||
| if len(contextKeysAndValues) > 0 { | ||
| sink = sink.WithValues(contextKeysAndValues...) |
There was a problem hiding this comment.
so this is assuming that the sink does the caching internally, right? But that doesn't work, unless I am missing something, because the sink merges these with the regular WithValues(). As we clone sinks, the set of context-keys can change, and we don't know which ones to replace vs retain.
I think we need either:
a) Sink gets a new optional interface which is specifically "values from context" so any subsequent call replaces the set
or
b) cache values here in Logger and pass then through WithValues(), which will perform worse obviously.
Or am I misunderstanding?
There was a problem hiding this comment.
Let's see...
Without caching:
- logger := FromContext(): context and keys remembered in Logger, for example with key "foo" and value "bar" in context
- logger = logger.WithValues("foo", 1)
- logger.Info("hello"): "foo=bar" retrieved now, overwrites "foo=1"
With caching:
- actually the same
Let's look at an example where logging triggers the caching. Without caching:
- logger := FromContext(): context and keys remembered in Logger, for example with key "foo" and value "bar" in context
- logger.Info("hello"): logs "foo=bar"
- logger = logger.WithValues("foo", 1)
- logger.Info("hello"): "foo=bar" retrieved now, overwrites "foo=1"
With caching:
- logger := FromContext(): context and keys remembered in Logger, for example with key "foo" and value "bar" in context
- logger.Info("hello"): logs "foo=bar" and stores that via WithValues
- logger = logger.WithValues("foo", 1):
setSinkcreates a newcontextKVwithout a sink in it - logger.Info("hello"): re-applies the context key/value pairs and logs "foo=bar"
This needs unit tests, but I think the implementation already handles it so that context key/value pairs are always logged as if they were passed to WithValues, as documented.
There was a problem hiding this comment.
There are clearly several "interesting" interactions between modifying a logger through WithName and WithValues. In particular WithValues deserves more coverage, with scenarios for calling it before FromContext and after.
I've extended the benchmarks (and thus unit test) with that.
There was a problem hiding this comment.
There is one relevant difference: when using the new API to retrieve context values, that retrieval happens right before the log call, after any WithValues calls by the app.
logger := logger.WithContextHandler(... <returns X=something>... )
...
logger := logr.FromContext()
logger.WithValues("X", 1)
# implicit: logger.WithValues("X", something)
logger.Info("hello"
This means that context values always overwrite WithValues values. It's not how the approach without this new API works, but I'm undecided whether that is enough reason to do something about this. Ultimately, key conflicts should better get avoided.
For now I just changed the definition of WithContextHandler to:
// WithContextHandlers extends the list of context handlers. When
// given a context through WithContext later, the Logger will invoke
// each handler and log the key/value pairs that they return as
// as if they had been passed to WithValues right before a log call.
You mentioned adding a LogSink API to store context key/value pairs. With such an API, the LogSink then could handle those pairs first (WithValue calls override them) or handle them last (WithValue calls get overridden, the current behavior).
There was a problem hiding this comment.
I checked out your PR to show you what I meant and I realized you've done something VERY clever.
You store the duplicate "derived" sink, but recreate it from the original sink - this is really subtle. Additionally, the allocation of a new contextKV clearing the sink is also pretty hidden. Both could use some comments :)
You raise 2 good questions, though.
- Which is "more important" - key-vals from context or key-vals at the callsite?
- When rendering, do "most important" values come first or last? Go's JSON parsing says "last value wins": https://go.dev/play/p/ZE1xXilHHHg
There was a problem hiding this comment.
Which is "more important" - key-vals from context or key-vals at the callsite?
I think we can define it however we like, because ultimately there shouldn't be any key conflicts, so it won't matter.
When rendering, do "most important" values come first or last?
I would say last. Currently, the order is WithValues followed by parameters. I prefer to add the context values in the middle.
There was a problem hiding this comment.
Context values are added by the "admin" (main) and callsite values are added by the "user". I sort of feel like context values coming last is correct (if a bit ugly). I could be fine with either answer as long as it doesn't need EVEN MORE surface area to effect.
There was a problem hiding this comment.
I'm not sure about the "admin" vs. "user" distinction: the admin might end up configuring the logger to log certain context values (but even that isn't necessary anymore), but then the actual context values come from the code and thus the "user". It may be reasonable to allow the user some final control by letting the call site override the context.
But primarily this is driven by how this can be implemented: by injecting in the middle, we can do the caching via WithValues. That wouldn't work if we wanted the context to come first (before other WithValues) or last (after call site parameters).
There was a problem hiding this comment.
How do you want to proceed? If you think it's important to let callsites override context, we need to have a different API than sink.WithValues(). I think I am OK with it as-is because, as you said, there shouldn't be any key conflicts. In fact, I wonder if it's worth the effort to do something like run a callback function if a duplicate key is detected or something.
There was a problem hiding this comment.
I prefer to keep it as-is, with no special support for detecting or reporting duplicate keys.
|
WRT squash, I'd probably just elide the imtermediate state, something like:
Even 3 and 4 could probably squash, but not a huge deal |
pohly
commented
Nov 27, 2022
This is because of the additional I found that the comparison becomes faster when using Baseline vs. Baseline vs. |
thockin
reviewed
Nov 28, 2022
logr.go
Outdated
| } | ||
| } | ||
|
|
||
| // setContext stores the handlers and updates any related fields. It mutates the |
There was a problem hiding this comment.
s/setContext/setContextHandlers/
logr.go
Outdated
|
|
||
| // contextKV is shared by different Logger instances. It combines everything | ||
| // that is needed to retrieve key/value pairs from a context. | ||
| type contextKV struct { |
There was a problem hiding this comment.
naming: how about contextHandle or contextMeta or something - KV makes it sound like a single value.
There was a problem hiding this comment.
I switched to contextMeta for the the type and to context for the Logger field.
logr.go
Outdated
| sync.Pool | ||
| } | ||
|
|
||
| func (pool *contextKVPoolType) Get(ctx context.Context, handlers []ContextHandler) *contextKV { |
There was a problem hiding this comment.
yeah, I was trying to put my finger on what didn't feel right still, and this might be it. It feels like thebest we can do is 1 alloc per WithContext() (assuming we use a small fixed array for small sets of handlers)
logr.go
Outdated
| @@ -352,18 +359,33 @@ func (l Logger) Info(msg string, keysAndValues ...interface{}) { | |||
| // triggered this log line, if present. The err parameter is optional | |||
| // and nil may be passed instead of an error instance. | |||
| func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) { | |||
| if l.sink == nil { | |||
| if l.sink == nil || l.sink == discardLogSinkInstance { | |||
There was a problem hiding this comment.
l.Info() calls l.Enabled() calls l.Sink.Enabled(). This crosses the interface boundary, so possible optimizations are defeated. I think checking it explicitly makes sense.
You say "I've added it anyway" but I don't see it here?
| // them. | ||
| return value.(LogSink) // nolint: forcetypeassert | ||
| } | ||
| sink := l.sink |
There was a problem hiding this comment.
comment like:
// This builds a result from the original sink, which may have user-defined pairs from WithValues(),
// and then adds pairs from context. Every time we change the user-defined pairs, the context, or
// the extraction function(s), the cached result is discarded, and this path will be called again.
logr.go
Outdated
|
|
||
| // ContextHandler provides callbacks for working with a context. | ||
| // More functionality might get added in the future. | ||
| type ContextHandler struct { |
There was a problem hiding this comment.
I don't love this name either. ContextExtractor ? ContextReader? ContextGetter ?
There was a problem hiding this comment.
Let's use ContextReader
logr.go
Outdated
| // | ||
| // ValuesFromContext must always return the same key/value pairs for | ||
| // the same context. The result might get cached. | ||
| ValuesFromContext func(ctx context.Context) []interface{} |
There was a problem hiding this comment.
Naming: "context" is redunant. I am not 100% convinced this struct is necessary. Wouldn't it all be easier to just say
log = log.WithContextValues(extractFromContext1, extractFromContext2)
There was a problem hiding this comment.
I wanted to avoid adding new APIs when at some point we find that we want to use something else then func(ctx context.Context) []interface{}. But I suppose I'm just overly cautious here: if that need ever arises, we can still introduce such a struct internally and have two APIs for adding to it (WithContextValues and WithContextValuesViaXYZ or whatever the difference will be).
I'm switching to WithContextValues taking ContextReader = func(ctx context.Context) []interface{} as arguments.
logr.go
Outdated
| // given a context through WithContext later, the Logger will invoke | ||
| // each handler and log the key/value pairs that they return as | ||
| // as if they had been passed to WithValues. | ||
| func (l Logger) WithContextHandlers(handlers ...ContextHandler) Logger { |
There was a problem hiding this comment.
Can you add some example to example_test.go, too ?
|
I have updated the PR with changes as discussed so far, except for adding examples. The last four commits implement different possible solutions:
The baseline is the solution with no changes to logr. Obviously, caching favors benchmarks where the same or related Logger instances are used multiple times. The last two differ a bit here because with the separate struct, more Loggers share the same cached sink (parent and siblings). This difference is currently not covered by a benchmark. Some benchmarks are very fast, so any slowdown shows up with a huge percentage. I am not sure how relevant that is in practice because they are still fast. It's also often the Discard* tests - those are irrelevant for Kubernetes production components because we always return a logger, but may of course matter in other projects. Let's look at a comparison between the baseline and different options:
Here It's faster in some benchmarks and slower in others.
Here we still pay the price for the extra allocation, but the cache seems to help.
This reduces allocations, but makes copying slower and reduces sharing of the cached sink. I'm leaning towards picking a solution which uses the cached sink. Let's compare the two versions (with cache, struct vs. inline): Not doing the additional allocation in I may be good to first get one component instrumented (like the apiserver) and do some real-world benchmarks with that component before deciding. |
thockin
reviewed
Dec 2, 2022
benchmark/benchmark_test.go
Outdated
| errResult = err | ||
|
|
||
| b.Run("with-logger", func(b *testing.B) { | ||
| ctx := logr.NewContext(ctx, logr.Discard()) |
There was a problem hiding this comment.
pedantic: shouldn't this be outside the b.Run() ?
logr.go
Outdated
| @@ -227,6 +227,13 @@ func (l *Logger) setSink(sink LogSink) { | |||
| l.sink = sink | |||
| } | |||
|
|
|||
| // skipSink returns true if the Logger has no sink or that sink is the discard | |||
| // LogSink. In those cases, operations involving the sink must respectively can | |||
There was a problem hiding this comment.
"must respectively can be" -> "can be"
thockin
reviewed
Dec 2, 2022
logr.go
Outdated
| type ContextReader func(ctx context.Context) []interface{} | ||
|
|
||
| // WithContextValues extends the list of ContextReaders. When | ||
| // given a context through WithContext later, the Logger will invoke |
pohly
added a commit
to pohly/logr
that referenced
this pull request
Dec 3, 2022
The original intention was to no treat the discard log sink in a special way. But it needs special treatment and lacking that in V() led to a bug: Discard() became different from Discard().V(1). Adding special detection of the discard logger also helps with the future logging of context values, because that extra work can be skipped for the discard logger. The distinction between null logger (from go-logr#153) and logr.Discard() was very minor. Instead of fixing the issue above with checks for both cases, Discard() now simply returns the null logger. Performance is a bit better: name old time/op new time/op delta DiscardLogInfoOneArg-36 92.7ns ± 5% 88.2ns ± 3% ~ (p=0.056 n=5+5) DiscardLogInfoSeveralArgs-36 239ns ± 0% 231ns ± 1% -3.40% (p=0.008 n=5+5) DiscardLogInfoWithValues-36 240ns ± 1% 236ns ± 3% ~ (p=0.889 n=5+5) DiscardLogV0Info-36 234ns ± 1% 228ns ± 0% -2.62% (p=0.008 n=5+5) DiscardLogV9Info-36 241ns ± 2% 228ns ± 0% -5.23% (p=0.008 n=5+5) DiscardLogError-36 264ns ± 1% 230ns ± 0% -12.78% (p=0.008 n=5+5) DiscardWithValues-36 116ns ± 1% 110ns ± 1% -5.35% (p=0.008 n=5+5) DiscardWithName-36 2.25ns ± 0% 0.72ns ± 0% -68.12% (p=0.008 n=5+5) FuncrLogInfoOneArg-36 2.13µs ± 2% 2.16µs ± 1% ~ (p=0.222 n=5+5) FuncrJSONLogInfoOneArg-36 2.41µs ± 1% 2.42µs ± 1% ~ (p=0.246 n=5+5) FuncrLogInfoSeveralArgs-36 4.53µs ± 4% 4.40µs ± 4% ~ (p=0.151 n=5+5) FuncrJSONLogInfoSeveralArgs-36 4.71µs ± 8% 4.67µs ± 2% ~ (p=0.310 n=5+5) FuncrLogInfoWithValues-36 4.60µs ± 2% 4.61µs ± 4% ~ (p=0.595 n=5+5) FuncrJSONLogInfoWithValues-36 4.81µs ± 3% 4.84µs ± 3% ~ (p=1.000 n=5+5) FuncrLogV0Info-36 4.45µs ± 3% 4.55µs ± 3% ~ (p=0.222 n=5+5) FuncrJSONLogV0Info-36 4.83µs ± 2% 4.78µs ± 3% ~ (p=0.548 n=5+5) FuncrLogV9Info-36 259ns ± 1% 252ns ± 0% -2.48% (p=0.008 n=5+5) FuncrJSONLogV9Info-36 258ns ± 1% 252ns ± 1% -2.52% (p=0.008 n=5+5) FuncrLogError-36 4.97µs ± 1% 4.78µs ± 3% -3.77% (p=0.032 n=5+5) FuncrJSONLogError-36 5.20µs ± 3% 5.13µs ± 2% ~ (p=0.548 n=5+5) FuncrWithValues-36 1.39µs ± 3% 1.38µs ± 3% ~ (p=0.690 n=5+5) FuncrWithName-36 217ns ± 1% 215ns ± 1% -0.62% (p=0.040 n=5+5) FuncrWithCallDepth-36 206ns ± 1% 210ns ± 1% +1.92% (p=0.008 n=5+5) FuncrJSONLogInfoStringerValue-36 2.59µs ± 2% 2.59µs ± 2% ~ (p=1.000 n=5+5) FuncrJSONLogInfoErrorValue-36 2.61µs ± 2% 2.63µs ± 2% ~ (p=0.310 n=5+5) FuncrJSONLogInfoMarshalerValue-36 2.63µs ± 2% 2.63µs ± 1% ~ (p=0.841 n=5+5) There's no difference in allocations. Co-authored-by: Tim Hockin <thockin@google.com> See go-logr#158 (comment)
thockin
pushed a commit
that referenced
this pull request
Dec 3, 2022
The original intention was to no treat the discard log sink in a special way. But it needs special treatment and lacking that in V() led to a bug: Discard() became different from Discard().V(1). Adding special detection of the discard logger also helps with the future logging of context values, because that extra work can be skipped for the discard logger. The distinction between null logger (from #153) and logr.Discard() was very minor. Instead of fixing the issue above with checks for both cases, Discard() now simply returns the null logger. Performance is a bit better: name old time/op new time/op delta DiscardLogInfoOneArg-36 92.7ns ± 5% 88.2ns ± 3% ~ (p=0.056 n=5+5) DiscardLogInfoSeveralArgs-36 239ns ± 0% 231ns ± 1% -3.40% (p=0.008 n=5+5) DiscardLogInfoWithValues-36 240ns ± 1% 236ns ± 3% ~ (p=0.889 n=5+5) DiscardLogV0Info-36 234ns ± 1% 228ns ± 0% -2.62% (p=0.008 n=5+5) DiscardLogV9Info-36 241ns ± 2% 228ns ± 0% -5.23% (p=0.008 n=5+5) DiscardLogError-36 264ns ± 1% 230ns ± 0% -12.78% (p=0.008 n=5+5) DiscardWithValues-36 116ns ± 1% 110ns ± 1% -5.35% (p=0.008 n=5+5) DiscardWithName-36 2.25ns ± 0% 0.72ns ± 0% -68.12% (p=0.008 n=5+5) FuncrLogInfoOneArg-36 2.13µs ± 2% 2.16µs ± 1% ~ (p=0.222 n=5+5) FuncrJSONLogInfoOneArg-36 2.41µs ± 1% 2.42µs ± 1% ~ (p=0.246 n=5+5) FuncrLogInfoSeveralArgs-36 4.53µs ± 4% 4.40µs ± 4% ~ (p=0.151 n=5+5) FuncrJSONLogInfoSeveralArgs-36 4.71µs ± 8% 4.67µs ± 2% ~ (p=0.310 n=5+5) FuncrLogInfoWithValues-36 4.60µs ± 2% 4.61µs ± 4% ~ (p=0.595 n=5+5) FuncrJSONLogInfoWithValues-36 4.81µs ± 3% 4.84µs ± 3% ~ (p=1.000 n=5+5) FuncrLogV0Info-36 4.45µs ± 3% 4.55µs ± 3% ~ (p=0.222 n=5+5) FuncrJSONLogV0Info-36 4.83µs ± 2% 4.78µs ± 3% ~ (p=0.548 n=5+5) FuncrLogV9Info-36 259ns ± 1% 252ns ± 0% -2.48% (p=0.008 n=5+5) FuncrJSONLogV9Info-36 258ns ± 1% 252ns ± 1% -2.52% (p=0.008 n=5+5) FuncrLogError-36 4.97µs ± 1% 4.78µs ± 3% -3.77% (p=0.032 n=5+5) FuncrJSONLogError-36 5.20µs ± 3% 5.13µs ± 2% ~ (p=0.548 n=5+5) FuncrWithValues-36 1.39µs ± 3% 1.38µs ± 3% ~ (p=0.690 n=5+5) FuncrWithName-36 217ns ± 1% 215ns ± 1% -0.62% (p=0.040 n=5+5) FuncrWithCallDepth-36 206ns ± 1% 210ns ± 1% +1.92% (p=0.008 n=5+5) FuncrJSONLogInfoStringerValue-36 2.59µs ± 2% 2.59µs ± 2% ~ (p=1.000 n=5+5) FuncrJSONLogInfoErrorValue-36 2.61µs ± 2% 2.63µs ± 2% ~ (p=0.310 n=5+5) FuncrJSONLogInfoMarshalerValue-36 2.63µs ± 2% 2.63µs ± 1% ~ (p=0.841 n=5+5) There's no difference in allocations. Co-authored-by: Tim Hockin <thockin@google.com> See #158 (comment)
Actual scenarios may be more complicated with more nested contexts, but this at least covers two cases (no logger in context.Background() and one log.NewContext).
These benchmark tests logging of two values (like trace and span ID) for different scenarios: - 1% of the call chains invoke Info, the rest don't log anything - 100% of the call chains log one entry, but it gets discarded due to verbosity - 100% of the call chains log one entry which really gets emitted Each of these is tested with and without additional calls to WithName and WithValues. Without special support for contextual logging, the code which adds values to the context must also modify the logger. The unit test reuses the setup code and checks in the benchmark functions.
Having to add a modified logger to a context when adding some values
to the context which are meant to be logged (like trace ID) has two
drawbacks:
- the instrumentation code which adds the values to the context must
be aware of logging
- modifying the logger incurs a cost, whether some actual log entry
then gets emitted or not.
A better approach is to add the values only to the context, then during logging
extract them. This is the same approach that contextual logging in Go is going
to use. The original plan was to tell a logger which keys to use to extract
values from a context. That plan was foiled by OpenTelemetry not exporting
those keys... Instead, a function provided by OpenTelemetry must be used to
get a SpanContext, then the span ID and trace ID can be extracted from that for
logging.
Such support is possible in Logger by manipulating the key/value slice before
passing it to the LogSink. But that then needs to deal with duplicates because
the LogSink might not expect those as part of the parameters. Using WithValues
is simpler, albeit also a bit slower.
Storing new fields in Logger is simple, but slows down scenarios where those
fields are not used. A better approach will follow in the next commits.
Discard() is documented as always comparing equal. Adding a context
or context keys breaks that. It seems useful to treat such a Logger
in a special way and not modify it to preserve the promise. The same
is done for the null Logger.
This has two advantages: - Logger becomes a bit smaller, which shows up in the other benchmarks - the struct can be used to cache the effect of context values on a LogSink without making Logger even larger (next step) Some benchmarks get fast, others get slower. It remains to be seen whether this is worth overall.
The underlying idea is that each contextKV instance optionally also contains a LogSink where the values were stored. The Logger struct can get copied, as before. Updates to it in the different With* functions become more complicated: if there is a contextMeta instance, then a new one must get created. The old one may still be in use by the parent Logger and therefore must not get modified.
Separate allocation increases the work that the garbage collector has to do.
|
I'm trying to figure the best way to visualize these for a few of the most critical test cases. Ran out of time this afternoon |
|
Should we regroup on this topic, or should we start to make noises about using slog instead? |
|
When is slog going to be stable enough to use it as logging API in Kubernetes? I agree that the end goal should be to use slog in Kubernetes libs, with traditional output formats (text, JSON) provided as slog backends. But for that we probably need an update of the contextual logging KEP. I've not investigated what changes would be necessary. |
|
I don't know the answer and I have not investigated either. I'm just
feeling less inclined to do major logr work now that slog is on the
horizon, unless it makes it easier to adopt slog.
…On Tue, Dec 27, 2022 at 10:55 AM Patrick Ohly ***@***.***> wrote:
When is slog going to be stable enough to use it as logging API in
Kubernetes?
I agree that the end goal should be to use slog in Kubernetes libs, with
traditional output formats (text, JSON) provided as slog backends. But for
that we probably need an update of the contextual logging KEP. I've not
investigated what changes would be necessary.
—
Reply to this email directly, view it on GitHub
<#158 (comment)>, or
unsubscribe
<https://github.com/notifications/unsubscribe-auth/ABKWAVHK3WAG6QGSYVD5YSTWPM3Q7ANCNFSM6AAAAAASEOZEG4>
.
You are receiving this because you were assigned.Message ID:
***@***.***>
|
|
That makes sense. We need to understand a possible timeline before we can decide whether adding new features is still needed. |
|
Let's not pursue this further. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Having to add a modified logger to a context when adding some values
to the context which are meant to be logged (like trace ID) has two
drawbacks:
be aware of logging
then gets emitted or not.
A better approach is to add the values only to the context, then during logging
extract them. This is the same approach that contextual logging in Go is going
to use.
I have experimented with a few different approaches for this, including doing it entirely in klog by wrapping the LogSink in a logger with one that injects the extra values. That is complicated and not worth discussing further.
In logr itself there are different approaches - see individual commits in https://github.com/pohly/logr/commits/with-context-all
The one proposed here implements logging of the additional values in Logger (no need to modify LogSinks) and passes them to the LogSink via WithValues.