Calling Debug or Check on a Production Logger is slow

[MarcErdmann]

First of all: thank you for such a great library!
Unfortunately I have some performance issues when calling Check or Debug on a production logger. I am unsure if I am using the library wrong. I am using the following code:

package main

import (
	"os"
	"testing"

	log "github.com/sirupsen/logrus"
	"go.uber.org/zap"
)

func BenchmarkZap(b *testing.B) {
	logger, _ := zap.NewProduction()
	defer logger.Sync()

	for n := 0; n < b.N; n++ {
		logger.Debug("Test")
	}
}

func BenchmarkZapCheck(b *testing.B) {
	logger, _ := zap.NewProduction()
	defer logger.Sync()

	for n := 0; n < b.N; n++ {
		if ce := logger.Check(zap.DebugLevel, "Test"); ce != nil {
			ce.Write()
		}
	}
}

func BenchmarkLogrus(b *testing.B) {
	log.SetFormatter(&log.JSONFormatter{})
	log.SetOutput(os.Stdout)
	log.SetLevel(log.WarnLevel)

	for n := 0; n < b.N; n++ {
		log.Debug("Test")
	}
}

And I get the following results:

goos: linux
goarch: amd64
pkg: bachelorarbeit
BenchmarkZap-4        	15698260	        74.8 ns/op	       0 B/op	       0 allocs/op
BenchmarkZapCheck-4   	17619888	        68.1 ns/op	       0 B/op	       0 allocs/op
BenchmarkLogrus-4     	341667280	         3.54 ns/op	       0 B/op	       0 allocs/op

Is this performance expected?

[abhinav]

Hello! No, you're not using Zap incorrectly. Logrus is misconfigured in that
example. Logs are being emitted at the debug level but the logger is
configured to discard anything below Warn.

After fixing the configuration, we get a more accurate idea of logging
performance.

func BenchmarkLogrus(b *testing.B) {
  log.SetFormatter(&log.JSONFormatter{})
  log.SetOutput(ioutil.Discard)
- log.SetLevel(log.WarnLevel)
+ log.SetLevel(log.DebugLevel)

BenchmarkZap-4             12965005                88.3 ns/op
BenchmarkZapCheck-4        13573184                88.3 ns/op
BenchmarkLogrus-4            453739              2583 ns/op

Hope that helped!

[MarcErdmann]

Thanks for your reply. To discard the logs was my intention actually. The CPU profile of my production application shows that zap uses 20% of my application's CPU time. Although I always use the method "check" and the production configuration. Logrus seems to be 20 times faster discarding debug logs in a production environment. Is there a reason for this?

[abhinav]

Oops, you're right. I misread the example.

[abhinav]

Dug into this. Most of the time is spent on time.Now. Looks like there was
prior discussion on dropping the time.Now call in #664, but it's unavoidable
until 2.0.

[prashantv]

One option: the Core embeds LevelEnabler, so it's quite reasonable to check the level before we create an entry and call Check on the underlying core. See PR: #771

The above benchmark, before:

BenchmarkZap-12                 16877612                60.0 ns/op
BenchmarkZapCheck-12            19379218                59.7 ns/op
BenchmarkLogrus-12              416875682                2.92 ns/op

and after:

BenchmarkZap-12                 113397655               10.2 ns/op
BenchmarkZapCheck-12            156923647                7.60 ns/op
BenchmarkLogrus-12              411759578                2.96 ns/op

Zap is still slower, likely because:

• We use an atomic for the level so it can be changed dynamically. The user can create their own logger with a custom LevelEnabler which isn't an atomic, that should be a little faster.
• We lose inlining due to the interfaces.