Performance Issues
Closed this issue · 4 comments
Hi! I'm pretty excited about honeycomb, but when we enabled it in our production environment, things completely melted. The general response times saw about a 2x increase.
I'm not sure I can diagnose why, but I can offer up some trivial benchmarking script and observations. Caveat -- these benchmarks are all running on my laptop, amidst other load. So, they're not the cleanest, but I think they're representational.
This was tested using version 1.3.0 of the honeycomb-beeline gem.
We do a lot with redis, so I looked at that first. redis-benchmarks.rb.zip is a simple ruby benchmark: sets a redis key, fetches it. deletes it.
I tried to test before requiring the gem, as well as after. The results are quite striking:
$ ruby honeycomb-benchmark/redis-benchmarks.rb
user system total real
plain redis: 1.256574 0.678867 1.935441 ( 10.317208)
hc required: 2.250149 0.894142 3.144291 ( 11.889222)
hc test client: 3.886355 1.214431 5.100786 ( 14.816577)
hc prod client: 5.055561 1.813043 6.868604 ( 16.607927)
$ ruby honeycomb-benchmark/redis-benchmarks.rb
user system total real
plain redis: 1.222948 0.642554 1.865502 ( 9.676573)
hc required: 2.162630 0.863228 3.025858 ( 11.181562)
hc test client: 3.727364 1.188236 4.915600 ( 13.488173)
hc prod client: 4.186184 1.621694 5.807878 ( 13.593950)
Next I tried a simple ActiveRecord find_by_id. activerecord-benchmarks.rb.zip
The results are less striking, but there does seem to be some performance impact.
$ ./honeycomb-benchmark/activerecord-benchmarks.rb
Running via Spring preloader in process 53923
user system total real
plain rails: 11.373044 0.670841 12.043885 ( 28.358484)
hc required: 11.158517 0.611581 11.770098 ( 27.193382)
hc test client: 13.674453 1.366414 15.040867 ( 32.382548)
hc prod client: 16.315415 2.602464 18.917879 ( 35.991214)
$ ./honeycomb-benchmark/activerecord-benchmarks.rb
Running via Spring preloader in process 53984
user system total real
plain rails: 12.021877 0.714252 12.736129 ( 30.415849)
hc required: 11.479381 0.681627 12.161008 ( 28.321843)
hc test client: 15.053928 1.512480 16.566408 ( 37.148174)
hc prod client: 16.336843 2.610865 18.947708 ( 36.275914)
Lastly, a simple test of start_span. span-test.rb.zip
These numbers have a big jump
$ ./honeycomb-benchmark/span-test.rb
user system total real
plain methods: 0.000476 0.000002 0.000478 ( 0.000475)
hc required: 0.000783 0.000137 0.000920 ( 0.000918)
hc test client: 0.263569 0.125435 0.389004 ( 0.391431)
hc prod client: 0.268705 0.115751 0.384456 ( 0.385942)
$ ./honeycomb-benchmark/span-test.rb
user system total real
plain methods: 0.000758 0.000020 0.000778 ( 0.001048)
hc required: 0.000926 0.000193 0.001119 ( 0.001116)
hc test client: 0.247749 0.115868 0.363617 ( 0.366042)
hc prod client: 0.281443 0.120039 0.401482 ( 0.402623)
I'm not really sure where to go from here. I recognize these benchmarks may be including bad data, but they seem about like what pushing this to production felt like.
Having slept on it, I think there's an absolute values part that matters. Though the span test is a huge percentage increase, it ultimately represents a very small amount of additional time.
The redis one, on the other hand, is much more significant.
The active record one feels pretty minor. 2s on 10,000 requests shouldn't hurt much
Thank you so much @directionless for building these benchmarks and documenting what you were seeing!
I just repro'd on my Ubuntu 19.10 dev box (i5-8400 CPU @ 2.80GHz) using the stock Ruby (2.5.5), confirmed the system was idle at the time:
# spin up a redis 5 instance in docker:
$ docker run --name redis-benchmark --rm -p 6379:6379 -d redis
# run1:
$ bundle exec bin/redis-benchmarks.rb
user system total real
plain redis: 0.771792 0.243165 1.014957 ( 1.465325)
hc required: 0.503528 0.134255 0.637783 ( 0.834873)
hc test client: 1.272352 0.182356 1.454708 ( 1.761655)
hc prod client: 3.029869 0.723596 3.753465 ( 3.410702)
# run2:
$ bundle exec bin/redis-benchmarks.rb
user system total real
plain redis: 0.680019 0.182846 0.862865 ( 1.192515)
hc required: 0.481824 0.169231 0.651055 ( 0.857399)
hc test client: 1.292129 0.145744 1.437873 ( 1.732268)
hc prod client: 2.727334 0.619321 3.346655 ( 3.052735)
wacky that hc required is somehow faster than plain redis - I suspect this was due to some combination of the CPU clocking up and maybe establishing the redis connection pool
Thanks for verifying this! It's great to hear it seems like a broader issue.
Across my various benchmarks, I also saw the same performance increase for the second test case. I didn't much dig into it, I don't think it invalidates the bigger picture of it.
Poking around the integrations, I sorta have several wishes. (And I'm happy to PR them, they are at least partly monkey patches in my environment)
- integrations should probably not default to all enabled. Even best case there are performance implications, and in some cases, privacy implications (#55)
- I could not figure out how to disable the redis integration. I see an attr_writer, but I can't get it to work.
- Performance benchmarks, maybe as part of rspec.
Testing some more, the simplest way I found to disable the redis integration is:
ENV["HONEYCOMB_INTEGRATIONS"] = [
"active_support",
"aws",
"faraday",
"rack",
"rails",
"railtie",
"rake",
# "redis",
"sequel",
"sinatra",
].join(",")
require 'honeycomb-beeline'
Oddly, even just a require 'rack' seems to make a difference in Benchmark here. (no honeycomb)