2021-11-08 16:39:17 +00:00

588 lines
15 KiB
Go

// Copyright (c) 2016 Uber Technologies, Inc.
//
// Permission is hereby granted, free of charge, to any person obtaining a copy
// of this software and associated documentation files (the "Software"), to deal
// in the Software without restriction, including without limitation the rights
// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
// copies of the Software, and to permit persons to whom the Software is
// furnished to do so, subject to the following conditions:
//
// The above copyright notice and this permission notice shall be included in
// all copies or substantial portions of the Software.
//
// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
// THE SOFTWARE.
package benchmarks
import (
"io/ioutil"
"log"
"testing"
"go.uber.org/zap"
)
func BenchmarkDisabledWithoutFields(b *testing.B) {
b.Logf("Logging at a disabled level without any structured context.")
b.Run("Zap", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.Check", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if m := logger.Check(zap.InfoLevel, getMessage(0)); m != nil {
m.Write()
}
}
})
})
b.Run("Zap.Sugar", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.SugarFormatting", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
b.Run("apex/log", func(b *testing.B) {
logger := newDisabledApexLog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("sirupsen/logrus", func(b *testing.B) {
logger := newDisabledLogrus()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("rs/zerolog", func(b *testing.B) {
logger := newDisabledZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info().Msg(getMessage(0))
}
})
})
}
func BenchmarkDisabledAccumulatedContext(b *testing.B) {
b.Logf("Logging at a disabled level with some accumulated context.")
b.Run("Zap", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).With(fakeFields()...)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.Check", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).With(fakeFields()...)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if m := logger.Check(zap.InfoLevel, getMessage(0)); m != nil {
m.Write()
}
}
})
})
b.Run("Zap.Sugar", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).With(fakeFields()...).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.SugarFormatting", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).With(fakeFields()...).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
b.Run("apex/log", func(b *testing.B) {
logger := newDisabledApexLog().WithFields(fakeApexFields())
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("sirupsen/logrus", func(b *testing.B) {
logger := newDisabledLogrus().WithFields(fakeLogrusFields())
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("rs/zerolog", func(b *testing.B) {
logger := fakeZerologContext(newDisabledZerolog().With()).Logger()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info().Msg(getMessage(0))
}
})
})
}
func BenchmarkDisabledAddingFields(b *testing.B) {
b.Logf("Logging at a disabled level, adding context at each log site.")
b.Run("Zap", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0), fakeFields()...)
}
})
})
b.Run("Zap.Check", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if m := logger.Check(zap.InfoLevel, getMessage(0)); m != nil {
m.Write(fakeFields()...)
}
}
})
})
b.Run("Zap.Sugar", func(b *testing.B) {
logger := newZapLogger(zap.ErrorLevel).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infow(getMessage(0), fakeSugarFields()...)
}
})
})
b.Run("apex/log", func(b *testing.B) {
logger := newDisabledApexLog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.WithFields(fakeApexFields()).Info(getMessage(0))
}
})
})
b.Run("sirupsen/logrus", func(b *testing.B) {
logger := newDisabledLogrus()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.WithFields(fakeLogrusFields()).Info(getMessage(0))
}
})
})
b.Run("rs/zerolog", func(b *testing.B) {
logger := newDisabledZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
fakeZerologFields(logger.Info()).Msg(getMessage(0))
}
})
})
}
func BenchmarkWithoutFields(b *testing.B) {
b.Logf("Logging without any structured context.")
b.Run("Zap", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.Check", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if ce := logger.Check(zap.InfoLevel, getMessage(0)); ce != nil {
ce.Write()
}
}
})
})
b.Run("Zap.CheckSampled", func(b *testing.B) {
logger := newSampledLogger(zap.DebugLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
i := 0
for pb.Next() {
i++
if ce := logger.Check(zap.InfoLevel, getMessage(i)); ce != nil {
ce.Write()
}
}
})
})
b.Run("Zap.Sugar", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.SugarFormatting", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
b.Run("apex/log", func(b *testing.B) {
logger := newApexLog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("go-kit/kit/log", func(b *testing.B) {
logger := newKitLog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Log(getMessage(0), getMessage(1))
}
})
})
b.Run("inconshreveable/log15", func(b *testing.B) {
logger := newLog15()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("sirupsen/logrus", func(b *testing.B) {
logger := newLogrus()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("stdlib.Println", func(b *testing.B) {
logger := log.New(ioutil.Discard, "", log.LstdFlags)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Println(getMessage(0))
}
})
})
b.Run("stdlib.Printf", func(b *testing.B) {
logger := log.New(ioutil.Discard, "", log.LstdFlags)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Printf("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
b.Run("rs/zerolog", func(b *testing.B) {
logger := newZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info().Msg(getMessage(0))
}
})
})
b.Run("rs/zerolog.Formatting", func(b *testing.B) {
logger := newZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info().Msgf("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
b.Run("rs/zerolog.Check", func(b *testing.B) {
logger := newZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if e := logger.Info(); e.Enabled() {
e.Msg(getMessage(0))
}
}
})
})
}
func BenchmarkAccumulatedContext(b *testing.B) {
b.Logf("Logging with some accumulated context.")
b.Run("Zap", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).With(fakeFields()...)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.Check", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).With(fakeFields()...)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if ce := logger.Check(zap.InfoLevel, getMessage(0)); ce != nil {
ce.Write()
}
}
})
})
b.Run("Zap.CheckSampled", func(b *testing.B) {
logger := newSampledLogger(zap.DebugLevel).With(fakeFields()...)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
i := 0
for pb.Next() {
i++
if ce := logger.Check(zap.InfoLevel, getMessage(i)); ce != nil {
ce.Write()
}
}
})
})
b.Run("Zap.Sugar", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).With(fakeFields()...).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("Zap.SugarFormatting", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).With(fakeFields()...).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
b.Run("apex/log", func(b *testing.B) {
logger := newApexLog().WithFields(fakeApexFields())
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("go-kit/kit/log", func(b *testing.B) {
logger := newKitLog(fakeSugarFields()...)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Log(getMessage(0), getMessage(1))
}
})
})
b.Run("inconshreveable/log15", func(b *testing.B) {
logger := newLog15().New(fakeSugarFields())
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("sirupsen/logrus", func(b *testing.B) {
logger := newLogrus().WithFields(fakeLogrusFields())
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0))
}
})
})
b.Run("rs/zerolog", func(b *testing.B) {
logger := fakeZerologContext(newZerolog().With()).Logger()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info().Msg(getMessage(0))
}
})
})
b.Run("rs/zerolog.Check", func(b *testing.B) {
logger := fakeZerologContext(newZerolog().With()).Logger()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if e := logger.Info(); e.Enabled() {
e.Msg(getMessage(0))
}
}
})
})
b.Run("rs/zerolog.Formatting", func(b *testing.B) {
logger := fakeZerologContext(newZerolog().With()).Logger()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info().Msgf("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
}
func BenchmarkAddingFields(b *testing.B) {
b.Logf("Logging with additional context at each log site.")
b.Run("Zap", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0), fakeFields()...)
}
})
})
b.Run("Zap.Check", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if ce := logger.Check(zap.InfoLevel, getMessage(0)); ce != nil {
ce.Write(fakeFields()...)
}
}
})
})
b.Run("Zap.CheckSampled", func(b *testing.B) {
logger := newSampledLogger(zap.DebugLevel)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
i := 0
for pb.Next() {
i++
if ce := logger.Check(zap.InfoLevel, getMessage(i)); ce != nil {
ce.Write(fakeFields()...)
}
}
})
})
b.Run("Zap.Sugar", func(b *testing.B) {
logger := newZapLogger(zap.DebugLevel).Sugar()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infow(getMessage(0), fakeSugarFields()...)
}
})
})
b.Run("apex/log", func(b *testing.B) {
logger := newApexLog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.WithFields(fakeApexFields()).Info(getMessage(0))
}
})
})
b.Run("go-kit/kit/log", func(b *testing.B) {
logger := newKitLog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Log(fakeSugarFields()...)
}
})
})
b.Run("inconshreveable/log15", func(b *testing.B) {
logger := newLog15()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info(getMessage(0), fakeSugarFields()...)
}
})
})
b.Run("sirupsen/logrus", func(b *testing.B) {
logger := newLogrus()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.WithFields(fakeLogrusFields()).Info(getMessage(0))
}
})
})
b.Run("rs/zerolog", func(b *testing.B) {
logger := newZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
fakeZerologFields(logger.Info()).Msg(getMessage(0))
}
})
})
b.Run("rs/zerolog.Check", func(b *testing.B) {
logger := newZerolog()
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
if e := logger.Info(); e.Enabled() {
fakeZerologFields(e).Msg(getMessage(0))
}
}
})
})
}