-
Notifications
You must be signed in to change notification settings - Fork 1.4k
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
Add zapio.Writer #971
Conversation
Codecov Report
@@ 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
Continue to review full report at Codecov.
|
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
Outdated
// Split on the newline, buffer and flush the left. | ||
line, remaining = line[:idx], line[idx+1:] | ||
w.buff.Write(line) |
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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 { |
There was a problem hiding this comment.
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
?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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 |
There was a problem hiding this comment.
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?
return len(bs), nil | |
return 0, nil |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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:] |
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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)
.
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) ```
There was a problem hiding this 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
}) | ||
} | ||
} | ||
|
There was a problem hiding this comment.
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
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ack
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.
That's a good point, except we'll end up with a cycle between zap and Another way we can break the zapio->zap dependency by making the So short of moving it to the zap package, we might have to live with |
This adds a new zapio package that provides a
Writer
. The writerimplements
io.WriteCloser
andzapcore.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:
Resolves #929