firstResponseLatency is always negative

[nickvollmar]

First: Thank you for creating/maintaining this library! It's been very useful to me and my colleagues.

Lettuce version: 4.4.2.Final (though the issue appears to exist in current master as well)

Steps to reproduce: https://gist.github.com/nickvollmar/a833681149fa27560b190799c02f6699

While playing with the metrics feature, I notice the firstResponse metrics never seem to change. The reported statistics are always the following:

firstResponse=[min=0, max=1, percentiles={50.0=1, 90.0=1, 95.0=1, 99.0=1, 99.9=1}]

This appears to be due to the following line in com.lambdaworks.redis.protocol.CommandHandler:

long firstResponseLatency = withLatency.getSent() - withLatency.getFirstResponse();

My understanding is that "sent" must be strictly before "firstResponse", because Redis cannot respond to a command that has not been sent. Therefore firstResponseLatency will always be less than zero, and DefaultCommandLatencyCollector.rangify() will always truncate the firstResponse value to MIN_LATENCY (1000 microseconds = 1 nanosecond, which is what we observe in the percentiles above).

A quick fix is to swap the order of the terms: long firstResponseLatency = withLatency.getFirstResponse() - withLatency.getSent(). I will make a PR with this change.

[nickvollmar]

Created PR #741.

And thanks again for maintaining Lettuce!!

[mp911de]

Good catch, you're right, a command must be sent before it can receive a response. Thanks for your pull request, going to take a look.