Redis - Why is this code SO fast?

Question

recently I improved some codes using Redis.Eval and it worked great. In fact, this worked too great, but I do not understand how this was possible.

For TL;DR

Improved redis code which used Redis.zcard multiple times to use Redis.eval once. Code got 100+ times faster(on test environment. On real project, it was 1000+ times faster). I don't know why. Can someone please explain this?

What code does

It does a very simple task. It takes an Array of strings, which are keys to ZSET stored in Redis, and sums the size of corresponding ZSETs, and returns one integer value, the sum.

Test Settings

In order to eliminate as many as outer variables possible, I set up a simple testing environment like below.

redis = Redis.new(host: '127.0.0.1', db: 1)
KEYS = 500.times.collect do |i| "KEY#{i}" end
KEYS.each do |key|
  redis.zadd(key, 0, "DATA")
end  

Before improvement

Before I changed the code, it worked like below.

sum = 0
KEYS.each do |key|
  sum += redis.zcard(key)
end

Then I tested the speed of this code using following one-line code.
t = Time.now; sum=0; KEYS.each do |key| sum += redis.zcard(key) end; puts(Time.now - t)
Which in result printed out 0.202seconds(202ms)
(please note that I calculated the time based on testing environment and the code written above, not on real environment)

After improvement

After I changed the code using Lua script and EVAL, it worked like below.

script = " 
local sum = 0
for index, key in pairs(KEYS) do
  sum = sum + redis.call('zcard', key);
end
return sum"
sum = redis.eval(script, KEYS)

Then, I also measured the time taken to execute the above code, using following one-line code.
t = Time.now; redis.eval(script, KEYS); puts(Time.now - t)
Which gave me 0.001519seconds(1.5ms). This is 134 times faster than the "before improvement" code.

The Confusion

What made me even confusing was that one redis.zcard(KEYS[0]) takes about 0.000542seconds(0.542ms). So the redis.eval code to sum 500 ZCARD in redis took about the same time to calculate 3 Redis.ZCARD in ruby.

When I first found this on my project, I thought that reduction in network delay, and reduction in wait-in-queue time did the work. However, when I tested this on local redis, I doubted my theory. There is no network delay at all, and no other task is using the Redis.

My theories are

1. Ruby summation(sum += redis.zcard(key)) takes most of the time.
2. Even though I'm using local host, there is some kind of delay between redis and ruby communication.
3. There is internal delay in redis when processing many queries. (not very likely though)

Can anyone please explain to me why this Redis.eval code is very fast? Thanks!

Answer 1

This happens due to lag, based on write/read to/from socket

20% - write command to socket

80% - read result from socket

require 'benchmark'
require 'redis'

redis = Redis.new(host: '127.0.0.1', db: 1)
KEYS = 10_000.times.collect { |i| "KEY#{i}" }
KEYS.each { |key| redis.zadd(key, 0, 'DATA') }

script = " 
local sum = 0
for index, key in pairs(KEYS) do
  sum = sum + redis.call('zcard', key);
end
return sum"

Benchmark.bm do |x|
  x.report { puts KEYS.inject(0) { |sum, key| sum + redis.zcard(key) } }
  x.report do
    client = redis.client
    client.send(:ensure_connected) do
      KEYS.inject(0) { |sum, key| sum + client.process([[:zcard, key]]) { client.read } }
    end.tap { |res| puts res}
  end
  x.report do
    client = redis.client
    client.send(:ensure_connected) do
      connection = client.connection
      socket = connection.instance_variable_get(:@sock)
      KEYS.map do |key|
        command = connection.build_command([:zcard, key])
        # Redis::Connection::Ruby
        socket.write(command) # write to socket, 20% of execution time
        line = socket.gets # read from socket, 80% of execution time
        reply_type = line.slice!(0, 1)
        connection.format_reply(reply_type, line)
      end.inject(:+)
    end.tap { |res| puts res}
  end
  x.report { puts redis.eval(script, KEYS) }
end

# user     system      total        real
# 10000
# 0.480000   0.230000   0.710000 (  0.966610)
# 10000
# 0.510000   0.250000   0.760000 (  1.132668)
# 10000
# 0.500000   0.270000   0.770000 (  1.193521)
# 10000
# 0.030000   0.000000   0.030000 (  0.054858)
# [Finished in 4.923s]

So probably the script, executing in redis, because of transport delays.