From 19424758e8aaf33e6e5a06a9cde9b55d460d19df Mon Sep 17 00:00:00 2001 From: Prashant Varanasi Date: Tue, 11 Feb 2020 21:27:17 -0800 Subject: [PATCH 1/3] Use Time.AppendFormat when possible Fixes #783. We can take advantage of Time.AppendFormat by adding a new exported method to the JSON encoder, and upcasting when encoding time to use the append-based method. This avoids an allocation to convert the time to a string before appending to the buffer. The benchmarks use the production config, which uses a nanos encoder so to understand the performance difference, I tweaked `BenchmarkZapJSON` to use RFC3339TimeEncoder and ran benchmarks: ``` > benchcmp -best old new benchmark old ns/op new ns/op delta BenchmarkZapJSON-12 514 497 -3.31% benchmark old allocs new allocs delta BenchmarkZapJSON-12 5 4 -20.00% benchmark old bytes new bytes delta BenchmarkZapJSON-12 1297 1265 -2.47% ``` I also wrote a benchmark that only logs a simple message using the RFC3339TimeEncoder, ``` func BenchmarkTimeEncoder(b *testing.B) { cfg := NewProductionConfig().EncoderConfig cfg.EncodeTime = zapcore.RFC3339TimeEncoder logger := New( zapcore.NewCore( zapcore.NewJSONEncoder(cfg), &ztest.Discarder{}, DebugLevel, )) b.ResetTimer() for i := 0; i < b.N; i++ { logger.Info("test") } } ``` Results: ``` > benchcmp -best old new benchmark old ns/op new ns/op delta BenchmarkTimeEncoder-12 695 571 -17.84% benchmark old allocs new allocs delta BenchmarkTimeEncoder-12 1 0 -100.00% benchmark old bytes new bytes delta BenchmarkTimeEncoder-12 32 0 -100.00% ``` --- buffer/buffer.go | 10 ++++- buffer/buffer_test.go | 2 + zapcore/encoder.go | 19 +++++++-- zapcore/json_encoder.go | 6 +++ zapcore/json_encoder_impl_test.go | 64 +++++++++++++++++++++++++++---- 5 files changed, 90 insertions(+), 11 deletions(-) diff --git a/buffer/buffer.go b/buffer/buffer.go index 7592e8c63..3f4b86e08 100644 --- a/buffer/buffer.go +++ b/buffer/buffer.go @@ -23,7 +23,10 @@ // package's zero-allocation formatters. package buffer // import "go.uber.org/zap/buffer" -import "strconv" +import ( + "strconv" + "time" +) const _size = 1024 // by default, create 1 KiB buffers @@ -49,6 +52,11 @@ func (b *Buffer) AppendInt(i int64) { b.bs = strconv.AppendInt(b.bs, i, 10) } +// AppendTime appends the time formatted using the specified layout. +func (b *Buffer) AppendTime(t time.Time, layout string) { + b.bs = t.AppendFormat(b.bs, layout) +} + // AppendUint appends an unsigned integer to the underlying buffer (assuming // base 10). func (b *Buffer) AppendUint(i uint64) { diff --git a/buffer/buffer_test.go b/buffer/buffer_test.go index 59bc08a6a..96b81c294 100644 --- a/buffer/buffer_test.go +++ b/buffer/buffer_test.go @@ -24,6 +24,7 @@ import ( "bytes" "strings" "testing" + "time" "github.com/stretchr/testify/assert" ) @@ -46,6 +47,7 @@ func TestBufferWrites(t *testing.T) { // Intenationally introduce some floating-point error. {"AppendFloat32", func() { buf.AppendFloat(float64(float32(3.14)), 32) }, "3.14"}, {"AppendWrite", func() { buf.Write([]byte("foo")) }, "foo"}, + {"AppendTime", func() { buf.AppendTime(time.Date(2000, 1, 2, 3, 4, 5, 6, time.UTC), time.RFC3339) }, "2000-01-02T03:04:05Z"}, } for _, tt := range tests { diff --git a/zapcore/encoder.go b/zapcore/encoder.go index becc0ff88..2cd4ebc44 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -112,21 +112,34 @@ func EpochNanosTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { enc.AppendInt64(t.UnixNano()) } +type appendTimeEncoder interface { + AppendTimeLayout(time.Time, string) +} + +func encodeTimeLayout(t time.Time, layout string, enc PrimitiveArrayEncoder) { + if enc, ok := enc.(appendTimeEncoder); ok { + enc.AppendTimeLayout(t, layout) + return + } + + enc.AppendString(t.Format(layout)) +} + // ISO8601TimeEncoder serializes a time.Time to an ISO8601-formatted string // with millisecond precision. func ISO8601TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { - enc.AppendString(t.Format("2006-01-02T15:04:05.000Z0700")) + encodeTimeLayout(t, "2006-01-02T15:04:05.000Z0700", enc) } // RFC3339TimeEncoder serializes a time.Time to an RFC3339-formatted string. func RFC3339TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { - enc.AppendString(t.Format(time.RFC3339)) + encodeTimeLayout(t, time.RFC3339, enc) } // RFC3339NanoTimeEncoder serializes a time.Time to an RFC3339-formatted string // with nanosecond precision. func RFC3339NanoTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { - enc.AppendString(t.Format(time.RFC3339Nano)) + encodeTimeLayout(t, time.RFC3339Nano, enc) } // UnmarshalText unmarshals text to a TimeEncoder. diff --git a/zapcore/json_encoder.go b/zapcore/json_encoder.go index 56256be8d..07f1897ed 100644 --- a/zapcore/json_encoder.go +++ b/zapcore/json_encoder.go @@ -266,6 +266,12 @@ func (enc *jsonEncoder) AppendString(val string) { enc.buf.AppendByte('"') } +func (enc *jsonEncoder) AppendTimeLayout(time time.Time, layout string) { + enc.buf.AppendByte('"') + enc.buf.AppendTime(time, layout) + enc.buf.AppendByte('"') +} + func (enc *jsonEncoder) AppendTime(val time.Time) { cur := enc.buf.Len() enc.EncodeTime(val, enc) diff --git a/zapcore/json_encoder_impl_test.go b/zapcore/json_encoder_impl_test.go index 183e2b8c1..81e3ed384 100644 --- a/zapcore/json_encoder_impl_test.go +++ b/zapcore/json_encoder_impl_test.go @@ -36,6 +36,11 @@ import ( "go.uber.org/multierr" ) +var _defaultEncoderConfig = EncoderConfig{ + EncodeTime: EpochTimeEncoder, + EncodeDuration: SecondsDurationEncoder, +} + func TestJSONClone(t *testing.T) { // The parent encoder is created with plenty of excess capacity. parent := &jsonEncoder{buf: bufferpool.Get()} @@ -224,7 +229,55 @@ func TestJSONEncoderObjectFields(t *testing.T) { for _, tt := range tests { t.Run(tt.desc, func(t *testing.T) { - assertOutput(t, tt.expected, tt.f) + assertOutput(t, _defaultEncoderConfig, tt.expected, tt.f) + }) + } +} + +func TestJSONEncoderTimeFormats(t *testing.T) { + date := time.Date(2000, time.January, 2, 3, 4, 5, 6, time.UTC) + + f := func(e Encoder) { + e.AddTime("k", date) + e.AddArray("a", ArrayMarshalerFunc(func(enc ArrayEncoder) error { + enc.AppendTime(date) + return nil + })) + } + tests := []struct { + desc string + cfg EncoderConfig + expected string + }{ + { + desc: "time.Time ISO8601", + cfg: EncoderConfig{ + EncodeDuration: NanosDurationEncoder, + EncodeTime: ISO8601TimeEncoder, + }, + expected: `"k":"2000-01-02T03:04:05.000Z","a":["2000-01-02T03:04:05.000Z"]`, + }, + { + desc: "time.Time RFC3339", + cfg: EncoderConfig{ + EncodeDuration: NanosDurationEncoder, + EncodeTime: RFC3339TimeEncoder, + }, + expected: `"k":"2000-01-02T03:04:05Z","a":["2000-01-02T03:04:05Z"]`, + }, + { + desc: "time.Time RFC3339Nano", + cfg: EncoderConfig{ + EncodeDuration: NanosDurationEncoder, + EncodeTime: RFC3339NanoTimeEncoder, + }, + expected: `"k":"2000-01-02T03:04:05.000000006Z","a":["2000-01-02T03:04:05.000000006Z"]`, + }, + } + + for _, tt := range tests { + t.Run(tt.desc, func(t *testing.T) { + assertOutput(t, tt.cfg, tt.expected, f) }) } } @@ -324,7 +377,7 @@ func TestJSONEncoderArrays(t *testing.T) { return nil })) } - assertOutput(t, `"array":`+tt.expected, func(enc Encoder) { + assertOutput(t, _defaultEncoderConfig, `"array":`+tt.expected, func(enc Encoder) { err := f(enc) assert.NoError(t, err, "Unexpected error adding array to JSON encoder.") }) @@ -336,11 +389,8 @@ func assertJSON(t *testing.T, expected string, enc *jsonEncoder) { assert.Equal(t, expected, enc.buf.String(), "Encoded JSON didn't match expectations.") } -func assertOutput(t testing.TB, expected string, f func(Encoder)) { - enc := &jsonEncoder{buf: bufferpool.Get(), EncoderConfig: &EncoderConfig{ - EncodeTime: EpochTimeEncoder, - EncodeDuration: SecondsDurationEncoder, - }} +func assertOutput(t testing.TB, cfg EncoderConfig, expected string, f func(Encoder)) { + enc := &jsonEncoder{buf: bufferpool.Get(), EncoderConfig: &cfg} f(enc) assert.Equal(t, expected, enc.buf.String(), "Unexpected encoder output after adding.") From f88859e1cc075f8565206373f2c1d5e82092cfae Mon Sep 17 00:00:00 2001 From: Prashant Varanasi Date: Thu, 13 Feb 2020 14:30:44 -0800 Subject: [PATCH 2/3] Add documentation about AppendTimeLayout support for encoders --- zapcore/encoder.go | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/zapcore/encoder.go b/zapcore/encoder.go index 2cd4ebc44..f0e480569 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -127,17 +127,26 @@ func encodeTimeLayout(t time.Time, layout string, enc PrimitiveArrayEncoder) { // ISO8601TimeEncoder serializes a time.Time to an ISO8601-formatted string // with millisecond precision. +// +// If enc supports AppendTimeLayout(t time.Time,layout string), it's used +// instead of appending a per-formatted string value. func ISO8601TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { encodeTimeLayout(t, "2006-01-02T15:04:05.000Z0700", enc) } // RFC3339TimeEncoder serializes a time.Time to an RFC3339-formatted string. +// +// If enc supports AppendTimeLayout(t time.Time,layout string), it's used +// instead of appending a per-formatted string value. func RFC3339TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { encodeTimeLayout(t, time.RFC3339, enc) } // RFC3339NanoTimeEncoder serializes a time.Time to an RFC3339-formatted string // with nanosecond precision. +// +// If enc supports AppendTimeLayout(t time.Time,layout string), it's used +// instead of appending a per-formatted string value. func RFC3339NanoTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { encodeTimeLayout(t, time.RFC3339Nano, enc) } From ee5afed79b4f0a3cc0461b95fea3a002c9c32261 Mon Sep 17 00:00:00 2001 From: Prashant Varanasi Date: Fri, 14 Feb 2020 15:15:09 -0800 Subject: [PATCH 3/3] CR feedback --- zapcore/encoder.go | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/zapcore/encoder.go b/zapcore/encoder.go index f0e480569..6c78f7e49 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -112,11 +112,11 @@ func EpochNanosTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { enc.AppendInt64(t.UnixNano()) } -type appendTimeEncoder interface { - AppendTimeLayout(time.Time, string) -} - func encodeTimeLayout(t time.Time, layout string, enc PrimitiveArrayEncoder) { + type appendTimeEncoder interface { + AppendTimeLayout(time.Time, string) + } + if enc, ok := enc.(appendTimeEncoder); ok { enc.AppendTimeLayout(t, layout) return @@ -129,7 +129,7 @@ func encodeTimeLayout(t time.Time, layout string, enc PrimitiveArrayEncoder) { // with millisecond precision. // // If enc supports AppendTimeLayout(t time.Time,layout string), it's used -// instead of appending a per-formatted string value. +// instead of appending a pre-formatted string value. func ISO8601TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { encodeTimeLayout(t, "2006-01-02T15:04:05.000Z0700", enc) } @@ -137,7 +137,7 @@ func ISO8601TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { // RFC3339TimeEncoder serializes a time.Time to an RFC3339-formatted string. // // If enc supports AppendTimeLayout(t time.Time,layout string), it's used -// instead of appending a per-formatted string value. +// instead of appending a pre-formatted string value. func RFC3339TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { encodeTimeLayout(t, time.RFC3339, enc) } @@ -146,7 +146,7 @@ func RFC3339TimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { // with nanosecond precision. // // If enc supports AppendTimeLayout(t time.Time,layout string), it's used -// instead of appending a per-formatted string value. +// instead of appending a pre-formatted string value. func RFC3339NanoTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) { encodeTimeLayout(t, time.RFC3339Nano, enc) }