Timing Queries in Redis-Cli?

Question

This seems like it ought to be trivial, but I want to run a query through redis-cli, and then just get back how long it took on the server, along with the results. This is just for debugging purposes, to factor out problems with my client library or latency. Is there a way to do this?

Answer 1

You can set the Slow Log to 0 (zero). Doing so will log every command.

The time you will see is in microseconds, and from the documentation this time means:

The execution time does not include the I/O operations like talking with the client, sending the reply and so forth, but just the time needed to actually execute the command (this is the only stage of command execution where the thread is blocked and can not serve other requests in the meantime)

To factor in the network performance you might have to hack your client library, logging just before and after the communication with redis, leaving out any tranformation your library may do.

Answer 2

You can do this by wrapping the redis command you're investigating in a MULTI/EXEC block, where the TIME command is used right before and right after your command. For example:

Using the node library:

var multi = redis.multi();
multi.time(); // start time
multi.sunionstore(['fast_food_joints', 'pizza_hut', 'taco_bell']); // this is the command I'm investigating
multi.time(); // end time
multi.exec(function(err, responses){
    var response = responses[1]; // the response i care about
    var start = (parseInt(responses[0][0]) * 1000) + (parseInt(responses[0][1]) / 1000);
    var end   = (parseInt(responses[2][0]) * 1000) + (parseInt(responses[2][1]) / 1000);            
    var execution_time = end - start; // in milliseconds
});

Or... using the command line (which is what you asked for in your question):

192.168.1.1:6379> MULTI
OK
192.168.1.1:6379> TIME
QUEUED
192.168.1.1:6379> SUNIONSTORE fast_food_joints pizza_hut taco_bell
QUEUED
192.168.1.1:6379> TIME
QUEUED
192.168.1.1:6379> EXEC
1) 1) "1450818240"
   2) "666636"
2) (integer) 48886
3) 1) "1450818240"
   2) "666639"

And then do the math yourself. The above example took 3 microseconds.