logur icon indicating copy to clipboard operation
logur copied to clipboard

Improve logger performance

Open sagikazarmark opened this issue 5 years ago • 3 comments

Try playing with fields and disabled levels in Zap and Hclog

Original benchmark results
goos: darwin
goarch: amd64
pkg: github.com/goph/logur/benchmarks
BenchmarkDisabledWithoutFields/zap-12     	100000000	        12.9 ns/op	      32 B/op	       2 allocs/op
BenchmarkDisabledWithoutFields/hclog-12   	50000000	        33.1 ns/op	      96 B/op	       3 allocs/op
BenchmarkDisabledWithoutFields/zerolog-12 	20000000	        61.9 ns/op	      96 B/op	       3 allocs/op
BenchmarkDisabledWithoutFields/kitlog-12  	20000000	       113 ns/op	     288 B/op	       8 allocs/op
BenchmarkDisabledWithoutFields/logrus-12  	100000000	        13.9 ns/op	      32 B/op	       2 allocs/op
BenchmarkDisabledAccumulatedContext/logrus-12         	100000000	        13.7 ns/op	      32 B/op	       2 allocs/op
BenchmarkDisabledAccumulatedContext/zap-12            	100000000	        16.0 ns/op	      32 B/op	       2 allocs/op
BenchmarkDisabledAccumulatedContext/hclog-12          	30000000	        39.2 ns/op	      96 B/op	       3 allocs/op
BenchmarkDisabledAccumulatedContext/zerolog-12        	20000000	        75.1 ns/op	      96 B/op	       3 allocs/op
BenchmarkDisabledAccumulatedContext/kitlog-12         	 5000000	       261 ns/op	    1249 B/op	       8 allocs/op
BenchmarkDisabledAddingFields/logrus-12               	 3000000	       487 ns/op	    1580 B/op	      15 allocs/op
BenchmarkDisabledAddingFields/zap-12                  	  300000	      4693 ns/op	    8742 B/op	      73 allocs/op
BenchmarkDisabledAddingFields/hclog-12                	 1000000	      1184 ns/op	    3507 B/op	      40 allocs/op
BenchmarkDisabledAddingFields/zerolog-12              	  300000	      4690 ns/op	    7707 B/op	      58 allocs/op
BenchmarkDisabledAddingFields/kitlog-12               	 2000000	       851 ns/op	    2946 B/op	      32 allocs/op
BenchmarkWithoutFields/zap-12                         	10000000	       207 ns/op	      96 B/op	       3 allocs/op
BenchmarkWithoutFields/hclog-12                       	 2000000	       686 ns/op	     128 B/op	       4 allocs/op
BenchmarkWithoutFields/zerolog-12                     	20000000	        71.1 ns/op	      96 B/op	       3 allocs/op
BenchmarkWithoutFields/kitlog-12                      	 3000000	       538 ns/op	    1058 B/op	      21 allocs/op
BenchmarkWithoutFields/logrus-12                      	  500000	      2936 ns/op	     513 B/op	      14 allocs/op
BenchmarkAccumulatedContext/logrus-12                 	   50000	     27717 ns/op	    4663 B/op	      92 allocs/op
BenchmarkAccumulatedContext/zap-12                    	10000000	       214 ns/op	      96 B/op	       3 allocs/op
BenchmarkAccumulatedContext/hclog-12                  	   50000	     26948 ns/op	    8089 B/op	     123 allocs/op
BenchmarkAccumulatedContext/zerolog-12                	20000000	        78.9 ns/op	      96 B/op	       3 allocs/op
BenchmarkAccumulatedContext/kitlog-12                 	  200000	      6090 ns/op	    6645 B/op	     110 allocs/op
BenchmarkAddingFields/logrus-12                       	   50000	     30147 ns/op	    6245 B/op	     106 allocs/op
BenchmarkAddingFields/zap-12                          	  300000	      5333 ns/op	    9058 B/op	      74 allocs/op
BenchmarkAddingFields/hclog-12                        	   50000	     31727 ns/op	   11503 B/op	     160 allocs/op
BenchmarkAddingFields/zerolog-12                      	  300000	      5021 ns/op	    7707 B/op	      58 allocs/op
BenchmarkAddingFields/kitlog-12                       	  200000	      6988 ns/op	    8374 B/op	     134 allocs/op
PASS
ok  	github.com/goph/logur/benchmarks	50.774s
Benchmark results after single message argument
goos: darwin
goarch: amd64
pkg: github.com/goph/logur/benchmarks
BenchmarkDisabledWithoutFields/logrus-12  	200000000	         6.94 ns/op	      16 B/op	       1 allocs/op
BenchmarkDisabledWithoutFields/zap-12     	200000000	         8.82 ns/op	      16 B/op	       1 allocs/op
BenchmarkDisabledWithoutFields/hclog-12   	2000000000	         1.69 ns/op	       0 B/op	       0 allocs/op
BenchmarkDisabledWithoutFields/zerolog-12 	50000000	        26.1 ns/op	       0 B/op	       0 allocs/op
BenchmarkDisabledWithoutFields/kitlog-12  	20000000	        76.5 ns/op	     192 B/op	       5 allocs/op
BenchmarkDisabledAccumulatedContext/logrus-12         	200000000	         8.26 ns/op	      16 B/op	       1 allocs/op
BenchmarkDisabledAccumulatedContext/zap-12            	100000000	        10.3 ns/op	      16 B/op	       1 allocs/op
BenchmarkDisabledAccumulatedContext/hclog-12          	2000000000	         1.77 ns/op	       0 B/op	       0 allocs/op
BenchmarkDisabledAccumulatedContext/zerolog-12        	50000000	        32.6 ns/op	       0 B/op	       0 allocs/op
BenchmarkDisabledAccumulatedContext/kitlog-12         	 5000000	       236 ns/op	    1152 B/op	       5 allocs/op
BenchmarkDisabledAddingFields/logrus-12               	 3000000	       512 ns/op	    1564 B/op	      14 allocs/op
BenchmarkDisabledAddingFields/zap-12                  	  300000	      5107 ns/op	    8728 B/op	      72 allocs/op
BenchmarkDisabledAddingFields/hclog-12                	 1000000	      1215 ns/op	    3390 B/op	      36 allocs/op
BenchmarkDisabledAddingFields/zerolog-12              	  300000	      4896 ns/op	    7586 B/op	      54 allocs/op
BenchmarkDisabledAddingFields/kitlog-12               	 2000000	       854 ns/op	    2830 B/op	      28 allocs/op
BenchmarkWithoutFields/logrus-12                      	  500000	      2981 ns/op	     497 B/op	      13 allocs/op
BenchmarkWithoutFields/zap-12                         	10000000	       200 ns/op	      80 B/op	       2 allocs/op
BenchmarkWithoutFields/hclog-12                       	 3000000	       507 ns/op	      32 B/op	       1 allocs/op
BenchmarkWithoutFields/zerolog-12                     	100000000	        26.2 ns/op	       0 B/op	       0 allocs/op
BenchmarkWithoutFields/kitlog-12                      	 3000000	       501 ns/op	     961 B/op	      18 allocs/op
BenchmarkAccumulatedContext/kitlog-12                 	  200000	      6371 ns/op	    6534 B/op	     107 allocs/op
BenchmarkAccumulatedContext/logrus-12                 	   50000	     28836 ns/op	    4646 B/op	      91 allocs/op
BenchmarkAccumulatedContext/zap-12                    	10000000	       206 ns/op	      80 B/op	       2 allocs/op
BenchmarkAccumulatedContext/hclog-12                  	   50000	     27934 ns/op	    7993 B/op	     120 allocs/op
BenchmarkAccumulatedContext/zerolog-12                	50000000	        31.1 ns/op	       0 B/op	       0 allocs/op
BenchmarkAddingFields/zerolog-12                      	  300000	      4693 ns/op	    7587 B/op	      54 allocs/op
BenchmarkAddingFields/kitlog-12                       	  200000	      7123 ns/op	    8243 B/op	     130 allocs/op
BenchmarkAddingFields/logrus-12                       	   50000	     31767 ns/op	    6230 B/op	     105 allocs/op
BenchmarkAddingFields/zap-12                          	  300000	      5263 ns/op	    9048 B/op	      73 allocs/op
BenchmarkAddingFields/hclog-12                        	   50000	     32059 ns/op	   11391 B/op	     156 allocs/op
PASS
ok  	github.com/goph/logur/benchmarks	58.244s

sagikazarmark avatar Dec 11 '18 21:12 sagikazarmark

Wondering what's the status on this?

"In a nutshell", what's the significance of the performance impact relative to direct usage of any one the abstracted logger libs (or specifically Zap)? And is the performance impact on resource efficiency or operational latency?

Finally bumped into the same problem where I'm unable to create a one-size-fits-all abstraction for logging. Unfortunately most of our logging will be concentrated in the hot path, so as much as I'd like to use this wrapper lib, if the performance is non-negligible, we'd be forced to completely buy into zap.

gerardmrk avatar Dec 20 '19 23:12 gerardmrk

Most (contextual) logging libraries fall into two categories:

  • Ones that accept context as map[string]interface{}
  • Ones that accept context as variadic ...interface{}

This abstraction uses map[string]interface{} (see the reasons in the readme), so in case of loggers that accept context as variadic (like zap) the context needs to be transformed to that format. This transformation requires extra allocations, so the "performance hit" is totally up to the size of the context.

You can see some benchmark results in the PR description above. It is actually based on the benchmark suite of zap, so you can directly compare the two. You will find that Logur with a Zap adapter is 5-8 times "slower" (when using a large context) than just using Zap, however we are talking about that magnitude in nanoseconds.

Personally I think that this "performance hit" is mostly negligible, especially if your context does not contain a lot of fields, but you should probably make that decision based on the provided benchmarking data and your use case.

I have plans to add a KVLogger interface implementing the variadic key-value style, which should make Zap-like loggers "faster". Then everyone can decide which style they want to use.

Hope that helps. Let me know what you think or if you decide to use/not use Logur.

sagikazarmark avatar Dec 21 '19 21:12 sagikazarmark

Any updates?

isavcic avatar Jan 09 '22 12:01 isavcic