[log] Refactor and measure performance using benchmark #90
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
- will have a design folder next to it, so the doc folder is no longer flat
- basically covered background, what was the goals, good thing about current implementation, bad thing etc.
Codecov Report
@@ Coverage Diff @@
## master #90 +/- ##
==========================================
+ Coverage 48.16% 48.22% +0.06%
==========================================
Files 52 56 +4
Lines 1796 2030 +234
==========================================
+ Hits 865 979 +114
- Misses 847 956 +109
- Partials 84 95 +11
Continue to review full report at Codecov.
|
- get `{"message":"page not found"}`
- just trim the path and keep the first /
- disable server handler check in unix server listen test, it failed CI because when close the server/remove socket file it seems the server didn't shut down gracefully ... https://travis-ci.org/dyweb/gommon/jobs/431772857
- first do benchmark to get a basic understanding of other logging libraries performance and what feature is lacking is gommon so we can modify the interface - then handle fields, structured logging makes log parsing much more easier, and is more generic since parser don't need to know the exact context, i.e. http access log etc. - finally handle the tree of logger problem, along with the skip runtime caller, it's essential for clean logging in testing and util functions
go test -bench=. goos: linux goarch: amd64 pkg: github.com/dyweb/gommon/log/_benchmarks BenchmarkWithoutFieldsJSON/gommon-8 20000000 96.9 ns/op BenchmarkWithoutFieldsJSON/Zap-8 10000000 176 ns/op BenchmarkWithoutFieldsJSON/Zap.Sugar-8 5000000 257 ns/op BenchmarkWithoutFieldsJSON/zerorlog-8 20000000 118 ns/op PASS ok github.com/dyweb/gommon/log/_benchmarks 8.031s
go test -bench=. -benchmem goos: linux goarch: amd64 pkg: github.com/dyweb/gommon/log/_benchmarks BenchmarkWithoutFieldsJSON/gommon-8 10000000 126 ns/op 496 B/op 4 allocs/op BenchmarkWithoutFieldsJSON/Zap-8 10000000 205 ns/op 0 B/op 0 allocs/op BenchmarkWithoutFieldsJSON/Zap.Sugar-8 3000000 353 ns/op 128 B/op 2 allocs/op BenchmarkWithoutFieldsJSON/zerorlog-8 10000000 131 ns/op 0 B/op 0 allocs/op PASS ok github.com/dyweb/gommon/log/_benchmarks 6.617s
- previously make is called inside formatHead so it will allocate on heap for sure, after moving the make to handler and increase the hard coded prefix ... some allocation can be avoided, at least we know the direction for optimization now (either use a pool or use a fixed length make, if it's large enough it can handle most log messages on stack)
BenchmarkWithoutFieldsText/gommon-8 30000000 129 ns/op 272 B/op 3 allocs/op BenchmarkWithoutFieldsText/std-8 10000000 401 ns/op 128 B/op 2 allocs/op BenchmarkWithoutFieldsText/zap-8 20000000 273 ns/op 72 B/op 3 allocs/op BenchmarkWithoutFieldsText/zap.sugar-8 20000000 309 ns/op 200 B/op 5 allocs/op BenchmarkWithoutFieldsText/zerolog-8 3000000 1395 ns/op 2011 B/op 36 allocs/op BenchmarkWithoutFieldsText/apex-8 3000000 1551 ns/op 320 B/op 15 allocs/op BenchmarkWithoutFieldsText/logrus-8 1000000 3209 ns/op 769 B/op 15 allocs/op BenchmarkWithoutFieldsJSON/gommon-8 50000000 79.6 ns/op 288 B/op 3 allocs/op BenchmarkWithoutFieldsJSON/zap-8 20000000 179 ns/op 0 B/op 0 allocs/op BenchmarkWithoutFieldsJSON/zap.sugar-8 20000000 259 ns/op 128 B/op 2 allocs/op BenchmarkWithoutFieldsJSON/zerolog-8 50000000 113 ns/op 0 B/op 0 allocs/op BenchmarkWithoutFieldsJSON/apex-8 2000000 1920 ns/op 512 B/op 10 allocs/op BenchmarkWithoutFieldsJSON/logrus-8 2000000 2990 ns/op 1218 B/op 22 allocs/op
- originally I though it merge the fields when output, but actually when you call logger.With(f1, f2), it encode f1, f2 right away into the underlying, it makes adding context cheap but couple context with the core (similar to handler in gommon/log) so that each core actually has state (handler in gommon/log are stateless, for now), exchange space for time - a drawback of this if a key is used two times, you end up having two fields instead of 1, zerolog has the same problem, and they mentioned in README that json allow duplicated key and json encoding/decoding library will handle it
- when use `interface{}` as parameter, it will cause allocation, I know
it is caued by `interface{}` based on the `16B` size but don't quite get
why it escape ...
- json format with context (logger w/ fields) - logrus and apex are actually entry w/ context where entry hold a pointer to the logger it should use ...
- was planning to change identity to a struct, but since it could be nil and it is not used most of the time, decided to change it back to pointer - [ ] TODO: updated gommon generator template, so all code that use struct logger factory need update
- the 'context` is actually just fields attached to logger - there aren't many tests so we didn't break any test ....
- fan out log in serial
- previously was not using empty value for optional parameters and endup having 6 functions, this made handler implementation error prone due to copy and paste also made handler func impossible - now there is just one log method in Handler call HandleLog
- it has less allocation than `Info` because it accepts string instead of
`interface{}`
- this should makes a gommon/log drop in replacement for some library that requires a standard library like interface `Print` and `Printf` - [ ] TODO: I don't want to add `Println` because `\n` does not make sense for most handlers, json, text w/ fields etc. there will be a `\n` for most most handlers, not after the message but after the fields
- just copy and paste from standard library and remove check on html and jsonp, looked at zap and zerolog, they are basically the same ...
- at first I thought allocate a fixed size on stack would remove the allocation, but I was wrong, because the slice is passed to io.Writer and a call on interface is marked as `parameter to indirect call` and so even a fixed size slice can escape ...
- since we can't avoid the alloc due to call on io.Writer, we just need to make sure to allocate a slice large enough for message and fields so we don't need to allocate during the middle of append - [ ] TODO: these are just magic numbers, which will waste resource/won't work when the size of fields key/value are too small/too big ... - [ ] TODO: no context with fields json still have two alloc ```` BenchmarkWithContextFieldsJSON/gommon-8 30000000 117 ns/op 352 B/op 3 allocs/op BenchmarkWithContextFieldsJSON/gommon.F-8 50000000 74.0 ns/op 224 B/op 1 allocs/op BenchmarkNoContextWithFieldsJSON/gommon.F-8 50000000 92.2 ns/op 352 B/op 2 allocs/op ````
- at first I suspect it's because varadic arg but it seems not ... - could be the `Fields` type
- this happens to zap as well but didn't happen to zerolog because
latter don't have any usage of interface methods when attaching fields
- this only works because zerolog only support json, so it can just
encode things right away and don't need handler interface, the drawback
is for all the other format, it has to decode the bytes into
map[string]interface{} and then print them out ...
This was referenced Nov 26, 2018
Closed
- actually they are alredy there in pretty.go under same package ...
This was referenced Nov 26, 2018
- in v1 we followed logrus and add a filter for filtering log - in v2 we added parent and children but it will cause gc problem
- registry will make the tree explicit, logger has to manually register themselves to registry and registry have to manually register to other registry, short lived logger should not register them self - registry also have identity and is like folder while logger is like file (log structured file system XD) - the map for children logger will be removed in following commit, and generator logic will change as well
- now only registry is used to keep the relationship between loggers across package and projects
- add WalkRegistry - remove deprecated logger_tree logic
- for single message w/ 1 allocation, increased from 60ns -> 236 - remove some outdated doc on log package, most of them are still very outdated though ...
at15
changed the title
This was referenced Dec 9, 2018
Closed
This was referenced Dec 9, 2018
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Trying to fix all those issues https://github.com/dyweb/gommon/issues?q=is%3Aopen+is%3Aissue+label%3Apkg%2Flog
Will first write the doc and list some changes in design, which could be the base of the long pending blog dyweb/blog#28
TODO
Fixed