Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use Time.AppendFormat when possible #786

Merged
merged 3 commits into from
Feb 19, 2020
Merged

Use Time.AppendFormat when possible #786

merged 3 commits into from
Feb 19, 2020

Conversation

prashantv
Copy link
Collaborator

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%

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%
```
@prashantv prashantv requested a review from abhinav February 13, 2020 18:16
@codecov
Copy link

codecov bot commented Feb 13, 2020

Codecov Report

Merging #786 into master will increase coverage by 0.01%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #786      +/-   ##
==========================================
+ Coverage   98.21%   98.22%   +0.01%     
==========================================
  Files          43       43              
  Lines        2293     2306      +13     
==========================================
+ Hits         2252     2265      +13     
  Misses         33       33              
  Partials        8        8
Impacted Files Coverage Δ
zapcore/json_encoder.go 100% <100%> (ø) ⬆️
buffer/buffer.go 100% <100%> (ø) ⬆️
zapcore/encoder.go 86.27% <100%> (+1.01%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 127ea09...ee5afed. Read the comment docs.

zapcore/encoder.go Outdated Show resolved Hide resolved
Copy link
Contributor

@jcorbin jcorbin left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/per-formatted/pre-formatted/

}

func encodeTimeLayout(t time.Time, layout string, enc PrimitiveArrayEncoder) {
if enc, ok := enc.(appendTimeEncoder); ok {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fwiw: it's possible to just use an anonymous duck, ok := val.(interface { quack() }) in cases like this where aliasing the interfaces serves no other purpose

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, although the line looks kind of long and complicated.

However, I moved the interface into the method, since it's not needed outside of this method.

@prashantv prashantv merged commit fa2c78c into master Feb 19, 2020
@prashantv prashantv deleted the append_time branch February 19, 2020 18:59
abhinav added a commit that referenced this pull request Mar 12, 2020
In #786, we added support for improving the performance of encoding time
by allowing encoder implementations to implement AppendTimeLayout.

If the encoder implements, `AppendTimeLayout(time.Time, string)`, some
of the time encoders shipped with Zap will use that method, which in
turn can make use of `Buffer.AppendTime`.

That change inadvertently broke the JSON output for arrays of time that
make use of that functionality.

Compare the old version of AppendTimeLayout with AppendString (both
operations append a string to the array).

    func (enc *jsonEncoder) AppendString(val string) {
      enc.addElementSeparator()
      enc.buf.AppendByte('"')
      // ...
    }

    func (enc *jsonEncoder) AppendTimeLayout(time time.Time, layout string) {
      enc.buf.AppendByte('"')
      // ...
    }

Without the `enc.addElementSeparator` call, `AppendTimeLayout` does not
include the `,` separator between array elements, instead yielding the
following.

    ["2001-12-19T00:00:00Z""2002-12-18T00:00:00Z""2003-12-17T00:00:00Z"]

Fixes #798
abhinav added a commit that referenced this pull request Mar 14, 2020
In #786, we added support for improving the performance of encoding time
by allowing encoder implementations to implement AppendTimeLayout.

If the encoder implements, `AppendTimeLayout(time.Time, string)`, some
of the time encoders shipped with Zap will use that method, which in
turn can make use of `Buffer.AppendTime`.

That change inadvertently broke the JSON output for arrays of time that
make use of that functionality.

Compare the old version of AppendTimeLayout with AppendString (both
operations append a string to the array).

    func (enc *jsonEncoder) AppendString(val string) {
      enc.addElementSeparator()
      enc.buf.AppendByte('"')
      // ...
    }

    func (enc *jsonEncoder) AppendTimeLayout(time time.Time, layout string) {
      enc.buf.AppendByte('"')
      // ...
    }

Without the `enc.addElementSeparator` call, `AppendTimeLayout` does not
include the `,` separator between array elements, instead yielding the
following.

    ["2001-12-19T00:00:00Z""2002-12-18T00:00:00Z""2003-12-17T00:00:00Z"]

Fixes #798
cgxxv pushed a commit to cgxxv/zap that referenced this pull request Mar 25, 2022
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%
```
cgxxv pushed a commit to cgxxv/zap that referenced this pull request Mar 25, 2022
In uber-go#786, we added support for improving the performance of encoding time
by allowing encoder implementations to implement AppendTimeLayout.

If the encoder implements, `AppendTimeLayout(time.Time, string)`, some
of the time encoders shipped with Zap will use that method, which in
turn can make use of `Buffer.AppendTime`.

That change inadvertently broke the JSON output for arrays of time that
make use of that functionality.

Compare the old version of AppendTimeLayout with AppendString (both
operations append a string to the array).

    func (enc *jsonEncoder) AppendString(val string) {
      enc.addElementSeparator()
      enc.buf.AppendByte('"')
      // ...
    }

    func (enc *jsonEncoder) AppendTimeLayout(time time.Time, layout string) {
      enc.buf.AppendByte('"')
      // ...
    }

Without the `enc.addElementSeparator` call, `AppendTimeLayout` does not
include the `,` separator between array elements, instead yielding the
following.

    ["2001-12-19T00:00:00Z""2002-12-18T00:00:00Z""2003-12-17T00:00:00Z"]

Fixes uber-go#798
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

Taking advantage of Time.AppendFormat
3 participants