Make benchmarks more rigorous (uber-go#482)

The benchmark fields are overly simple - they're all single objects, and most are primitives. Make the benchmarks push zap a bit harder by adding more complex types. Along the way, alter the script that generates the README to always sort zap to the top.
vosonwang · Jul 24, 2017 · a0c01aa · a0c01aa
1 parent 9d9d613
commit a0c01aa
Show file tree

Hide file tree

Showing 6 changed files with 132 additions and 88 deletions.
diff --git a/README.md b/README.md
@@ -64,40 +64,40 @@ id="anchor-versions">[1](#footnote-versions)</sup>
 
 Log a message and 10 fields:
 
-| Package | Time | Bytes Allocated | Objects Allocated |
-| :--- | :---: | :---: | :---: |
-| :zap: zap | 1692 ns/op | 705 B/op | 2 allocs/op |
-| :zap: zap (sugared) | 2507 ns/op | 1610 B/op | 20 allocs/op |
-| go-kit | 6327 ns/op | 2895 B/op | 66 allocs/op |
-| lion | 8036 ns/op | 5807 B/op | 63 allocs/op |
-| logrus | 8970 ns/op | 6092 B/op | 78 allocs/op |
-| apex/log | 17101 ns/op | 3832 B/op | 65 allocs/op |
-| log15 | 21398 ns/op | 5632 B/op | 93 allocs/op |
+| 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 |
 
 Log a message with a logger that already has 10 fields of context:
 
-| Package | Time | Bytes Allocated | Objects Allocated |
-| :--- | :---: | :---: | :---: |
-| :zap: zap | 467 ns/op | 0 B/op | 0 allocs/op |
-| :zap: zap (sugared) | 597 ns/op | 80 B/op | 2 allocs/op |
-| lion | 5172 ns/op | 4074 B/op | 38 allocs/op |
-| go-kit | 6892 ns/op | 3078 B/op | 53 allocs/op |
-| logrus | 8102 ns/op | 4564 B/op | 63 allocs/op |
-| apex/log | 15332 ns/op | 2897 B/op | 51 allocs/op |
-| log15 | 16905 ns/op | 2642 B/op | 44 allocs/op |
+| 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 |
 
 Log a static string, without any context or `printf`-style templating:
 
-| Package | Time | Bytes Allocated | Objects Allocated |
-| :--- | :---: | :---: | :---: |
-| :zap: zap | 465 ns/op | 0 B/op | 0 allocs/op |
-| standard library | 602 ns/op | 80 B/op | 2 allocs/op |
-| :zap: zap (sugared) | 647 ns/op | 80 B/op | 2 allocs/op |
-| go-kit | 994 ns/op | 656 B/op | 13 allocs/op |
-| lion | 1402 ns/op | 1224 B/op | 10 allocs/op |
-| logrus | 2299 ns/op | 1505 B/op | 27 allocs/op |
-| apex/log | 3148 ns/op | 584 B/op | 11 allocs/op |
-| log15 | 6329 ns/op | 1592 B/op | 26 allocs/op |
+| 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 |
 
 ## Development Status: Stable
 

diff --git a/benchmarks/apex_test.go b/benchmarks/apex_test.go
@@ -22,7 +22,6 @@ package benchmarks
 
 import (
 	"io/ioutil"
-	"time"
 
 	"github.com/apex/log"
 	"github.com/apex/log/handlers/json"
@@ -44,15 +43,15 @@ func newApexLog() *log.Logger {
 
 func fakeApexFields() log.Fields {
 	return log.Fields{
-		"int":               1,
-		"int64":             int64(1),
-		"float":             3.0,
-		"string":            "four!",
-		"bool":              true,
-		"time":              time.Unix(0, 0),
-		"error":             errExample.Error(),
-		"duration":          time.Second,
-		"user-defined type": _jane,
-		"another string":    "done!",
+		"int":     _tenInts[0],
+		"ints":    _tenInts,
+		"string":  _tenStrings[0],
+		"strings": _tenStrings,
+		"time":    _tenTimes[0],
+		"times":   _tenTimes,
+		"user1":   _oneUser,
+		"user2":   _oneUser,
+		"users":   _tenUsers,
+		"error":   errExample,
 	}
 }
diff --git a/benchmarks/logrus_test.go b/benchmarks/logrus_test.go
@@ -22,7 +22,6 @@ package benchmarks
 
 import (
 	"io/ioutil"
-	"time"
 
 	"github.com/sirupsen/logrus"
 )
@@ -44,15 +43,15 @@ func newLogrus() *logrus.Logger {
 
 func fakeLogrusFields() logrus.Fields {
 	return logrus.Fields{
-		"int":               1,
-		"int64":             int64(1),
-		"float":             3.0,
-		"string":            "four!",
-		"bool":              true,
-		"time":              time.Unix(0, 0),
-		"error":             errExample.Error(),
-		"duration":          time.Second,
-		"user-defined type": _jane,
-		"another string":    "done!",
+		"int":     _tenInts[0],
+		"ints":    _tenInts,
+		"string":  _tenStrings[0],
+		"strings": _tenStrings,
+		"time":    _tenTimes[0],
+		"times":   _tenTimes,
+		"user1":   _oneUser,
+		"user2":   _oneUser,
+		"users":   _tenUsers,
+		"error":   errExample,
 	}
 }
diff --git a/benchmarks/scenario_bench_test.go b/benchmarks/scenario_bench_test.go
@@ -74,7 +74,7 @@ func BenchmarkDisabledWithoutFields(b *testing.B) {
 					time.Unix(0, 0),
 					errExample,
 					time.Second,
-					_jane,
+					_oneUser,
 					"done!",
 				)
 			}
@@ -145,7 +145,7 @@ func BenchmarkDisabledAccumulatedContext(b *testing.B) {
 					time.Unix(0, 0),
 					errExample,
 					time.Second,
-					_jane,
+					_oneUser,
 					"done!",
 				)
 			}
@@ -280,7 +280,7 @@ func BenchmarkWithoutFields(b *testing.B) {
 					time.Unix(0, 0),
 					errExample,
 					time.Second,
-					_jane,
+					_oneUser,
 					"done!",
 				)
 			}
@@ -354,7 +354,7 @@ func BenchmarkWithoutFields(b *testing.B) {
 					time.Unix(0, 0),
 					errExample,
 					time.Second,
-					_jane,
+					_oneUser,
 					"done!",
 				)
 			}
@@ -420,7 +420,7 @@ func BenchmarkAccumulatedContext(b *testing.B) {
 					time.Unix(0, 0),
 					errExample,
 					time.Second,
-					_jane,
+					_oneUser,
 					"done!",
 				)
 			}

diff --git a/benchmarks/zap_test.go b/benchmarks/zap_test.go
@@ -25,6 +25,7 @@ import (
 	"fmt"
 	"time"
 
+	"go.uber.org/multierr"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 	"go.uber.org/zap/zaptest"
@@ -33,7 +34,38 @@ import (
 var (
 	errExample = errors.New("fail")
 
-	_messages = fakeMessages(1000)
+	_messages   = fakeMessages(1000)
+	_tenInts    = []int{1, 2, 3, 4, 5, 6, 7, 8, 9, 0}
+	_tenStrings = []string{"a", "b", "c", "d", "e", "f", "g", "h", "i", "j"}
+	_tenTimes   = []time.Time{
+		time.Unix(0, 0),
+		time.Unix(1, 0),
+		time.Unix(2, 0),
+		time.Unix(3, 0),
+		time.Unix(4, 0),
+		time.Unix(5, 0),
+		time.Unix(6, 0),
+		time.Unix(7, 0),
+		time.Unix(8, 0),
+		time.Unix(9, 0),
+	}
+	_oneUser = &user{
+		Name:      "Jane Doe",
+		Email:     "jane@test.com",
+		CreatedAt: time.Date(1980, 1, 1, 12, 0, 0, 0, time.UTC),
+	}
+	_tenUsers = users{
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+		_oneUser,
+	}
 )
 
 func fakeMessages(n int) []string {
@@ -48,28 +80,34 @@ func getMessage(iter int) string {
 	return _messages[iter%1000]
 }
 
+type users []*user
+
+func (uu users) MarshalLogArray(arr zapcore.ArrayEncoder) error {
+	var err error
+	for i := range uu {
+		err = multierr.Append(err, arr.AppendObject(uu[i]))
+	}
+	return err
+}
+
 type user struct {
 	Name      string    `json:"name"`
 	Email     string    `json:"email"`
 	CreatedAt time.Time `json:"created_at"`
 }
 
-func (u user) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+func (u *user) MarshalLogObject(enc zapcore.ObjectEncoder) error {
 	enc.AddString("name", u.Name)
 	enc.AddString("email", u.Email)
-	enc.AddInt64("created_at", u.CreatedAt.UnixNano())
+	enc.AddInt64("createdAt", u.CreatedAt.UnixNano())
 	return nil
 }
 
-var _jane = user{
-	Name:      "Jane Doe",
-	Email:     "jane@test.com",
-	CreatedAt: time.Date(1980, 1, 1, 12, 0, 0, 0, time.UTC),
-}
-
 func newZapLogger(lvl zapcore.Level) *zap.Logger {
-	// use the canned production encoder configuration
-	enc := zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())
+	ec := zap.NewProductionEncoderConfig()
+	ec.EncodeDuration = zapcore.NanosDurationEncoder
+	ec.EncodeTime = zapcore.EpochNanosTimeEncoder
+	enc := zapcore.NewJSONEncoder(ec)
 	return zap.New(zapcore.NewCore(
 		enc,
 		&zaptest.Discarder{},
@@ -88,30 +126,30 @@ func newSampledLogger(lvl zapcore.Level) *zap.Logger {
 
 func fakeFields() []zapcore.Field {
 	return []zapcore.Field{
-		zap.Int("int", 1),
-		zap.Int64("int64", 2),
-		zap.Float64("float", 3.0),
-		zap.String("string", "four!"),
-		zap.Bool("bool", true),
-		zap.Time("time", time.Unix(0, 0)),
+		zap.Int("int", _tenInts[0]),
+		zap.Ints("ints", _tenInts),
+		zap.String("string", _tenStrings[0]),
+		zap.Strings("strings", _tenStrings),
+		zap.Time("time", _tenTimes[0]),
+		zap.Times("times", _tenTimes),
+		zap.Object("user1", _oneUser),
+		zap.Object("user2", _oneUser),
+		zap.Array("users", _tenUsers),
 		zap.Error(errExample),
-		zap.Duration("duration", time.Second),
-		zap.Object("user-defined type", _jane),
-		zap.String("another string", "done!"),
 	}
 }
 
 func fakeSugarFields() []interface{} {
 	return []interface{}{
-		"int", 1,
-		"int64", 2,
-		"float", 3.0,
-		"string", "four!",
-		"bool", true,
-		"time", time.Unix(0, 0),
+		"int", _tenInts[0],
+		"ints", _tenInts,
+		"string", _tenStrings[0],
+		"strings", _tenStrings,
+		"time", _tenTimes[0],
+		"times", _tenTimes,
+		"user1", _oneUser,
+		"user2", _oneUser,
+		"users", _tenUsers,
 		"error", errExample,
-		"duration", time.Second,
-		"user-defined type", _jane,
-		"another string", "done!",
 	}
 }
diff --git a/internal/readme/readme.go b/internal/readme/readme.go
@@ -111,8 +111,8 @@ func getBenchmarkRows(benchmarkName string) (string, error) {
 	}
 	sort.Sort(benchmarkRowsByTime(benchmarkRows))
 	rows := []string{
-		"| Package | Time | Bytes Allocated | Objects Allocated |",
-		"| :--- | :---: | :---: | :---: |",
+		"| Package | Time | Objects Allocated |",
+		"| :--- | :---: | :---: |",
 	}
 	for _, benchmarkRow := range benchmarkRows {
 		rows = append(rows, benchmarkRow.String())
@@ -191,13 +191,21 @@ type benchmarkRow struct {
 }
 
 func (b *benchmarkRow) String() string {
-	return fmt.Sprintf("| %s | %d ns/op | %d B/op | %d allocs/op |", b.Name, b.Time.Nanoseconds(), b.AllocatedBytes, b.AllocatedObjects)
+	return fmt.Sprintf("| %s | %d ns/op | %d allocs/op |", b.Name, b.Time.Nanoseconds(), b.AllocatedObjects)
 }
 
 type benchmarkRowsByTime []*benchmarkRow
 
 func (b benchmarkRowsByTime) Len() int      { return len(b) }
 func (b benchmarkRowsByTime) Swap(i, j int) { b[i], b[j] = b[j], b[i] }
 func (b benchmarkRowsByTime) Less(i, j int) bool {
-	return b[i].Time.Nanoseconds() < b[j].Time.Nanoseconds()
+	left, right := b[i], b[j]
+	leftZap, rightZap := strings.Contains(left.Name, "zap"), strings.Contains(right.Name, "zap")
+
+	// If neither benchmark is for zap or both are, sort by time.
+	if !(leftZap || rightZap) || (leftZap && rightZap) {
+		return left.Time.Nanoseconds() < right.Time.Nanoseconds()
+	}
+	// Sort zap benchmark first.
+	return leftZap
 }