Non-sugared logger always slower than the sugar counterpart

[fracasula]

Describe the bug

The non-sugared logger is always slower than the sugar counterpart.

Can someone explain how come I'm getting these results?

To Reproduce

I'm using the latest zap i.e. v1.26.0

func BenchmarkZap(b *testing.B) {
	// BenchmarkZap/sugared-20         	 7758231	       135.8 ns/op
	b.Run("sugared", func(b *testing.B) {
		l, err := zap.NewProduction()
		if err != nil {
			b.Fatal(err)
		}
		ls := l.Sugar()
		defer ls.Sync()

		b.ResetTimer()
		for i := 0; i < b.N; i++ {
			ls.Infow("test", "key1", "1", "key2", 2)
		}
	})

	// BenchmarkZap/non-sugared-20     	 7065886	       168.0 ns/op
	b.Run("non-sugared", func(b *testing.B) {
		l, err := zap.NewProduction()
		if err != nil {
			b.Fatal(err)
		}
		defer l.Sync()

		b.ResetTimer()
		for i := 0; i < b.N; i++ {
			l.Info("test", zap.String("key1", "1"), zap.Int64("key2", 2))
		}
	})
}

When running the above benchmark with the Debug functions instead of Info the situation is even worse:

func BenchmarkZap(b *testing.B) {
	b.Run("sugared", func(b *testing.B) {
		l, err := zap.NewProduction()
		if err != nil {
			b.Fatal(err)
		}
		ls := l.Sugar()
		defer ls.Sync()

		b.ResetTimer()
		for i := 0; i < b.N; i++ {
			ls.Debugw("test", "key1", "1", "key2", 2)
		}
	})

	b.Run("non-sugared", func(b *testing.B) {
		l, err := zap.NewProduction()
		if err != nil {
			b.Fatal(err)
		}
		defer l.Sync()

		b.ResetTimer()
		for i := 0; i < b.N; i++ {
			l.Debug("test", zap.String("key1", "1"), zap.Int64("key2", 2))
		}
	})
}

The Debug benchmark gives the following (beware that I did not change the log level so nothing gets actually printed on screen when running this benchmark):

goos: linux
goarch: amd64
pkg: github.com/rudderlabs/rudder-go-kit/logger
cpu: 12th Gen Intel(R) Core(TM) i9-12900HK
BenchmarkZap
BenchmarkZap/sugared
BenchmarkZap/sugared-20         	247027641	         4.932 ns/op
BenchmarkZap/non-sugared
BenchmarkZap/non-sugared-20     	31585494	        40.08 ns/op
PASS

Expected behavior

Non-sugared logger should be faster. As per documentation it's supposed to be used in performance critical areas.

Additional context

None.

[rabbbit]

Why did you close this @fracasula?

[prashantv]

Reopening as this does look like a real issue. I did a little bit of investigation, and it seems like a combination of sampling, and how the lifetime of the fields maps to the write.

To make it easier to read the output, I'm changing the logger to write to /dev/null:

cfg := zap.NewProductionConfig()
cfg.OutputPaths = []string{"/dev/null"}
l, err := cfg.Build()

Otherwise, it's the same code as what you had, and it does show that sugar is faster, and we can see there's an additional alloc on the non-sugar logger,

BenchmarkZap/sugared            13319682                89.44 ns/op            5 B/op          0 allocs/op
BenchmarkZap/non-sugared        10174995               117.3 ns/op           130 B/op          1 allocs/op

If we disable sampling, the results change to what we'd expect, where sugar is slower,

cfg := zap.NewProductionConfig()
cfg.OutputPaths = []string{"/dev/null"}
cfg.Sampling = nil

BenchmarkZap/sugared              665176              1766 ns/op             504 B/op          3 allocs/op
BenchmarkZap/non-sugared          781226              1441 ns/op             376 B/op          3 allocs/op

With sampling enabled, since the message is constant, most of the logs are dropped. When logs aren't dropped, the input ...any is converted to a []zap.Field to the underlying core write. In the non-sugar case, the ...Field is passed as-is to the core write. This leads the escape analysis to behave differently.

To verify this, I put some temporary code into zap to pass in a copy of the fields to the core write, e.g., updating Info to:

// Info logs a message at InfoLevel. The message includes any fields passed
// at the log site, as well as any fields accumulated on the logger.
func (log *Logger) Info(msg string, fields ...Field) {
	if ce := log.check(InfoLevel, msg); ce != nil {
		ce.Write(copyFields(fields)...)
	}
}

With this copy in place, the escape analysis now sees that fields never escapes (it's never passed to the underlying interface), but then we'd pay for a copy if it does escape.

[fracasula]

Why did you close this @fracasula?

I needed more time to understand if I was reporting a false positive due to things like bad configuration.

Compare these two benchmark for example.

The first one with a custom configuration shows the non-sugared as much faster (like it should be) while the second one shows the opposite.

The only thing that changes is the configuration but I did not have the time to investigate further and temporarily closed the issue.

func BenchmarkZap(b *testing.B) {
	newZap := func(lvl zapcore.Level) *zap.Logger {
		ec := zap.NewProductionEncoderConfig()
		ec.EncodeDuration = zapcore.NanosDurationEncoder
		ec.EncodeTime = zapcore.EpochNanosTimeEncoder
		enc := zapcore.NewJSONEncoder(ec)
		return zap.New(zapcore.NewCore(
			enc,
			&discarder{},
			lvl,
		))
	}
	b.Run("Zap", func(b *testing.B) {
		logger := newZap(zapcore.DebugLevel)
		b.ResetTimer()
		b.RunParallel(func(pb *testing.PB) {
			for pb.Next() {
				logger.Debug("message", zap.String("key1", "111"), zap.Int("key2", 222))
			}
		})
	})
	b.Run("Zap.Sugar", func(b *testing.B) {
		logger := newZap(zapcore.DebugLevel).Sugar()
		b.ResetTimer()
		b.RunParallel(func(pb *testing.PB) {
			for pb.Next() {
				logger.Debugw("message", "key1", "111", "key2", 222)
			}
		})
	})
}

func BenchmarkZapSlow(b *testing.B) {
	b.Run("Zap", func(b *testing.B) {
		l, err := zap.NewProduction()
		if err != nil {
			b.Fatal(err)
		}
		defer l.Sync()

		b.ResetTimer()
		b.RunParallel(func(pb *testing.PB) {
			for pb.Next() {
				l.Debug("message", zap.String("key1", "111"), zap.Int("key2", 222))
			}
		})
	})

	b.Run("Zap.Sugar", func(b *testing.B) {
		l, err := zap.NewProduction()
		if err != nil {
			b.Fatal(err)
		}
		ls := l.Sugar()
		defer ls.Sync()

		b.ResetTimer()
		b.RunParallel(func(pb *testing.PB) {
			for pb.Next() {
				ls.Debugw("message", "key1", "111", "key2", 222)
			}
		})
	})
}

Gives:

go test -v -count 1 -bench=. -benchmem -run Benchmark ./logger
goos: linux
goarch: amd64
pkg: github.com/rudderlabs/rudder-go-kit/logger
cpu: 12th Gen Intel(R) Core(TM) i9-12900HK
BenchmarkZap
BenchmarkZap/Zap
BenchmarkZap/Zap-20    			24349593	        53.76 ns/op	     129 B/op	       1 allocs/op
BenchmarkZap/Zap.Sugar
BenchmarkZap/Zap.Sugar-20         	13165832	        90.20 ns/op	     258 B/op	       1 allocs/op
BenchmarkZapSlow
BenchmarkZapSlow/Zap
BenchmarkZapSlow/Zap-20           	37065819	        31.54 ns/op	     128 B/op	       1 allocs/op
BenchmarkZapSlow/Zap.Sugar
BenchmarkZapSlow/Zap.Sugar-20     	1000000000	         0.5974 ns/op	       0 B/op	       0 allocs/op
PASS
ok  	github.com/rudderlabs/rudder-go-kit/logger	4.517s

Please note that:

• none of the benchmark produce any output, the first one because we're discarding it with io.Discard, the second one because the log level isn't set to debug and we're invoking INFO
• the 2nd benchmark shows no allocations for the sugar version
• if we change the 2nd benchmark to use Info and Infow instead of Debug and Debugw we still see the non-sugared logger as slower:
  • Zap-20 9974296 105.7 ns/op 132 B/op 1 allocs/op
  • Zap.Sugar-20 22225963 70.65 ns/op 5 B/op 0 allocs/op