About Redis latency

I’m checking out my logs and saw that the latency between my app and Redis is about 70-80ms.

Are these expected numbers?

That is too high.

What region(s) is your app running in?

dfw Dallas 2, Texas (US)

Just to be sure, you’re sending commands to Redis database 0 when you see high latency?

I wasn’t selecting a database and the Node driver uses 0 by default.

I explicitly set 0 just to make sure but I’m getting similar latencies.

redis.createClient({
  url: process.env.FLY_REDIS_CACHE_URL,
  db: 0
},

Edit:

The lowest latency I’ve seen in the logs is 20ms, but it’s usually 30-80ms.

2020-08-11T15:44:06.713Z c0fb95d4 dfw [info] REDIS LATENCY 33
2020-08-11T15:46:35.780Z c0fb95d4 dfw [info] REDIS LATENCY 60
2020-08-11T15:46:36.582Z c0fb95d4 dfw [info] REDIS LATENCY 32
2020-08-11T15:46:37.567Z c0fb95d4 dfw [info] REDIS LATENCY 51
2020-08-11T15:46:46.132Z c0fb95d4 dfw [info] REDIS LATENCY 77
2020-08-11T15:46:46.973Z c0fb95d4 dfw [info] REDIS LATENCY 59
2020-08-11T15:50:56.361Z c0fb95d4 dfw [info] REDIS LATENCY 51
2020-08-11T15:50:57.135Z c0fb95d4 dfw [info] REDIS LATENCY 72
2020-08-11T15:50:58.149Z c0fb95d4 dfw [info] REDIS LATENCY 95
etc

Are you pooling your connections?

I just ran a quick latency check from an instance in dfw and got the following:

/ # redis-cli --latency -h 77.83.141.196 -p 10079
min: 4, max: 18, avg: 5.88 (1028 samples)

The average here seems pretty ok.

If you’re not pooling, then you might be connecting + issuing a AUTH command frequently, which can take a while.

1 Like

@jerome I have a single Node Redis client in this app. Not sure if it uses polling under the hood, I don’t see any options in their docs. It seems to reconnect every couple of minutes or so.

BTW those numbers you showed are the read latencies of the Redis instance itself, right? Would that take into account network latency between Redis and the app container?

This was latency measured from within a container (virtual machine), connecting to our redis IP (outside the container). It should be the same as connecting from your app since this is our “debug” app that runs the same as any app from our users.

This instance of our debug app was also on a different server than the one where the closest redis instance lives. Meaning it had to go through extra layers to get to it.

So you’re getting 5ms on average? :open_mouth:

Then yeah something is definitely wrong with my setup. I will create a very simple repro to see if I can pinpoint the problem.

Pooling, rather than polling. Redis connections are strange; couple of questions for you, are you using any blocking redis calls like BRPOP, BLPOP and so on. They will block the connection and only free up when something has released the block on that connection (which can show as a long execution time of the call or other calls).

Will look at your repro when you have it.

Oh yeah I meant pooling (sorry non native speaker here).

I have no idea what those are, so I’m guessing no :slight_smile:

Here’s the repro: https://github.com/PierBover/fly-redis-node-test

Whenever it connects to Redis it reads a key 50 times and prints the latency. This is the relevant code.

I deployed it to Fly and I saw the following latencies. Best value seems to be 24ms which is way higher than the values reported by @jerome .

2020-08-11T16:42:29.616Z 5311e58d dfw [info] REDIS LATENCY 67
2020-08-11T16:42:29.667Z 5311e58d dfw [info] REDIS LATENCY 51
2020-08-11T16:42:29.732Z 5311e58d dfw [info] REDIS LATENCY 28
2020-08-11T16:42:29.761Z 5311e58d dfw [info] REDIS LATENCY 28
2020-08-11T16:42:29.788Z 5311e58d dfw [info] REDIS LATENCY 26
2020-08-11T16:42:29.837Z 5311e58d dfw [info] REDIS LATENCY 49
2020-08-11T16:42:29.886Z 5311e58d dfw [info] REDIS LATENCY 49
2020-08-11T16:42:29.900Z 5311e58d dfw [info] REDIS LATENCY 14
2020-08-11T16:42:29.974Z 5311e58d dfw [info] REDIS LATENCY 54
2020-08-11T16:42:29.998Z 5311e58d dfw [info] REDIS LATENCY 23
2020-08-11T16:42:30.084Z 5311e58d dfw [info] REDIS LATENCY 86
2020-08-11T16:42:30.127Z 5311e58d dfw [info] REDIS LATENCY 42
2020-08-11T16:42:30.143Z 5311e58d dfw [info] REDIS LATENCY 15
2020-08-11T16:42:30.243Z 5311e58d dfw [info] REDIS LATENCY 51
2020-08-11T16:42:30.462Z 5311e58d dfw [info] REDIS LATENCY 144
2020-08-11T16:42:30.545Z 5311e58d dfw [info] REDIS LATENCY 82
2020-08-11T16:42:30.606Z 5311e58d dfw [info] REDIS LATENCY 60
2020-08-11T16:42:30.662Z 5311e58d dfw [info] REDIS LATENCY 55
2020-08-11T16:42:30.772Z 5311e58d dfw [info] REDIS LATENCY 36
2020-08-11T16:42:30.816Z 5311e58d dfw [info] REDIS LATENCY 43
2020-08-11T16:42:30.907Z 5311e58d dfw [info] REDIS LATENCY 43
2020-08-11T16:42:30.966Z 5311e58d dfw [info] REDIS LATENCY 58
2020-08-11T16:42:30.999Z 5311e58d dfw [info] REDIS LATENCY 33
2020-08-11T16:42:31.037Z 5311e58d dfw [info] REDIS LATENCY 37
2020-08-11T16:42:31.064Z 5311e58d dfw [info] REDIS LATENCY 26
2020-08-11T16:42:31.140Z 5311e58d dfw [info] REDIS LATENCY 29
2020-08-11T16:42:31.231Z 5311e58d dfw [info] REDIS LATENCY 90
2020-08-11T16:42:31.265Z 5311e58d dfw [info] REDIS LATENCY 34
2020-08-11T16:42:31.321Z 5311e58d dfw [info] REDIS LATENCY 55
2020-08-11T16:42:31.439Z 5311e58d dfw [info] REDIS LATENCY 40
2020-08-11T16:42:31.477Z 5311e58d dfw [info] REDIS LATENCY 37
2020-08-11T16:42:31.543Z 5311e58d dfw [info] REDIS LATENCY 66
2020-08-11T16:42:31.577Z 5311e58d dfw [info] REDIS LATENCY 34
2020-08-11T16:42:31.609Z 5311e58d dfw [info] REDIS LATENCY 31
2020-08-11T16:42:31.654Z 5311e58d dfw [info] REDIS LATENCY 23
2020-08-11T16:42:31.695Z 5311e58d dfw [info] REDIS LATENCY 40
2020-08-11T16:42:31.773Z 5311e58d dfw [info] REDIS LATENCY 35
2020-08-11T16:42:31.885Z 5311e58d dfw [info] REDIS LATENCY 62
2020-08-11T16:42:31.925Z 5311e58d dfw [info] REDIS LATENCY 39
2020-08-11T16:45:32.183Z 5311e58d dfw [info] REDIS LATENCY 76
2020-08-11T16:45:32.208Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:32.233Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.259Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:32.284Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.310Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.336Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.361Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.387Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:32.413Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.439Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.464Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.490Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.515Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.541Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.567Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.592Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.618Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:32.643Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.670Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.695Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.721Z 5311e58d dfw [info] REDIS LATENCY 26
2020-08-11T16:45:32.747Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.772Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.798Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.824Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.849Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.875Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.901Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.926Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.951Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:32.977Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.002Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.028Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.054Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.079Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.104Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.130Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:33.155Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.181Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:33.206Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.232Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.259Z 5311e58d dfw [info] REDIS LATENCY 26
2020-08-11T16:45:33.284Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.310Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.335Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.361Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.386Z 5311e58d dfw [info] REDIS LATENCY 24
2020-08-11T16:45:33.412Z 5311e58d dfw [info] REDIS LATENCY 25
2020-08-11T16:45:33.437Z 5311e58d dfw [info] REDIS LATENCY 25

Ok, your Redis test runs after you get CONNECTED. Could you move your test() to the READY event instead and let us know what you see?

2020-08-11T17:57:47.579Z 6a967216 dfw [info] REDIS connected
2020-08-11T17:57:47.970Z 6a967216 dfw [info] REDIS ready
2020-08-11T17:57:48.164Z 6a967216 dfw [info] REDIS LATENCY 193
2020-08-11T17:57:48.359Z 6a967216 dfw [info] REDIS LATENCY 193
2020-08-11T17:57:48.553Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:48.748Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:48.942Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:49.137Z 6a967216 dfw [info] REDIS LATENCY 193
2020-08-11T17:57:49.331Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:49.526Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:49.720Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:49.915Z 6a967216 dfw [info] REDIS LATENCY 193
2020-08-11T17:57:50.110Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:50.304Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:50.499Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:50.693Z 6a967216 dfw [info] REDIS LATENCY 194
2020-08-11T17:57:50.888Z 6a967216 dfw [info] REDIS LATENCY 194
etc

Ah, the exact opposite to what I was seeing with your test. Hmmmm… The investigation continues.

@pier I believe you should see improvements to latency right about now (if you make a new connection)

We’ve been having sub-optimal routing for a little bit, and kept improving it every week. Our redis connections go through the very same proxy that routes requests to your app and is therefore susceptible to the same balancing issues.

We’ve adjusted the balancing algorithm significantly this afternoon and latency should now be much better.

It’s worth noting that AUTH is expensive with our redis. It’s best to keep the same redis connection around as much as possible (I believe you’re doing that already). It’s expensive because there’s extra overhead to authorizing a connection, the way we’ve set it up.

Let us know if it’s better and especially if it’s not!

2 Likes

Thanks for the info @jerome

I’ve redeployed the app but now the logs seem dead for all my Fly apps… once the logs are working again I will let you know about the Redis latency.

@pier there’s an issue with logs that we’re fixing right now, sorry about that.

1 Like

Thanks, no worries @michael I imagined that was the case.

Should be good now :slight_smile:

Thanks @jerome and @michael .

Unfortunately the Redis latencies haven’t changed much :confused:

I destroyed the testing Fly app to start clean. I updated the code to show the latencies via HTTP instead of the console.

Now whenever you visit the domain it will make 10 reads to Redis and show the time it took for each.

https://green-bush-1427.fly.dev/

These were the last results, but if you refresh a couple of times you will probably see results above 100ms.

Redis latency test: 
59ms
50ms
76ms
60ms
66ms
61ms
46ms
23ms
61ms
22ms

I’ve updated the repo too: https://github.com/PierBover/fly-redis-node-test

When I test this locally I get latencies of 0-2ms so I don’t think the issue is really in my code or the Redis driver.

Since you’re seeing much better results in your test app… maybe it’s an issue with the Docker current-alpine image?

I confess I’m a Docker ignorant… but I followed the instructions in your docs for the Dockerfile.