Skip to content

Commit

Permalink
Use Time.AppendFormat when possible (uber-go#786)
Browse files Browse the repository at this point in the history
Fixes uber-go#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%
```
  • Loading branch information
prashantv authored Feb 19, 2020
1 parent 3005bdc commit 407aaae
Show file tree
Hide file tree
Showing 5 changed files with 99 additions and 11 deletions.
10 changes: 9 additions & 1 deletion buffer/buffer.go
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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) {
Expand Down
2 changes: 2 additions & 0 deletions buffer/buffer_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ import (
"bytes"
"strings"
"testing"
"time"

"github.com/stretchr/testify/assert"
)
Expand All @@ -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 {
Expand Down
28 changes: 25 additions & 3 deletions zapcore/encoder.go
Original file line number Diff line number Diff line change
Expand Up @@ -112,21 +112,43 @@ func EpochNanosTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) {
enc.AppendInt64(t.UnixNano())
}

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
}

enc.AppendString(t.Format(layout))
}

// 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 pre-formatted string value.
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.
//
// If enc supports AppendTimeLayout(t time.Time,layout string), it's used
// instead of appending a pre-formatted string value.
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.
//
// If enc supports AppendTimeLayout(t time.Time,layout string), it's used
// instead of appending a pre-formatted string value.
func RFC3339NanoTimeEncoder(t time.Time, enc PrimitiveArrayEncoder) {
enc.AppendString(t.Format(time.RFC3339Nano))
encodeTimeLayout(t, time.RFC3339Nano, enc)
}

// UnmarshalText unmarshals text to a TimeEncoder.
Expand Down
6 changes: 6 additions & 0 deletions zapcore/json_encoder.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
64 changes: 57 additions & 7 deletions zapcore/json_encoder_impl_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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()}
Expand Down Expand Up @@ -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)
})
}
}
Expand Down Expand Up @@ -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.")
})
Expand All @@ -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.")

Expand Down

0 comments on commit 407aaae

Please sign in to comment.