pkg/log: improve performance of log.Debug()

[rohrerj]

I saw that even if the log level is info a call to log.Debug(...) requires on my system 135ns because convertCtx() is executed before checking the log level. Therefore I added a check to the log.Debug(...) function. With the help of the following benchmark tests I was able to reduce the execution time from 135ns to 30ns.

func BenchmarkLog(b *testing.B) {
err := log.Setup(log.Config{Console: log.ConsoleConfig{Level: "info"}})
assert.NoError(b, err)
for i := 0; i < b.N; i++ {
log.Debug("hello world", "i", i)
}
}

---

This change is 

[matzf]

Thank you for this contribution, @rohrerj!

Reviewed 1 of 1 files at r1, all commit messages.
Reviewable status: all files reviewed, 3 unresolved discussions (waiting on @rohrerj)

---

pkg/log/wrappers.go line 27 at r1 (raw file):

	if zap.L().Core().Enabled(zapcore.DebugLevel) {
		zap.L().Debug(msg, convertCtx(ctx)...)
	}

Once you've added the same check in (*logger).Debug etc. (see comment below), we could replace this implementation by Root().Debug(msg, ctx...) to avoid the code duplication.

This might lead to excessive allocation of the wrapper objects, showing up in your benchmark. It would make sense to also change logger to be passed around by value instead of by pointer (in particular, change all of logger's methods to take a value-receiver instead of a pointer-receiver) to (hopefully) avoid these allocations. Feel free to do this or just leave it like it is now, either way seems fine for me.

---

pkg/log/wrappers.go line 32 at r1 (raw file):

// Info logs at info level.
func Info(msg string, ctx ...interface{}) {
	zap.L().Info(msg, convertCtx(ctx)...)

Same log-level check as in Debug should be applied here and in Error as well.

---

pkg/log/wrappers.go line 77 at r1 (raw file):

func (l *logger) Debug(msg string, ctx ...interface{}) {
	l.logger.Debug(msg, convertCtx(ctx)...)

Let's add the level check here as well, and also in the Info and Error methods of this logger type. We can use the existing Enabled wrapper function instead of using the l.logger.Core().Enabled(...).

if l.Enabled(DebugLevel) {
   ...
}

[rohrerj]

Reviewable status: 0 of 1 files reviewed, 3 unresolved discussions (waiting on @matzf)

---

pkg/log/wrappers.go line 27 at r1 (raw file):

Previously, matzf (Matthias Frei) wrote…

Once you've added the same check in (*logger).Debug etc. (see comment below), we could replace this implementation by Root().Debug(msg, ctx...) to avoid the code duplication.

This might lead to excessive allocation of the wrapper objects, showing up in your benchmark. It would make sense to also change logger to be passed around by value instead of by pointer (in particular, change all of logger's methods to take a value-receiver instead of a pointer-receiver) to (hopefully) avoid these allocations. Feel free to do this or just leave it like it is now, either way seems fine for me.

I added the check now also in the (*logger).Debug function. I tried to replace the implementation as you suggested but it lead to really poor performance. I think some additional changes would be required to solve that. Therefore I just left it as it is.

---

pkg/log/wrappers.go line 32 at r1 (raw file):

Previously, matzf (Matthias Frei) wrote…

Same log-level check as in Debug should be applied here and in Error as well.

Done.

---

pkg/log/wrappers.go line 77 at r1 (raw file):

Previously, matzf (Matthias Frei) wrote…

Let's add the level check here as well, and also in the Info and Error methods of this logger type. We can use the existing Enabled wrapper function instead of using the l.logger.Core().Enabled(...).

if l.Enabled(DebugLevel) {
   ...
}

Done.

[matzf]

Reviewed 1 of 1 files at r2, all commit messages.
Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @rohrerj)

---

pkg/log/wrappers.go line 44 at r2 (raw file):

}

func Enabled(lvl Level) bool {

This makes sense to avoid the repetition, but I'd rather not add this function to the API; the package level log functions are mainly here for convenience, the functionality is identical to using the Root() logger. If a user of this package wants to check if a log level is enabled, they can use Root().Enabled(...).

So, keep the function, but make it un-exported (rename it to enabled).

[rohrerj]

Reviewable status: 0 of 1 files reviewed, 1 unresolved discussion (waiting on @matzf)

---

pkg/log/wrappers.go line 44 at r2 (raw file):

Previously, matzf (Matthias Frei) wrote…

This makes sense to avoid the repetition, but I'd rather not add this function to the API; the package level log functions are mainly here for convenience, the functionality is identical to using the Root() logger. If a user of this package wants to check if a log level is enabled, they can use Root().Enabled(...).

So, keep the function, but make it un-exported (rename it to enabled).

Done.

[matzf]

Reviewed 1 of 1 files at r3, all commit messages.
Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @rohrerj)

[rohrerj]

Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @rohrerj)