ezmobius/redis-rb — Issue #181: Slowness on random commands
Author: jonhyman
Created: 2012-02-22 20:34:52+00:00
State: open

Has anyone run into random slowness using the Redis gem? Once in awhile some of the commands take a very long time to run. Here's my setup:

* redis-rb latest master
* I have a global `$redis` connection object
* Web server is Unicorn on a medium high-CPU EC2 machine.
* In my `unicorn.rb`, I have an `after_fork` block which calls `$redis.client.disconnect(); $redis = Redis.new(...)`
* Redis server is on small EC2 instance

I created a logging decorator for my `$redis` object and here are some examples of output:

> **Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#incr took 0.846048 seconds**
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#zincrby took 0.001869 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#set took 0.00174 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#set took 0.014876 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#expire took 0.001912 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#zadd took 0.002401 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#zremrangebyscore took 0.001966 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#sadd took 0.002223 seconds
> Feb 22 10:43:12 ip-10-244-233-167 API_Staging[3535]: Redis#rpush took 0.001802 seconds
> **Feb 22 12:04:00 ip-10-244-233-167 API_Staging[10499]: Redis#set took 2.01812 seconds**
> Feb 22 12:04:00 ip-10-244-233-167 API_Staging[10499]: Redis#expire took 0.001568 seconds
> Feb 22 12:04:00 ip-10-244-233-167 API_Staging[10499]: Redis#zadd took 0.001461 seconds
> Feb 22 12:04:00 ip-10-244-233-167 API_Staging[10499]: Redis#zremrangebyscore took 0.001422 seconds
> Feb 22 12:04:00 ip-10-244-233-167 API_Staging[10499]: Redis#sadd took 0.001413 seconds
> Feb 22 12:04:00 ip-10-244-233-167 API_Staging[10499]: Redis#rpush took 0.001591 seconds
> **Feb 22 12:04:02 ip-10-244-233-167 API_Staging[10499]: Redis#lrange took 2.025997 seconds**

As you can see, most commands are incredibly fast. But every now and then, something takes a very long time. Even O(1) commands! Using SLOWLOG, I can't even find these commands. System agent monitoring on my Redis server shows plenty of RAM and a load average of 0.01, with barely any CPU spikes. (I don't have a lot of traffic in staging, but I see this in production as well).

I've also run `redis-cli --latency` from my web server to my Redis server and everything is in the tens of millseconds or less.

Any ideas on what could be causing this? Has anyone else experienced or debugged slowness? My guess is that it's a network problem, but I'm not sure how to troubleshoot that.