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

Add zapio.Writer #971

Merged
merged 4 commits into from Jun 25, 2021
Merged

Add zapio.Writer #971

merged 4 commits into from Jun 25, 2021

Conversation

abhinav
Copy link
Collaborator

@abhinav abhinav commented Jun 24, 2021

This adds a new zapio package that provides a Writer. The writer
implements io.WriteCloser and zapcore.WriteSyncer.

It works by splitting the input on newlines, flushing to the logger as
new lines are encountered, and buffering input otherwise.

So for example, if write "foobar\n" is split across multiple Write calls
"foo" and "bar\n", instead of emitting two separate logs for "foo"
and "bar", the Writer will buffer the input until the newline is
encountered and write a single log for "foobar".

Performance:

name             time/op
Writer/single-4  384ns ± 3%
Writer/splits-4  488ns ±26%

name             alloc/op
Writer/single-4  16.0B ± 0%
Writer/splits-4  16.0B ± 0%

name             allocs/op
Writer/single-4   2.00 ± 0%
Writer/splits-4   2.00 ± 0%

Resolves #929

@codecov
Copy link

codecov bot commented Jun 24, 2021

Codecov Report

Merging #971 (b6abcb8) into master (aa3e73e) will increase coverage by 0.04%.
The diff coverage is 100.00%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #971      +/-   ##
==========================================
+ Coverage   98.16%   98.21%   +0.04%     
==========================================
  Files          45       46       +1     
  Lines        2020     2076      +56     
==========================================
+ Hits         1983     2039      +56     
  Misses         29       29              
  Partials        8        8              
Impacted Files Coverage Δ
zapio/writer.go 100.00% <100.00%> (ø)
buffer/buffer.go 100.00% <0.00%> (ø)
zapcore/buffered_write_syncer.go 100.00% <0.00%> (ø)

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 aa3e73e...b6abcb8. Read the comment docs.

This adds a new zapio package that provides a `Writer`. The writer
implements `io.WriteCloser` and `zapcore.WriteSyncer`.

It works by splitting the input on newlines, flushing to the logger as
new lines are encountered, and buffering input otherwise.

So for example, if write "foobar\n" is split across multiple Write calls
"foo" and "bar\n", instead of emitting two separate logs for "foo"
and "bar", the Writer will buffer the input until the newline is
encountered and write a single log for "foobar".

Resolves #929
zapio/writer.go Show resolved Hide resolved
zapio/writer.go Outdated
Comment on lines 73 to 75
// Split on the newline, buffer and flush the left.
line, remaining = line[:idx], line[idx+1:]
w.buff.Write(line)
Copy link
Collaborator

Choose a reason for hiding this comment

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

optional performance optimization:
if the buffer is empty, we could write the contents directly to the logger without copying it to w.buff

Copy link
Collaborator Author

@abhinav abhinav Jun 24, 2021

Choose a reason for hiding this comment

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

Oh, that's a good idea. That'll be the case a majority of the time anyway.

zapio/writer.go Outdated
// if the bool is set.
func (w *Writer) flush(allowEmpty bool) {
if allowEmpty || w.buff.Len() > 0 {
if ce := w.Log.Check(w.Level, w.buff.String()); ce != nil {
Copy link
Collaborator

Choose a reason for hiding this comment

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

can we save some allocations using a strings.Builder instead of a bytes.Buffer?

Copy link
Collaborator Author

@abhinav abhinav Jun 24, 2021

Choose a reason for hiding this comment

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

I wrote a benchmark and tested that. strings.Builder performs the same because it throws away the buffer on each Reset.

Given that Zap will not use the string given to Check once we call ce.Write, it might be okay for us to cast the []byte to string unsafely.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

So I tried the unsafe cast. Turns out we can't do that after all.
We have no guarantee that a custom Core isn't holding onto the string.
In fact, I discovered the issue because zaptest/observer holds onto the string.

func (w *Writer) Write(bs []byte) (n int, err error) {
// Skip all checks if the level isn't enabled.
if !w.Log.Core().Enabled(w.Level) {
return len(bs), nil
Copy link
Contributor

Choose a reason for hiding this comment

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

Doesn't Write usually return len of bytes written? If so, shouldn't this be 0?

Suggested change
return len(bs), nil
return 0, nil

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

That's a valid point, in that we're not actually writing those bytes, but per https://golang.org/pkg/io/#Writer

Write must return a non-nil error if it returns n < len(p).

So this is less to detect "how much you wrote in reality" but more "how much were you able to write before it failed". If the logger is configured to not log at this level, it's a no-op, but we're still consuming the text, so I figured we'd want to tell the caller we consumed everything.

The alternative here is to return an error stating that the logger is not configured to log at this level, but I suspect that's undesirable.

Copy link
Contributor

Choose a reason for hiding this comment

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

Ok, that makes sense. I agree that telling the caller that we consumed everything would be better than returning an error. Thanks!

}

// Split on the newline, buffer and flush the left.
line, remaining = line[:idx], line[idx+1:]
Copy link
Contributor

Choose a reason for hiding this comment

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

if idx == len(bytes)-1, wouldn't line[idx+1:] panic?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Na, subslicing like foo[x:] works fine when x == len(foo), but not if x > len(foo).

https://play.golang.org/p/5f_L9-TqAUs

Add a benchmark that measures the performance of the writer when writes are
split across multiple lines, as well as when it's one log per write.

```
name             time/op
Writer/single-4  422ns ±21%
Writer/splits-4  433ns ± 4%

name             alloc/op
Writer/single-4  16.0B ± 0%
Writer/splits-4  16.0B ± 0%

name             allocs/op
Writer/single-4   2.00 ± 0%
Writer/splits-4   2.00 ± 0%
```
If we don't have a leftover partial write in the buffer, we can skip the
buffer completely and write directly to the logger.

This improves performance when log statements aren't split across too many
writes.

```
name             old time/op    new time/op    delta
Writer/single-4     422ns ±21%     383ns ± 2%  -9.26%  (p=0.000 n=10+9)
Writer/splits-4     433ns ± 4%     435ns ± 1%    ~     (p=0.236 n=9+8)

name             old alloc/op   new alloc/op   delta
Writer/single-4     16.0B ± 0%     16.0B ± 0%    ~     (all equal)
Writer/splits-4     16.0B ± 0%     16.0B ± 0%    ~     (all equal)

name             old allocs/op  new allocs/op  delta
Writer/single-4      2.00 ± 0%      2.00 ± 0%    ~     (all equal)
Writer/splits-4      2.00 ± 0%      2.00 ± 0%    ~     (all equal)
```
Copy link
Collaborator

@prashantv prashantv left a comment

Choose a reason for hiding this comment

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

Can you paste the benchmark results as well?

One other minor question: does it make sense to use this writer in place of loggerWriter?
https://github.com/uber-go/zap/blob/v1.17.0/global.go#L160

zapio/writer.go Show resolved Hide resolved
})
}
}

Copy link
Collaborator

Choose a reason for hiding this comment

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

can you add a test to ensure that Sync() doesn't flush out empty lines

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Ack

@abhinav
Copy link
Collaborator Author

abhinav commented Jun 24, 2021

Can you paste the benchmark results as well?

Yeah, they were in the individual commits. I'll add them to the PR description.

Add a test case to verify the behavior of Sync, especially with regard to
not logging anything when the buffer is empty.
@abhinav
Copy link
Collaborator Author

abhinav commented Jun 24, 2021

One other minor question: does it make sense to use this writer in place of loggerWriter?
https://github.com/uber-go/zap/blob/v1.17.0/global.go#L160

That's a good point, except we'll end up with a cycle between zap and
zapio. I don't have an immediate good solution for this, except maybe
moving zapio.Writer to the zap package. I originally elected to put it
in zapio because zap is already a pretty densely populated package.

Another way we can break the zapio->zap dependency by making the
*zap.Logger references in zapio use an interface but that seems like
it'll be limiting, especially if it means that we can never introduce a
dependency from zapio to zap.

So short of moving it to the zap package, we might have to live with
the duplication. Honestly, it might be justifiable with the argument
that "that's for Zap's own internal usage, and this is for everyone
else."

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.

Possible to set exec.Command Stdout and Stderr to zap?
4 participants