Binary format support #37
Conversation
|
Will resolve conflicts in a day or two - need to understand how the hooks work. |
|
All the "if binary then cbor else json" everywhere is to avoid using an interface and leave a chance for the compiler to inline those calls? It make the code hard to maintain, we should find a better solution. |
|
I went back and forth trying to decide about it - if we decide to use the interface, go will have to alloc memory for the arguments - since it is not known where the interface will point to. I kept the signatures of json and cbor apis very similar so that if we want to do interface, can be done. I didn't find any other way - but i will post of go forum asking for alternatives. |
|
Here is another approach: a6bc163 The runtime cost is lighter than condition and the code is simpler. The downside is that you need to use build tag to enable binary (e.g.: |
|
That is one option. My idea was that user will switch ON binary logging when deploying the code in production – aka some sort of a runtime knob.
I’ve posted on go forum - https://forum.golangbridge.org/t/two-providers-one-caller/8118 - lets see if there are other ways other than interfaces.
|
|
Most people would have a separate build for production. So the tag approach would work. |
|
Sure Olivier, will add the build tag.
|
|
one final thing i am still debugging - allocs/op for ArrayObj is non-zero ... |
|
@rs - the code is ready for merge - fixed the last issue. Here's the benchmark results - highlighting the difference. https://docs.google.com/spreadsheets/d/1SDFzgPKkkF1xckoNh-5RlCH1XRvgrKX_r-co3u_Bupo/edit?usp=sharing There are two sheets:
Three things i will work on next:
Thx |
array.go
Outdated
| @@ -16,7 +14,7 @@ var arrayPool = &sync.Pool{ | |||
| } | |||
|
|
|||
| type Array struct { | |||
| buf []byte | |||
| buf []byte | |||
There was a problem hiding this comment.
oops.. will run gofmt and update the code.
hook_test.go
Outdated
| @@ -1,3 +1,5 @@ | |||
| // +build !enable_binary_log | |||
There was a problem hiding this comment.
hooks does work. these tests compare the output with a json string. So duplicated few of the testcases into binary_tests.go and there i convert binary to json and compare with the output.
other thought i had was to clone each _test.go into a _binary_test.go and do the exact same tests.. but then i decided it will be too many _test.go files - so i went with one binary_tests.go with all binary related tests (hooks, ctxt..)
There was a problem hiding this comment.
What about wrapping the wanted output into a noop method in json mode that convert the json into cbor in binary mode?
ctx_test.go
Outdated
| @@ -1,3 +1,5 @@ | |||
| // +build !enable_binary_log | |||
There was a problem hiding this comment.
see above comment for hook_test.go
There was a problem hiding this comment.
done - enabled this test for binary as well.
internal/json/types.go
Outdated
| return append(dst, '{') | ||
| } | ||
|
|
||
| func AppendEndMarker(dst []byte, terminal bool) []byte { |
There was a problem hiding this comment.
Why don't you extract the "terminal = true" in it's own AppendLineBreak instead of adding a branch to all end markers?
There was a problem hiding this comment.
good idea. will introduce appendLineBreak..
internal/json/types.go
Outdated
|
|
||
| func AppendObjectData(dst []byte, o []byte) []byte { | ||
| if o[0] == '{' { | ||
| o[0] = ',' |
There was a problem hiding this comment.
Can you please add a comment explaining why you have to do that?
log.go
Outdated
|
|
||
| //DecodeIfBinaryToString - converts a binary formatted log msg to a | ||
| //JSON formatted String Log message - suitable for printing to Console/Syslog etc | ||
| func DecodeIfBinaryToString(in []byte) string { |
There was a problem hiding this comment.
I think zerolog needs to provide decode method apis. Since CBOR package is internal to zerolog, i thought zerolog can provide one.
There was a problem hiding this comment.
If we provide a decoder, to be useful it should take a reader and write into a struct instead converting to json. It would be thus better to expose the cbor package.
I don’t think it is the role of a log lib to do that. If there is not cbor lib available to decode cbor, let’s expose the cbor lib as a separate project.
There was a problem hiding this comment.
good point. no longer expose this api.
syslog.go
Outdated
| @@ -26,11 +28,13 @@ func SyslogLevelWriter(w SyslogWriter) LevelWriter { | |||
| } | |||
|
|
|||
| func (sw syslogWriter) Write(p []byte) (n int, err error) { | |||
| p = DecodeIfBinaryToBytes(p, true) | |||
There was a problem hiding this comment.
I'm not sure it is relevant to do that. What is the point to enable binary logging if the writer silently converts it back to JSON?
There was a problem hiding this comment.
This and console are writing to text destinations (syslog/console), outputing binary is not good - so i thought decoding is needed. in case of writing to these text destinations, we cannot delay the decoding of the binary to json. when writing to file or stream etc we can run a decoder.
An alternative for this is users run another process that takes these logs and decodes it and prints to console/syslog...
There was a problem hiding this comment.
I get it for console. For syslog we should not implement it in binary mode as it does not make sense.
There was a problem hiding this comment.
excluded syslog and hlog from binary support.
json_encoder.go
Outdated
| @@ -0,0 +1,184 @@ | |||
| // +build !enable_binary_log | |||
|
|
|||
There was a problem hiding this comment.
I would have named the two encoders encoder_json.go and encoder_cbor.go so they stay grouped together.
There was a problem hiding this comment.
i can rename the files to encoder_json, encoder_cbor.
|
Do you know why some of the JSON parts are so much worse perf-wize after the change? |
|
will investigate a bit more on the reason for cpu increase |
|
@rs - i've updated the same google doc with the new performance numbers. There is a little bit of variation of the ns/op numbers between each run (i've noticed variation of +/- 40ns on my machine) for the same test in the same codebase. For the one case "LogArrayObject" case the difference is about 200ns - i did a bunch of trials with various code combinations and found that the overhead of function calls adds up to it and ArrayObject lots of such function calls (as compared to other benchmarks). These functions are not leaf functions, so they are not getting inlined. The variation in calculation (+/- 40ns) explains the cases where the cpu usage is lower in spite of the extra function call introduced by this code change. To provide more details - a single call to (Array )Object() involves: I am going to move most of the single line functions from json Package to encoder_json.go (same for cbor). |
|
Moved some of the simple functions from json pkg to encoder_json - helped cut the cpu usage for json encoding. |
diode/diode_test.go
Outdated
| log := zerolog.New(w) | ||
| log.Print("test") | ||
|
|
||
| w.Close() | ||
| fmt.Println(cbor.DecodeIfBinaryToString(buf.Bytes())) |
There was a problem hiding this comment.
I have three options with tests:
- Disable them for binary (since the tests compare the output with text output).
- Decode if binary and let the comparison with text output continue..
- Go with Option 1 - but create another file which does the same test for binary
I chose 2nd option.
There was a problem hiding this comment.
A cleaner approach occurred to me:
Since examples show up in documentation, i made it just text - so doc looks clean
Same examples, i made sure that there were tests that tested both ascii and binary - so i split diode_test.go to diode_example_test.go (text only) / diode_test.go (text and binary).
hlog/hlog.go
Outdated
| @@ -1,3 +1,5 @@ | |||
| // +build !enable_binary_log | |||
There was a problem hiding this comment.
I made a judgement call that http logger will not want binary encoding - just like how syslog and binary log doesn't go together. Do you think otherwise ?
There was a problem hiding this comment.
HTTP handlers are just tools to add context to the logs. The format of the output does not matter.
There was a problem hiding this comment.
my bad. i didn't read hlog in detail... Will read thru and make necessary changes in a few days..
There was a problem hiding this comment.
Enabled hlog_test.go for binary test too. hlog_example_test.go - i left it just text.
|
Bench with current master in JSON mode: |
|
i am struggling a bit to nail down the cause of the cpu increase. For instance Bools is the same where as Bool is very different. Also i ran it on a linux machine and got a slightly different result: I am trying a eliminate parts of the code and trying to figure out what is causing this.. if you do have some inputs, would be appreciated. I've read most of the blogs/write ups about pprof etc - still not able to get narrow it quickly.. |
|
I'm not sure to understand why either. |
context.go
Outdated
| c.l.context = json.AppendError(json.AppendKey(c.l.context, ErrorFieldName), err) | ||
| } | ||
| return c | ||
| return c.AnErr(ErrorFieldName, err) |
There was a problem hiding this comment.
Err is used more than AnErr. I would prefer not to add a func call here.
encoder_cbor.go
Outdated
|
|
||
| func appendObjectData(dst []byte, src []byte) []byte { | ||
| //we keep the map begin Character in context - we | ||
| //don't need to copy that - so skip first char |
There was a problem hiding this comment.
Can you add space after // and use cap/period for comments please?
| case time.Duration: | ||
| dst = json.AppendDuration(dst, val, DurationFieldUnit, DurationFieldInteger) | ||
| dst = appendDuration(dst, val, DurationFieldUnit, DurationFieldInteger) |
There was a problem hiding this comment.
Please merge last change that append pointers support.
internal/cbor/README.MD
Outdated
| @@ -0,0 +1,74 @@ | |||
| Reference: | |||
|
@rs - builds on travis hits a spurious error - which i am not able to recreate on my end - https://travis-ci.org/rs/zerolog/builds/358665413 i tried to on my mac, linux and a docker with go1.10 and ran 50+ times, still cannot reproduce it.. not sure what would be causing this. Sometimes the same test passes on travis (like https://travis-ci.org/rs/zerolog/builds/358670909).. just letting you know.. |
|
Awesome work @toravir, thanks a lot! |
|
One last request before change. Instead of |
|
Yes @rs 'binary_log' is clear, simple and neat tag name. Pushed the changes. appreciate all your feedback. |
.travis.yml
Outdated
| @@ -9,4 +9,5 @@ matrix: | |||
| allow_failures: | |||
| - go: "master" | |||
| script: | |||
| go test -v -race -cpu=1,2,4 -bench . -benchmem ./... | |||
| - go test -v -race -cpu=1,2,4 -bench . -benchmem ./... | |||
| - go test -v -tags enable_binary_log -race -cpu=1,2,4 -bench . -benchmem ./... | |||
There was a problem hiding this comment.
oops yeah. fixed it.
Submitting the PR for #21 with two minor things in the todo items:
Changes to documentation (README.md)
Because after code review, will write the docs.
When doing reflection, skip using JSON and write a binary based encoder
Writing an equivalent of json.Marshal() would take more time and careful testing.