High CPU consumption on marshalling/unmarshalling ES json requests/responses

[konradgaluszka]

Hi,

during our performance tests we've noticed that there's quite a lot of CPU usage spent on marshalling or unmarshalling jsons to/from ElasticSearch. I would like to know whether there's something wrong with our setup or if that's the issue you also experience.

The output from profiling tool:
https://github.com/konradgaluszka/jaeger-test-results

Test setup:

• 1 kilobyte spans from multiple pods send via jaeger-agent sidecar using GRPC protocol

• The ES setup was more or less the minimum HA in hot-warm configuration (not a real large cluster)
  o 3 x hot node (12 CPU cores, 50Gb RAM)
  o 3 x warm node(12 CPU cores, 50Gb RAM) – you can disregard those since data were not moved between hot and warm during the tests

• Jaeger setup:
  o 2 x collector (7 CPUs, 32Gb memory)
  o 2 x query (1 CPUs, 16Gb memory) – you can disregard Query component since it was not tested during the tests

• Maximum traffic handled was around 100 000 spans per second (100 MB/s) with resources utilization as follows:
  o 60 CPUs / 300GBs RAM for ES; 8 CPUs / 10 GB RAM for Collector

• The setup above is one of a few tests (different span sizes, different number of collectors and ES configuration), we have tuned arguments for Collector as below (where the es.bulk.size and es.bulk.action have the most positive influence on the performance)
  - '--collector.queue-size=8000000'
  - '--collector.num-workers=50'
  - '--es.tags-as-fields.all'
  - '--es.bulk.workers=48'
  - '--es.num-replicas=1'
  - '--es.num-shards=3'
  - '--es.bulk.size=50000000'
  - '--es.bulk.actions=10000'

Questions:
What do you think can be done to improve the performance? Maybe is it possible to change how bulk response (a long list of acknowledgement objects from ES) is processed?

[yurishkuro]

Given that the time seems to go into encoding/json stdlib package, I think the only option is to consider some other json libraries. The std one is reflection based, there maybe better alternatives that use reflection at build time to do code gen. I don't know of any off the top of my head.

If you're interested in contributing an improvement, it would be awesome.

[pavolloffay]

There are many alternative json libraries. However the benchmark results they show are contradicting between each other. Also this blog post shows that some of the libraries might not be more performant than stdlib and the results might depends also on go version https://medium.com/a-journey-with-go/go-is-the-encoding-json-package-really-slow-62b64d54b148. Therefore before going forward we should benchmark candidates on sample data and decide based on that.

Here are some libraries

• https://github.com/francoispqt/gojay, it claims to be the fastest https://www.reddit.com/r/golang/comments/8eznr8/very_fast_json_encoderdecoder_for_go_currently/
• https://github.com/json-iterator/go - the same API as encoding/json
  https://github.com/valyala/fastjson - only parser

[pavolloffay]

I have written and run benchmarks for stdlib, gojay, fastjson, jsoniter using our ES span model.

The repository with results is here https://github.com/pavolloffay/golang-json-benchmark. There is also CI which runs benchmarks (Github actions).

I am copying here results and conclusions:

Conclusions

• Fastjson does not provide a way to unmarshal interface{} in tag map, therefore it should not be considered in results
• stdlib marshalling performance drops (especially allocations increase) when unmarshalling tag map (span.tag/span.process.tag) map[string]interface{}

GOMAXPROCS=1 go test -bench=Marshal -test.benchtime=3s -benchmem -cpuprofile profile_cpu.out ./pkg/jsontest
goos: linux
goarch: amd64
pkg: json-benchmark/pkg/jsontest
BenchmarkMarshalGojay/default.json         	  516730	      6654 ns/op	    4240 B/op	       9 allocs/op
BenchmarkMarshalGojay/default-unicode.json 	  904315	      3617 ns/op	    1808 B/op	       8 allocs/op
BenchmarkMarshalGojay/default-tagmap.json  	  802406	      4899 ns/op	    2607 B/op	       8 allocs/op
BenchmarkMarshalStdlib/default.json        	  558175	      5728 ns/op	    1536 B/op	       1 allocs/op
BenchmarkMarshalStdlib/default-unicode.json         	  768222	      4183 ns/op	    1024 B/op	       1 allocs/op
BenchmarkMarshalStdlib/default-tagmap.json          	  362587	      8962 ns/op	    2752 B/op	      37 allocs/op
BenchmarkMarshalJsoniter/default.json               	  499992	      6932 ns/op	    1800 B/op	       6 allocs/op
BenchmarkMarshalJsoniter/default-unicode.json       	  612794	      5121 ns/op	    1288 B/op	       6 allocs/op
BenchmarkMarshalJsoniter/default-tagmap.json        	  245335	     13910 ns/op	    7930 B/op	      50 allocs/op
GOMAXPROCS=1 go test -bench=Unmarshal -test.benchtime=3s -benchmem -cpuprofile profile_cpu.out ./pkg/jsontest
goos: linux
goarch: amd64
pkg: json-benchmark/pkg/jsontest
BenchmarkUnmarshalFastjson/default.json         	  170601	     21980 ns/op	   29440 B/op	     158 allocs/op
BenchmarkUnmarshalFastjson/default-unicode.json 	  235021	     14834 ns/op	   16160 B/op	     115 allocs/op
BenchmarkUnmarshalFastjson/default-tagmap.json  	  312003	     10821 ns/op	   14416 B/op	      54 allocs/op
BenchmarkUnmarshalGojay/default.json            	  148288	     22983 ns/op	   10159 B/op	      75 allocs/op
BenchmarkUnmarshalGojay/default-unicode.json    	  237422	     14631 ns/op	    6818 B/op	      49 allocs/op
BenchmarkUnmarshalGojay/default-tagmap.json     	  266962	     12868 ns/op	    5377 B/op	      61 allocs/op
BenchmarkUnmarshalStdlib/default.json           	  103725	     32835 ns/op	    1520 B/op	      73 allocs/op
BenchmarkUnmarshalStdlib/default-unicode.json   	  159901	     23717 ns/op	    1136 B/op	      53 allocs/op
BenchmarkUnmarshalStdlib/default-tagmap.json    	  151378	     22602 ns/op	    2192 B/op	      95 allocs/op
BenchmarkUnmarshalJsoninter/default.json        	  417264	      8225 ns/op	    1184 B/op	      76 allocs/op
BenchmarkUnmarshalJsoninter/default-unicode.json         	  518607	      5856 ns/op	     816 B/op	      56 allocs/op
BenchmarkUnmarshalJsoninter/default-tagmap.json          	  480778	      6971 ns/op	    1456 B/op	      85 allocs/op

4 CPUs

GOMAXPROCS=4 go test -bench=Marshal -test.benchtime=3s -benchmem -cpuprofile profile_cpu.out ./pkg/jsontest
goos: linux
goarch: amd64
pkg: json-benchmark/pkg/jsontest
BenchmarkMarshalGojay/default.json-4         	  661621	      4624 ns/op	    4240 B/op	       9 allocs/op
BenchmarkMarshalGojay/default-unicode.json-4 	 1000000	      3157 ns/op	    1808 B/op	       8 allocs/op
BenchmarkMarshalGojay/default-tagmap.json-4  	  868977	      3669 ns/op	    2608 B/op	       8 allocs/op
BenchmarkMarshalStdlib/default.json-4        	  565506	      5802 ns/op	    1536 B/op	       1 allocs/op
BenchmarkMarshalStdlib/default-unicode.json-4         	  800090	      4386 ns/op	    1024 B/op	       1 allocs/op
BenchmarkMarshalStdlib/default-tagmap.json-4          	  415911	      8413 ns/op	    2752 B/op	      37 allocs/op
BenchmarkMarshalJsoniter/default.json-4               	  529898	      6596 ns/op	    1800 B/op	       6 allocs/op
BenchmarkMarshalJsoniter/default-unicode.json-4       	  615393	      4976 ns/op	    1288 B/op	       6 allocs/op
BenchmarkMarshalJsoniter/default-tagmap.json-4        	  345463	     10480 ns/op	    7933 B/op	      50 allocs/op
GOMAXPROCS=4 go test -bench=Unmarshal -test.benchtime=3s -benchmem -cpuprofile profile_cpu.out ./pkg/jsontest
goos: linux
goarch: amd64
pkg: json-benchmark/pkg/jsontest
BenchmarkUnmarshalFastjson/default.json-4         	  161304	     20712 ns/op	   29440 B/op	     158 allocs/op
BenchmarkUnmarshalFastjson/default-unicode.json-4 	  251964	     13733 ns/op	   16160 B/op	     115 allocs/op
BenchmarkUnmarshalFastjson/default-tagmap.json-4  	  332452	      9770 ns/op	   14416 B/op	      54 allocs/op
BenchmarkUnmarshalGojay/default.json-4            	  194344	     18322 ns/op	    9983 B/op	      75 allocs/op
BenchmarkUnmarshalGojay/default-unicode.json-4    	  285207	     11772 ns/op	    6932 B/op	      49 allocs/op
BenchmarkUnmarshalGojay/default-tagmap.json-4     	  287793	     12263 ns/op	    5470 B/op	      61 allocs/op
BenchmarkUnmarshalStdlib/default.json-4           	  123186	     29579 ns/op	    1520 B/op	      73 allocs/op
BenchmarkUnmarshalStdlib/default-unicode.json-4   	  158065	     21486 ns/op	    1136 B/op	      53 allocs/op
BenchmarkUnmarshalStdlib/default-tagmap.json-4    	  146869	     21530 ns/op	    2192 B/op	      95 allocs/op
BenchmarkUnmarshalJsoninter/default.json-4        	  379986	      8116 ns/op	    1184 B/op	      76 allocs/op
BenchmarkUnmarshalJsoninter/default-unicode.json-4         	  571060	      5947 ns/op	     816 B/op	      56 allocs/op
BenchmarkUnmarshalJsoninter/default-tagmap.json-4          	  523004	      6824 ns/op	    1456 B/op	      85 allocs/op

Unmarshalling

• jsoniter is the fastest for unmarshalling, lowest CPU and memory allocations. 1/3 CPU and about the same memory compared to stdlib
• gojay is 1/2 CPU but the memory usage is 2-3 times higher than stdlib

Marshaling

• gojay performs the best for marshalling (span.tag/span.process.tag) map[string]interface{}. It does not increase allocations and CPU also looks stable
• jsoninter is slover than stdlib CPU and memory wise
• gojay might be a bit faster than stdlib but it consumes more memory.

[pavolloffay]

Based on the results above there is no clear winner. Gojay seems to be a bit faster but not dramatically in normal use-case. It only outperforms when using tag map (tags for kibana). The memory wise it is worse than stdlib.

[pavolloffay]

I have reported the issue in encoding/json golang/go#35585 to improve map[string]interface marshaling.