zerolog: fix log level

[lgfa29]

zerolog.Logger.Level() returns a new logger, which was being ignored, causing SetLevel() to be a no-op.

Store the current logger in a atomic.Value that is swapped for the new logger whenever SetLevel() is called.

[ShivanshVij]

The PR itself looks good but I'm concerned about the atomic lookup every time we log something.

I'm approving this if you're confident that a single atomic lookup is fine, but in all honesty I think I'd prefer we don't bother with the atomic value. If there's a race getting the logger pointer then there's a race getting the logger pointer.

[lgfa29]

Hum...yeah, good point. Since zerolog uses immutable loggers, I think the worse case for a race between a SetLevel() and a Msg() would be a few log lines emitted at the outdated level, which may not be a big deal. I will test a lock-free version.

[lgfa29]

Implemented and benchmarked a few alternative implementations.

Benchmark test:

func BenchmarkLogs(b *testing.B) {
	out := &bytes.Buffer{}
	out.Grow(100 * 1024 * 1024)
	log := New(Zerolog, b.Name(), out)

	doneCh := make(chan struct{})
	b.Cleanup(func() {
		close(doneCh)
	})

	go func() {
		ticker := time.NewTicker(time.Millisecond)

		for {
			select {
			case <-doneCh:
				return
			case <-ticker.C:
				if log.Level() == types.InfoLevel {
					log.SetLevel(types.DebugLevel)
				} else {
					log.SetLevel(types.InfoLevel)
				}
			}
		}
	}()

	b.ResetTimer()

	for n := 0; n < b.N; n++ {
		log.Info().Msg("test")
	}
}

Base line (main):

$ go test -bench=. -run BenchmarkLogs -count=10 .
goos: darwin
goarch: arm64
pkg: github.com/loopholelabs/logging
BenchmarkLogs-12        12905925               102.2 ns/op
BenchmarkLogs-12        14153098                90.54 ns/op
BenchmarkLogs-12        14161108                90.51 ns/op
BenchmarkLogs-12        13790361                90.77 ns/op
BenchmarkLogs-12        13766762                92.12 ns/op
BenchmarkLogs-12        14217510                90.92 ns/op
BenchmarkLogs-12        14149426                91.80 ns/op
BenchmarkLogs-12        13994242                92.80 ns/op
BenchmarkLogs-12        13713292                91.54 ns/op
BenchmarkLogs-12        14195317                92.13 ns/op
PASS
ok      github.com/loopholelabs/logging 14.226s

Using atomic (fix-zerolog-level, this branch):

$ go test -bench=. -run BenchmarkLogs -count=10 .
goos: darwin
goarch: arm64
pkg: github.com/loopholelabs/logging
BenchmarkLogs-12        12604886               106.5 ns/op
BenchmarkLogs-12        13758529                93.77 ns/op
BenchmarkLogs-12        13643521                94.53 ns/op
BenchmarkLogs-12        13253322                95.10 ns/op
BenchmarkLogs-12        13163426                95.45 ns/op
BenchmarkLogs-12        13709480                95.57 ns/op
BenchmarkLogs-12        13511484                96.22 ns/op
BenchmarkLogs-12        13509778                96.73 ns/op
BenchmarkLogs-12        13421860                95.99 ns/op
BenchmarkLogs-12        13511497                95.39 ns/op
PASS
ok      github.com/loopholelabs/logging 14.326s

Using a RWMutex (fix-zerolog-level-rwmutex):

$ go test -bench=. -run BenchmarkLogs -count=10 .
goos: darwin
goarch: arm64
pkg: github.com/loopholelabs/logging
BenchmarkLogs-12        13330321               114.8 ns/op
BenchmarkLogs-12        14138515                92.56 ns/op
BenchmarkLogs-12        13786005                93.19 ns/op
BenchmarkLogs-12        13814221                93.39 ns/op
BenchmarkLogs-12        13798687                94.29 ns/op
BenchmarkLogs-12        13733112                93.46 ns/op
BenchmarkLogs-12        13698942                93.34 ns/op
BenchmarkLogs-12        13815493                93.51 ns/op
BenchmarkLogs-12        13818423                93.66 ns/op
BenchmarkLogs-12        13813830                93.12 ns/op
PASS
ok      github.com/loopholelabs/logging 14.435s

Lock-free (fix-zerolog-level-no-lock):

$ go test -bench=. -run BenchmarkLogs -count=10 .
goos: darwin
goarch: arm64
pkg: github.com/loopholelabs/logging
BenchmarkLogs-12        12690662               105.3 ns/op
BenchmarkLogs-12        13969880                92.13 ns/op
BenchmarkLogs-12        13978125                92.77 ns/op
BenchmarkLogs-12        13821679                93.08 ns/op
BenchmarkLogs-12        13871943                92.62 ns/op
BenchmarkLogs-12        13655002                92.60 ns/op
BenchmarkLogs-12        13860226                94.46 ns/op
BenchmarkLogs-12        13842420                93.70 ns/op
BenchmarkLogs-12        13782976                94.04 ns/op
BenchmarkLogs-12        13471938                96.16 ns/op
PASS
ok      github.com/loopholelabs/logging 14.323s

As expected, the lock-free implementation is the fastest, but, also as expected, it causes -race to trigger an error.

Kind of weird that main is so much slower. I would expect twice as slow because the log level setting is not being applied, so it's logging twice as many messages as the other branches, but it's a whole order of magnitude slower

I think the RWMutex implementation may be a good compromise, faster than the atomic, and safer than the lock-free.

[lgfa29]

I ran a CPU profile on the benchmark and I think the discrepancies I was seeing in main were caused by the buffer having to grow due to the additional log messages, so I changed the test to preallocate a large buffer and also to flip between INFO and DEBUG so that all branches log about the same volume of messages, and the test results now seem consistent. I've updated the previous comment with the new results.

RWMutex seems to still be a good choice?

[ShivanshVij]

@lgfa29 I can absolutely live with the RWMutex implementation. Merge at will.

[lgfa29]

Awesome! I will replace this branch with fix-zerolog-level-rwmutex