improvement: Check log level enabled before evaluating parameters #157

bmoylan · 2021-09-02T17:35:36Z

This should remove the overhead associated with logging at a disabled level

This change is

nmiyake · 2021-09-02T17:43:11Z

changelog/@unreleased/pr-157.v2.yml

@@ -0,0 +1,5 @@
+type: improvement
+improvement:
+  description: Check log level enabled before evaluating parameters


Can you expand the description a bit? For the change as implemented, would be something like:

Adds "Enabled" function to the LeveledLogger interface and updates logger implementations so that, if a logger is not enabled at a given level, the logger parameters are not evaluated.

wlog/logentry.go

wlog/svclog/svc1log/logger.go

nmiyake

Minor feedback on comment.

Wanted to raise another consideration to discuss here -- although it looks like it wasn't 100% consistent, previously some degree of effort was made to centralize the logger level in the actual logger implementation. The intent here was two-fold: one was to not duplicate state (have two different places where "level" was stored) and the other was to delegate the difficulties of atomic updates down to the implementing libraries.

Updating and checking log levels atomically can be pretty complicated/hard to do in a performance-efficient manner (and even more so for things like logging libraries where calls are incredibly frequent and overhead to check for locks etc. can be substantial). I believe that many logging libraries go to great lengths to optimize this.

It doesn't look like we do any special locking here, so at the extreme it's possible for the wlog logger level to differ from the internal one, and when changing the value it's possible for things to proceed non-atomically (a logger statement may emit after a level has been changed).

This may not matter even in the edge cases, but do want to ensure that we consider it.

nmiyake · 2021-09-02T19:20:26Z

wlog/wrappedlog/wrapped1log/logger.go

@@ -42,12 +42,15 @@ func New(w io.Writer, level wlog.LogLevel, name, version string) Logger {
 }

 func NewFromProvider(w io.Writer, level wlog.LogLevel, creator wlog.LoggerProvider, name, version string) Logger {
+	levelLogger := creator.NewLeveledLogger(w, level)
+	levelProvider, _ := levelLogger.(wlog.LevelProvider)


Can you add a comment that explains that it's safe to ignore the second value because if the assertion fails then levelProvider is nil and this case is properly handled/supported?

wlog/levels.go

bmoylan · 2021-09-02T21:26:23Z

Thanks @nmiyake, I hadn't really thought about the atomicity problem. I've pushed a new approach (third time's the charm?) which adds a AtomicLogLevel for use in the logger implementations and shares similar logic in one place for all of them.

nmiyake

Thanks! Some minor nits/feedback on mostly stylistic things.

At a high level, this implementation adds a new atomic.Value.Load() call for every logging call. From what I've read, it seems like this function is relatively fast (and better than using a RW mutex), but this is a new overhead. However, for applications that previously made logger calls at levels that weren't enabled, there will be new performance/allocation savings by not converting parameters.

I think this is likely acceptable on the whole, but that is a gut instinct (not backed by data), and just flagging because this is super inner-loop code.

If we find that the extra checks are causing overhead, I think we could work around it by adding a level of indirection to the loggers and having a different logger implementation for each level -- an inner[impl]Logger[level] that only emits for that level. For example, innerZapLoggerDebug would provide an implementation that emits at all levels, while innerZapLoggerError would only emit at error (its Info and Debug functions would just be empty). A SetLevel call would create and set a new inner logger implementation and a Get would return the stored level (and these shouldn't be an issue because the get/set frequency is much less than logging).

Hopefully this shouldn't be necessary, but noting for posterity in case we do find perf issues with this implementation. Also, knowing that we have the option of an alternative implementation like this that still fulfills the interface/behavioral contract makes this particular PR lower-risk, which feels good.

wlog-zerolog/internal/logger.go

wlog/levels.go

nmiyake · 2021-09-07T17:07:58Z

wlog/wrappedlog/wrapped1log/logger.go

@@ -42,12 +42,16 @@ func New(w io.Writer, level wlog.LogLevel, name, version string) Logger {
 }

 func NewFromProvider(w io.Writer, level wlog.LogLevel, creator wlog.LoggerProvider, name, version string) Logger {
+	delegate := creator.NewLeveledLogger(w, level)
+	// We ignore the second return value because 'level: nil' is a valid state handled in the implementation.


nit: for consistency, please avoid "I/we" in comments -- update to something like "The second return value is ignored because..."

nmiyake · 2021-09-07T17:08:18Z

wlog/svclog/svc1log/logger.go

@@ -33,11 +33,12 @@ func New(w io.Writer, level wlog.LogLevel, params ...Param) Logger {
 }

 func NewFromCreator(w io.Writer, level wlog.LogLevel, creator wlog.LeveledLoggerCreator, params ...Param) Logger {
+	delegate := creator(w, level)
+	// We ignore the second return value because 'level: nil' is a valid state handled in the implementation.


nit: for consistency, please avoid "I/we" in comments -- update to something like "The second return value is ignored because..."

nmiyake · 2021-09-07T17:09:26Z

wlog-zap/internal/provider.go

-	return zap.New(zapcore.NewCore(enc, zapcore.AddSync(w), level)), &level
-}
+func newZapLogger(w io.Writer, encoderConfig zapcore.EncoderConfig) *zap.Logger {
+	// We do our own enforcement in the level-specific methods; no need for zap to check again.


nit: for consistency, please avoid "I/we" in comments -- update to something like "wlog performs its own enforcement of leveled logging in level-specific methods..."

nmiyake · 2021-09-07T17:22:36Z

wlog/levels.go

+}
+
+type AtomicLogLevel struct {
+	value atomic.Value


Flagging one nuance/thing to keep in mind here which is, per the documentation at https://pkg.go.dev/sync/atomic#Value:

A Value provides an atomic load and store of a consistently typed value. The zero value for a Value returns nil from Load. Once Store has been called, a Value must not be copied.

A Value must not be copied after first use.

Since atomic.Value is stored here directly and AtomicLogLevel is embedded directly in most of the logger structs, this means that, with this change, it's not safe to copy logger structs via assignment once their level has been set. However, making this a pointer doesn't really help, since in that case different logger structs will always share the same log level.

I believe this should be safe since it looks like all of the logger structs are generally private and we only return a pointer to them as a wlog.Logger interface, which I believe means that there's no way for callers to create copies of these loggers. However, I think it would be a good idea to verify that we're not copying loggers anywhere in the internal code of WGL and to add a comment to this struct that states that it shouldn't be copied because of this caveat of atomic.Value.

Yeah this was safe because we always use a reference to the outer (logger) struct so the AtomicLogLevel is never copied.

That said, I think this is a good enough flag and easy to mess up down the road that I've converted things to use *AtomicLogLevel to avoid foot-shooting in some later refactor.

It is true that loggers (that want independent log levels) should never be shallow-copied. Given that is not possible by a caller (because the structs are private), do you think a comment on all of them would be helpful?

Yeah, I'm fine with either a comment on this struct or on each of the fields -- as long as it's mentioned in one place or the other I think that's sufficient.

A similar pattern used in the stdlib (and protobufs) is to embed a struct that implements both Lock and Unlock since go vet will flag any code that attempts to copy a lock. We could do something similar here so we have compile time checks for any copies.
Examples:
Go stdlib: https://cs.opensource.google/go/go/+/master:src/sync/cond.go;l=89-98
Protobuf: https://github.com/protocolbuffers/protobuf-go/blob/5aec41b4809b9822a34e17acd06ae9ae9f41c13d/internal/pragma/pragma.go#L24-L29

bmoylan · 2021-09-07T17:46:48Z

On the performance piece, I think it is a wash because we are no longer using the loggers' leveling mechanism which also required an atomic lookup

nmiyake · 2021-09-07T20:42:00Z

Thanks! Last bit of feedback on the updating the comment for the atomic.Value, but otherwise looks good to me.

@tabboud for review/input as well, but I'm good to grant approval after comment update.

bmoylan · 2021-09-08T16:45:49Z

comment added!

tabboud

Just 1 suggestion but otherwise looks good

tabboud · 2021-09-13T13:56:28Z

wlog/levels.go

+}
+
+type AtomicLogLevel struct {
+	value atomic.Value


A similar pattern used in the stdlib (and protobufs) is to embed a struct that implements both Lock and Unlock since go vet will flag any code that attempts to copy a lock. We could do something similar here so we have compile time checks for any copies.
Examples:
Go stdlib: https://cs.opensource.google/go/go/+/master:src/sync/cond.go;l=89-98
Protobuf: https://github.com/protocolbuffers/protobuf-go/blob/5aec41b4809b9822a34e17acd06ae9ae9f41c13d/internal/pragma/pragma.go#L24-L29

bmoylan · 2021-09-13T21:28:02Z

ooh cool, @tabboud! Just pushed a new commit which uses that

svc-autorelease · 2021-09-16T17:55:17Z

Released 1.17.0

bmoylan and others added 2 commits September 2, 2021 10:34

improvement: Check log level enabled before evaluating parameters

ae5027c

Add generated changelog entries

ec34a25

nmiyake requested changes Sep 2, 2021

View reviewed changes

bmoylan added 3 commits September 2, 2021 11:47

refactor: undo interface break in favor of new LevelProvider interface

adafe3a

cleanup jsonMapLogger

5f6b02b

cleanup noop and warn loggers

170cebf

bmoylan commented Sep 2, 2021

View reviewed changes

wlog/svclog/svc1log/logger.go Show resolved Hide resolved

bmoylan added autorelease merge when ready labels Sep 2, 2021

nmiyake requested changes Sep 2, 2021

View reviewed changes

introduce AtomicLogLevel

76062f3

bmoylan force-pushed the bm/check-level-enabled branch from 47d0148 to 76062f3 Compare September 2, 2021 21:27

bmoylan removed autorelease merge when ready labels Sep 7, 2021

nmiyake requested changes Sep 7, 2021

View reviewed changes

CR

e8b063a

comment

4ce4f59

tabboud approved these changes Sep 13, 2021

View reviewed changes

bmoylan added 2 commits September 13, 2021 12:50

Merge branch 'develop' into bm/check-level-enabled

f7aa809

Use sync.Locker to protect from copying AtomicLogLevel

232aec4

allow second space in wlog-tmpl tests

8467d60

bmoylan added autorelease merge when ready labels Sep 16, 2021

bulldozer-bot bot merged commit 3c9b4f3 into develop Sep 16, 2021

bulldozer-bot bot deleted the bm/check-level-enabled branch September 16, 2021 17:55

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

improvement: Check log level enabled before evaluating parameters #157

improvement: Check log level enabled before evaluating parameters #157

bmoylan commented Sep 2, 2021 •

edited

Loading

nmiyake Sep 2, 2021

nmiyake left a comment

nmiyake Sep 2, 2021

bmoylan commented Sep 2, 2021

nmiyake left a comment

nmiyake Sep 7, 2021

nmiyake Sep 7, 2021

nmiyake Sep 7, 2021

nmiyake Sep 7, 2021

bmoylan Sep 7, 2021

nmiyake Sep 7, 2021

tabboud Sep 13, 2021

bmoylan commented Sep 7, 2021

nmiyake commented Sep 7, 2021

bmoylan commented Sep 8, 2021

tabboud left a comment

tabboud Sep 13, 2021

bmoylan commented Sep 13, 2021

svc-autorelease commented Sep 16, 2021

improvement: Check log level enabled before evaluating parameters #157

improvement: Check log level enabled before evaluating parameters #157

Conversation

bmoylan commented Sep 2, 2021 • edited Loading

Choose a reason for hiding this comment

nmiyake left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bmoylan commented Sep 2, 2021

nmiyake left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bmoylan commented Sep 7, 2021

nmiyake commented Sep 7, 2021

bmoylan commented Sep 8, 2021

tabboud left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bmoylan commented Sep 13, 2021

svc-autorelease commented Sep 16, 2021

bmoylan commented Sep 2, 2021 •

edited

Loading