Redis flushdb is causing error: "Redis server 127.0.0.1:6379 went away"

[jessewaitz]

Expected behaviour

Flushing the db using the phpredis function flushdb() should clear the redis database, and if a new redis call comes in to check if a key exists or to set a new key, it should respond null, false, or fail gracefully.

Actual behaviour

Instead the redis server is causing subsequent redis calls, to check if a key exists, or set a new key, to throw a redisException: "Redis server 127.0.0.1:6379 went away"

Note: It appears that the errors only happen during the few milliseconds that the database is being cleared and the server is resetting. Our site gets close to 80k uniques a day so this problem is probably not seen on sites will way less visitors. But on our site we get at least 1 or 2 exceptions every time we clear the cache during business hours, at night when traffic is way less, this error never happens. But, after those couple exceptions, everything goes back to normal, and no additional exceptions happen until the redis db is flushed again.

In addition, this error is new since we upgraded the server to php 8.1 and our wordpress code to 6.1. Before this upgrade the redis keys hovered around 500k keys, but after the update to wp 6.1 our keys have quadrupled to about 2 million. So while I understand that wordpress is now using redis more heavily in its core functions, and a DB with 2 million keys is going to take longer to flush, shouldn't there be a way to make redis fail gracefully during this flushing process, instead of causing RedisExceptions.

I did add a php try/catch exception handler to the redis function that was causing the exception (in this first case, checking if a key exists). This worked for handling the exception for function. but then once that was handled the exceptions started firing on the setex() function. So it is just moving onto the next function after the exists() function returns null and is then trying to now set the key, and it is throwing the same exception on that function now.

Any help that you can give to reduce or eliminate these exceptions, would be greatly appreciated. thanks.

I'm seeing this behaviour on

• OS: Ubuntu 20 (Linux 5.4.0-128-generic x86_64)
• Redis: v7.0.5
• PHP: v8.1.12
• PhpRedis: v5.3.7

Steps to reproduce, backtrace or example script

See above, it happens every time I flush the db...

I've checked

• [ X ] There is no similar issue from other users
• [ X ] Issue isn't fixed in develop branch

[michael-grunder]

My guess is that you're running into a common issue with Redis, namely that it is single-threaded and therefore will block other clients when executing very expensive operations.

After you execute the flush, I assume other clients are simply hitting any read timeout that is set, and then raising the Redis server went away exception.

A quick solution may be to switch to using FLUSHDB ASYNC, which will tell Redis to delete the keys in the background, rather than blocking clients until the operation is complete.

In PhpRedis 5.3.7 you simply need to invoke FLUSHDB like this:

$redis->flushdb(true);

Edit: Alternatively you can change your redis-server config settings (if you are using >= 6.2.0) so it will do an async flush by default.

By default, FLUSHDB will synchronously flush all keys from the database. Starting with Redis 6.2, setting the lazyfree-lazy-user-flush configuration directive to "yes" changes the default flush mode to asynchronous.

[jessewaitz]

Michael, Thank you for the really quick response.

I forgot to mention in my original post, that I did try that "async" option in my flush calls, and it did not make any difference, the exists function threw the same exceptions just as before.

[michael-grunder]

I forgot to mention in my original post, that I did try that "async" option in my flush calls,

In that case, I would make sure that FLUSHDB ASYNC is actually being invoked by monitoring the redis-server when you execute a flush. You can also use redis-cli to monitor latency at the same time:

# For raw numbers
redis-cli -h <host> -p <port> --latency-history

# If you want a graph
redis-cli -h <host> -p <port> --latency-dist

The most likely culprit here is that Redis is blocking on a large operation. It might be something else, but I've never seen this issue occur with an ASYNC flush.

You can also try increasing whatever timeouts you have set, but I think getting at the blocking issue is probably more useful.

[jessewaitz]

ok, that is a good recommendation. I will try that over the next few days, and let you know what happens.

[jessewaitz]

Michael,

I have set my flushdb() function ASYNC (ie. flushdb(true) ).

I then logged into the server and ran the "redis-cli --latency-history" command and then finally flushed the redis db with our normal procedure, and here is the output of the cli command:

root#>> redis-cli --latency-history
min: 0, max: 2, avg: 0.12 (1469 samples) -- 15.01 seconds range
min: 0, max: 4, avg: 0.11 (1469 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.10 (1469 samples) -- 15.00 seconds range
min: 0, max: 6, avg: 0.12 (1467 samples) -- 15.01 seconds range
min: 0, max: 2, avg: 0.11 (1468 samples) -- 15.00 seconds range
min: 0, max: 2, avg: 0.12 (1467 samples) -- 15.01 seconds range
min: 0, max: 3588, avg: 3.35 (1114 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.10 (1469 samples) -- 15.01 seconds range
min: 0, max: 2, avg: 0.11 (1467 samples) -- 15.00 seconds range
min: 0, max: 2, avg: 0.12 (1465 samples) -- 15.00 seconds range
min: 0, max: 2, avg: 0.12 (1465 samples) -- 15.01 seconds range

I am not sure what to make of this output. Maybe you have some insight?

I can also state that the redisException did not get thrown during this test. But that is only a single test event, so I cannot be sure it is fixed yet. I will leave the ASYNC parameter in place on my site, for now and see if it fixes anything.

I am interested if this output (above) means anything to you, let me know what you think, thanks.

[jessewaitz]

@michael-grunder , do you have any ideas about my last post... your thoughts are greatly appreciated.

[michael-grunder]

Sure,

The --latency-history redis-cli command just repeatedly hits Redis and reports statistics on latency. The numbers are all in milliseconds.

More information about what all the fields mean

The worst latency in the history you displayed is here:

min: 0, max: 3588, avg: 3.35 (1114 samples) -- 15.00 seconds range

This means Redis blocked for nearly 3.5 seconds during the flush. That doesn't make a lot of sense to me if you're using FLUSHDB ASYNC, which really shouldn't block very much at all.

Are you near maxmemory limits when you issue the FLUSHDB?

Just to test things out, I loaded a Redis instance on my local machine with 32G of data, and a FLUSHDB ASYNC doesn't cause any measurable latency at all. A non-async flush does.

[jessewaitz]

Michael,

Thanks for the explanation, but when you write "maxmemory" are you referring to server memory or redis memory. Our server has 32GB of RAM, and we never get close to using up that. If you are referring to redis memory where would I go to find that information.

I have changed all of the functions in my php code that call flushDB, and so I am pretty sure I turned ASYNC on. Would the next thing to try be to change the setting to async in the redis conf file? What do you think?

Im sorry for my noob questions, I am just not all that of an expert on redis.

[michael-grunder]

when you write "maxmemory" are you referring to server memory or redis memory.

Redis has a special setting called maxmemory which is typically set in redis.conf which allows users to set an upper bound on how much data Redis will allow itself to use before either refusing to write new keys or starting to actively evict old data.

Here's a good summary of the subject.

I only ask because I've seen high latency when operating at or near this maxmemory setting because Redis was continuously spinning trying to get under the limit. That said, it may be completely unrelated.

Another mechanism you can try to use to see why the latency is happening is by using the SLOWLOG command. More info here.

For example, inspecting the instance where I did a non-async FLUSHDB earlier I see this:

$ redis-cli slowlog get
1) 1) (integer) 1
   2) (integer) 1673383885
   3) (integer) 614746
   4) 1) "flushdb"
   5) "127.0.0.1:55174"
   6) ""

Specifically, this is telling me that at Unix timestamp 1673383885 a flushdb command took 614746 microseconds (or .614 seconds). It also tells me which client invoked the command.

Also, you can use the info commandstats command to dump a bunch of statistical information about every command that has been executed on the server and corresponding statistics

Here's info from the server where I executed a SYNC flushdb (and three async ones).

❯ redis-cli info commandstats|grep flushdb
cmdstat_flushdb:calls=4,usec=614762,usec_per_call=153690.50,rejected_calls=0,failed_calls=0

Im sorry for my noob questions, I am just not all that of an expert on redis.

No worries at all!

[jessewaitz]

My redis.conf file says that my maxmemory is set to 4g. Is that enough or should it be set higher?

With regard to the slowlog, I ran that command, and got 10 results. The last two look like your example (see below):

 9) 1) (integer) 193
    2) (integer) 1673460496
    3) (integer) 612878
    4) 1) "FLUSHDB"
    5) "127.0.0.1:54570"
    6) ""
10) 1) (integer) 192
    2) (integer) 1673460489
    3) (integer) 17483
    4) 1) "flushdb"
    5) "127.0.0.1:54702"
    6) ""

Lastly, I ran your info commandstats command and got this result (see below):

cmdstat_flushdb:calls=14,usec=10909772,usec_per_call=779269.44,rejected_calls=0,failed_calls=0

Does any of this point to the source of the problem to you?

[michael-grunder]

My redis.conf file says that my maxmemory is set to 4g. Is that enough or should it be set higher?

It depends. If Redis is using at or near 4g when you issue the flush, it's possible the setting is related, but you'd need to test it to be sure.

What yourSLOWLOG and commandstat info tells me is that the FLUSHDB command is still blocking for quite a long time. So either, a non-async FLUSHDB is still being called or even the async flush is still blocking for an unknown reason.

It might be worth setting the lazyfree-lazy-user-flush so FLUSHDB is async by default. Additionally, you could monitor your redis instance with something like redis-cli MONITOR|grep -i flushdb to ensure every flushdb is in fact using the ASYNC argument.

[jessewaitz]

I have not changed any conf files yet, I need to plan that for a weekend in case it causes us unforeseen problems, but I did run the monitor command during a flush and here is the output I got:

>> redis-cli MONITOR|grep -i flushdb
1673536585.758826 [0 127.0.0.1:58550] "flushdb"
1673536589.944847 [1 127.0.0.1:58456] "FLUSHDB"

[michael-grunder]

That monitor log shows that a non-async FLUSHDB is in fact being issued.

It would look like this if an async flush was issued:

$ redis-cli monitor|grep -i flushdb
1673566612.900433 [0 127.0.0.1:35588] "FLUSHDB" "ASYNC"