search

uber-go / zap

Blazing fast, structured, leveled logging in Go.
https://pkg.go.dev/go.uber.org/zap
MIT License
21.72k stars 1.42k forks source link

Non-sugared logger always slower than the sugar counterpart #1385

Open fracasula opened 10 months ago

fracasula commented 10 months ago

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 commented 10 months ago

Why did you close this @fracasula?

prashantv commented 10 months ago

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 commented 10 months ago

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: