occasional slow response

[gingerlime]

I'm trying to investigate some strange behaviour, when occasionally requests to redis seem to take very long, even with the same request. We started to observe this using ohm, and I already posted a question about it there.

I tried to avoid any extra layers so was running a quick benchmark using only redis.rb but still something feels a little strange. Most requests are completed within a very short timeframe (probably less than 0.3ms), but some requests take what seems like an order of magnitude longer. I observed this both when connecting over tcp and unix sockets, but with tcp it is much more pronounced. Both the gap between short and longer requests seem larger, but also the number of occurances.

In this quick'n'dirty benchmark I'm running 10000 pings and measure the execution time. If it's slower than 1ms, I print it out.

The machine is not doing much else, and we've observed this on other machines.

If I reduce the threshold down to around 0.5ms it still appears more or less the same, i.e. around 99.999% of the requests are really fast, but a very small fraction takes hugely longer.

The redis slowlog does not show any requests taking longer than 19 microseconds (0.019ms).

Any reason why this might happen? What could be the cause of this, or is there a way to fix it somehow?

[1] pry(main)> require 'rubygems'                                                                                                                                                                                                              
=> false
[2] pry(main)> require 'redis'
=> true
[3] pry(main)> redis_tcp = Redis.new                                                                                                                                                                                                           
=> #<Redis client v3.0.2 for redis://127.0.0.1:6379/0>
[4] pry(main)> redis_sock = Redis.new(:path => "/tmp/redis.sock")
=> #<Redis client v3.0.2 for redis:///tmp/redis.sock/0>
[5] pry(main)> require 'benchmark'                                                                                                                                                                                                             
=> true
[8] pry(main)> (1..10000).each { x = (Benchmark.measure { redis_tcp.ping }.real * 1000); puts x if x>1 }                                                                                                                                       
1.0859966278076172
15.413761138916016
9.968280792236328
17.358064651489258
9.308338165283203
19.347190856933594
10.436534881591797
16.648530960083008
18.29051971435547
11.01994514465332
16.663074493408203
10.289192199707031
18.82338523864746
10.233402252197266
18.0819034576416
10.293722152709961
16.989707946777344
16.74628257751465
11.02137565612793
18.3870792388916
9.713172912597656
18.86296272277832
10.99538803100586
21.112918853759766
10.663270950317383
18.846511840820312
9.303569793701172
18.17607879638672
11.545181274414062
17.992496490478516
10.821104049682617
16.9985294342041
9.186983108520508
17.48514175415039
20.769119262695312
10.525226593017578
18.34559440612793
9.228944778442383
16.63994789123535
11.941909790039062
20.30038833618164
=> 1..10000
[9] pry(main)> (1..10000).each { x = (Benchmark.measure { redis_sock.ping }.real * 1000); puts x if x>1 }                                                                                                                                      
11.031389236450195
14.653682708740234
10.750293731689453

[pietern]

There are many things sitting between the Ruby code you execute, the request executing on the Redis-side, and the response being return to the Ruby code. For starters, there is Ruby's I/O stack that can cause latency. Then, there's the operating system that can cause latency, for example because of process scheduling.

To remove Ruby's I/O stack from the equation, I ran your test using the hiredis connection driver and got a lot less >1ms latency samples. The handful of samples that exceeded 1ms were not higher than 5ms.

There are too many variables that influence the latency to make a call where it comes from. The important thing is that the vast majority is not impacted, and that there is only a very small set of outliers.

Closing, because this is not an issue with redis-rb, but rather an artifact of the runtime and operating system.

[gingerlime]

Thanks for looking into this @pietern .

Would have to look into hiredis (still new to the whole thing), although I'm not sure if ohm does not already use this.

I was curious enough to check if it is somehow connected to the operating system, and so I did a similar quick test using redis-py. I don't get the same number of outliers, and not with the same 'intensity' either it seems.

With the unix sockets, It was hard to find any request taking longer than 0.5ms, with tcp a little easier, but still much faster and much fewer of those compare to the ruby version.

Here's a quick dump from ipython:

In [1]: import timeit

In [2]: setup_stmt = "import redis; r = redis.Redis(unix_socket_path='/tmp/redis.sock', db=0)"

In [3]: for i in range(0, 10000):
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 1:
        print t
   ...: 

In [4]: setup_stmt = "import redis; r = redis.Redis(host='localhost', port=6379, db=0)"       

In [5]: for i in range(0, 10000):                                                      
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 1:
        print t
   ...: 
1.36184692383
1.26194953918
1.03306770325

In [6]: setup_stmt = "import redis; r = redis.Redis(host='localhost', port=6379, db=0)"

In [7]: for i in range(0, 10000):                                                      
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 1:
        print t
   ...: 
1.02806091309
1.17206573486

In [8]: setup_stmt = "import redis; r = redis.Redis(unix_socket_path='/tmp/redis.sock', db=0)"

In [9]: for i in range(0, 10000):                                                             
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 1:
        print t
   ...: 

In [10]: for i in range(0, 10000):
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 0.8:                                                                                                                                                 
        print t
   ....: 

In [11]: for i in range(0, 10000):
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 0.6:                                                                                                                                                 
        print t
   ....: 

In [12]: for i in range(0, 10000):
    t = timeit.timeit('r.ping()', setup=setup_stmt, number=1)*1000
    if t > 0.5:                                                                                                                                                 
        print t
   ....: 
0.537157058716

[gingerlime]

Another update, in case this helps anybody with a similar problem, we think we might have found the cause for this problem, and even a solution

TL;DR : use hiredis + tune the ruby GC parameters.

Thanks again for your help @pietern