Skip to content

Commit

Permalink
Add benchmarks for zerolog (#483)
Browse files Browse the repository at this point in the history
Add some benchmarks for `github.com/rs/zerolog`.

These aren't exactly the same as the benchmarks in the author's PR:

1. The author's benchmarks don't timestamp zerolog's output, which is
   why they're so startingly fast.
2. Zerolog's sampler is too simple for reasonable production use - it
   just blindly drops a percentage of logs, rather than reservoir
   sampling. Given that, I left out sampling benchmarks.

After those two adjustments, zerolog ends up being a bit faster than zap
(~50 ns) when not adding context, but much slower (~14000 ns) when
adding fields.

This seems like a reasonable price to pay for zap's configurability,
thread-safety, and encoding-agnosticism.

* DRY up Sprintf varargs

* Update README again
  • Loading branch information
akshayjshah committed Jul 25, 2017
1 parent a0c01aa commit f948727
Show file tree
Hide file tree
Showing 7 changed files with 233 additions and 97 deletions.
47 changes: 25 additions & 22 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -66,38 +66,41 @@ Log a message and 10 fields:

| Package | Time | Objects Allocated |
| :--- | :---: | :---: |
| :zap: zap | 3243 ns/op | 5 allocs/op |
| :zap: zap (sugared) | 4232 ns/op | 21 allocs/op |
| go-kit | 16652 ns/op | 126 allocs/op |
| lion | 16753 ns/op | 111 allocs/op |
| logrus | 22492 ns/op | 142 allocs/op |
| log15 | 36261 ns/op | 149 allocs/op |
| apex/log | 40263 ns/op | 126 allocs/op |
| :zap: zap | 3131 ns/op | 5 allocs/op |
| :zap: zap (sugared) | 4173 ns/op | 21 allocs/op |
| zerolog | 16154 ns/op | 90 allocs/op |
| lion | 16341 ns/op | 111 allocs/op |
| go-kit | 17049 ns/op | 126 allocs/op |
| logrus | 23662 ns/op | 142 allocs/op |
| log15 | 36351 ns/op | 149 allocs/op |
| apex/log | 42530 ns/op | 126 allocs/op |

Log a message with a logger that already has 10 fields of context:

| Package | Time | Objects Allocated |
| :--- | :---: | :---: |
| :zap: zap | 405 ns/op | 0 allocs/op |
| :zap: zap (sugared) | 547 ns/op | 2 allocs/op |
| lion | 6462 ns/op | 39 allocs/op |
| go-kit | 19563 ns/op | 115 allocs/op |
| logrus | 23127 ns/op | 130 allocs/op |
| log15 | 27495 ns/op | 79 allocs/op |
| apex/log | 38938 ns/op | 115 allocs/op |
| :zap: zap | 380 ns/op | 0 allocs/op |
| :zap: zap (sugared) | 564 ns/op | 2 allocs/op |
| zerolog | 321 ns/op | 0 allocs/op |
| lion | 7092 ns/op | 39 allocs/op |
| go-kit | 20226 ns/op | 115 allocs/op |
| logrus | 22312 ns/op | 130 allocs/op |
| log15 | 28788 ns/op | 79 allocs/op |
| apex/log | 42063 ns/op | 115 allocs/op |

Log a static string, without any context or `printf`-style templating:

| Package | Time | Objects Allocated |
| :--- | :---: | :---: |
| :zap: zap | 429 ns/op | 0 allocs/op |
| :zap: zap (sugared) | 549 ns/op | 2 allocs/op |
| standard library | 585 ns/op | 2 allocs/op |
| go-kit | 909 ns/op | 13 allocs/op |
| lion | 1420 ns/op | 10 allocs/op |
| logrus | 2404 ns/op | 27 allocs/op |
| apex/log | 3457 ns/op | 11 allocs/op |
| log15 | 6313 ns/op | 26 allocs/op |
| :zap: zap | 361 ns/op | 0 allocs/op |
| :zap: zap (sugared) | 534 ns/op | 2 allocs/op |
| zerolog | 323 ns/op | 0 allocs/op |
| standard library | 575 ns/op | 2 allocs/op |
| go-kit | 922 ns/op | 13 allocs/op |
| lion | 1413 ns/op | 10 allocs/op |
| logrus | 2291 ns/op | 27 allocs/op |
| apex/log | 3690 ns/op | 11 allocs/op |
| log15 | 5954 ns/op | 26 allocs/op |

## Development Status: Stable

Expand Down
171 changes: 110 additions & 61 deletions benchmarks/scenario_bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,6 @@ import (
"io/ioutil"
"log"
"testing"
"time"

"go.uber.org/zap"
)
Expand Down Expand Up @@ -65,18 +64,7 @@ func BenchmarkDisabledWithoutFields(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n",
1,
int64(1),
3.0,
"four!",
true,
time.Unix(0, 0),
errExample,
time.Second,
_oneUser,
"done!",
)
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
Expand All @@ -98,6 +86,15 @@ func BenchmarkDisabledWithoutFields(b *testing.B) {
}
})
})
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) {
Expand Down Expand Up @@ -136,18 +133,7 @@ func BenchmarkDisabledAccumulatedContext(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n",
1,
int64(1),
3.0,
"four!",
true,
time.Unix(0, 0),
errExample,
time.Second,
_oneUser,
"done!",
)
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
Expand All @@ -169,6 +155,15 @@ func BenchmarkDisabledAccumulatedContext(b *testing.B) {
}
})
})
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) {
Expand Down Expand Up @@ -220,6 +215,15 @@ func BenchmarkDisabledAddingFields(b *testing.B) {
}
})
})
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) {
Expand Down Expand Up @@ -271,18 +275,7 @@ func BenchmarkWithoutFields(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n",
1,
int64(1),
3.0,
"four!",
true,
time.Unix(0, 0),
errExample,
time.Second,
_oneUser,
"done!",
)
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
Expand Down Expand Up @@ -345,18 +338,36 @@ func BenchmarkWithoutFields(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Printf("%v %v %v %s %v %v %v %v %v %s\n",
1,
int64(1),
3.0,
"four!",
true,
time.Unix(0, 0),
errExample,
time.Second,
_oneUser,
"done!",
)
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))
}
}
})
})
Expand Down Expand Up @@ -411,18 +422,7 @@ func BenchmarkAccumulatedContext(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n",
1,
int64(1),
3.0,
"four!",
true,
time.Unix(0, 0),
errExample,
time.Second,
_oneUser,
"done!",
)
logger.Infof("%v %v %v %s %v %v %v %v %v %s\n", fakeFmtArgs()...)
}
})
})
Expand Down Expand Up @@ -471,6 +471,35 @@ func BenchmarkAccumulatedContext(b *testing.B) {
}
})
})
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) {
Expand Down Expand Up @@ -562,4 +591,24 @@ func BenchmarkAddingFields(b *testing.B) {
}
})
})
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))
}
}
})
})
}
17 changes: 17 additions & 0 deletions benchmarks/zap_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -153,3 +153,20 @@ func fakeSugarFields() []interface{} {
"error", errExample,
}
}

func fakeFmtArgs() []interface{} {
// Need to keep this a function instead of a package-global var so that we
// pay the cast-to-interface{} penalty on each call.
return []interface{}{
_tenInts[0],
_tenInts,
_tenStrings[0],
_tenStrings,
_tenTimes[0],
_tenTimes,
_oneUser,
_oneUser,
_tenUsers,
errExample,
}
}
63 changes: 63 additions & 0 deletions benchmarks/zerolog_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,63 @@
// 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"

"github.com/rs/zerolog"
)

func newZerolog() zerolog.Logger {
return zerolog.New(ioutil.Discard).With().Timestamp().Logger()
}

func newDisabledZerolog() zerolog.Logger {
return newZerolog().Level(zerolog.Disabled)
}

func fakeZerologFields(e *zerolog.Event) *zerolog.Event {
return e.
Int("int", _tenInts[0]).
Interface("ints", _tenInts).
Str("string", _tenStrings[0]).
Interface("strings", _tenStrings).
Time("time", _tenTimes[0]).
Interface("times", _tenTimes).
Interface("user1", _oneUser).
Interface("user2", _oneUser).
Interface("users", _tenUsers).
Err(errExample)
}

func fakeZerologContext(c zerolog.Context) zerolog.Context {
return c.
Int("int", _tenInts[0]).
Interface("ints", _tenInts).
Str("string", _tenStrings[0]).
Interface("strings", _tenStrings).
Time("time", _tenTimes[0]).
Interface("times", _tenTimes).
Interface("user1", _oneUser).
Interface("user2", _oneUser).
Interface("users", _tenUsers).
Err(errExample)
}
Loading

0 comments on commit f948727

Please sign in to comment.