Open rmd4 opened 7 months ago
hi @rmd4
I have been testing keydb, and have experienced similar crashes. Adding more logging, I noticed when keydb is not properly shutdown, it loses the TTLs in they flash storage:
1023:1127:M 21 Nov 2023 02:04:41.188 * ckeysExpired [92601] db->expireSize() [0]
After this point, keydb will keep crashing on shutdown, and intermittently at runtime (this check is also done in other parts of the code at runtime).
Will post here if I find anything else useful.
In the meantime, the workaround is to delete the flash folder and reload from RDB, not very nice. Ugh, sorry, even with this workaround, another runtime error occurs when keydb is restarted:
9:578:M 21 Nov 2023 02:31:54.496 # === ASSERTION FAILED ===
9:578:M 21 Nov 2023 02:31:54.496 # ==> db.cpp:1833 'm_numexpires > 0' is not true
hi @rmd4
It looks like KeyDB has some issues with the m_numexpires field when flash is enabled. My temporary solution is to patch it and rebuild m_numexpires on startup. At least it is not crashing on shutdown and startup anymore, so I can keep testing.
After looking into this a bit more, the m_numexpires was introduced in:
https://github.com/Snapchat/KeyDB/pull/720
@msotheeswaran-sc it looks like this was pushed in v6.3.4 to fix the OOM issues by evicting items in flash. Briefly looking at the PR, m_numexpires in managed at runtime, but if the server restarts, it will be 0 and will no longer be in sync with flash?
I did wonder if this was related to flash storge as I have also seen the
db.cpp:1833 'm_numexpires > 0'
issue. However, I turned off flash storage and that one was resolved, athough it was effectively replaced with the db->expireSize() issue. Both would occur at roughly the same time of day (0405am even though my housekeeping starts at 0200 and is complete by 0300 - no idea why 0405).
My current config does not make use of flash:
# Enable FLASH support (Experimental Feature)
#storage-provider flash /mnt/keydb/keydb
I even removed the /mnt/keydb mount point, just to make sure ;) However, I'm still getting the
ckeysExpired == db->expireSize()
issue. I can 'resolve' it by turning off database dumping completely:
save ""
#save 900 1
#save 300 10
#save 60 10000
I've been stable now for 48+ hours.
I don't believe it's releated to an unclean shutdown as I can flush the DB and restart (DB save enabled, no flash) and the issue will return within 24 hours of production use.
It must be linked to something I'm managing to place in the DB, but as per the Python script above, it's not something I have managed to reproduce other than with my production code (a website where load is usage driven).
hi @rmd4
As per my previous comment, I tracked it down to the eviction changes for flash introduced in v6.3.4. My temporary workaround for this is to set m_numexpires on startup. So far, haven't had the crash, ie with both flash and data dumping enabled.
For unclean shutdown, use a KILL -9 and also make sure you have entries with TTL in flash. And this may not be the only way to trigger the bug, as you have mentioned, it can also happen at runtime. I did find that once the variable is out of sync, then the crash can happen anytime (dump at shutdown or at runtime).
My current goal is to stress test the flash feature in the most challenging way I can, ie maxmemory smaller than dataset (so keys get evicted from memory), 5000+ read/writes per second, module scanning, RDB background saving, etc. I have had countless crashes, and just hacking the code to workaround them. So far, I am very impressed with KeyDB.
Technically a duplicate of https://github.com/Snapchat/KeyDB/issues/739 but there is more discussion here.
I don't use flash storage and yet have this very issue.
@keithchew can you please share your patch?
Hello! I've received the same issue on keydb.
Finding the root case of issue, i've notes, that if keyspace looks like this:
keydb@keydb-0:/data$ keydb-cli info keyspace
# Keyspace
db0:keys=3305,expires=3305,avg_ttl=44022308,cached_keys=3305
db1:keys=11204,expires=11204,avg_ttl=75608578,cached_keys=11204
db2:keys=6136,expires=6136,avg_ttl=851903,cached_keys=6136
db3:keys=64,expires=70,avg_ttl=826725,cached_keys=64
db4:keys=26541,expires=26543,avg_ttl=4932380,cached_keys=26541
keys in db3 and db4 are not equal to expires.
keydb-cli bgsave reports in log STACK TRACE (see attached keydb-0.log file)
if run commands: keydb-cli -n 3 flushdb keydb-cli -n 4 flushdb
then command keydb-cli bgsave runs successfully.
I've also notes, that this behavior occurs when application, that uses keydb service call DEL-command on keys with TTL.
From redis-exporter, if make substitution of redis_db_keys and redis_db_keys_expiring, it'll be negative indicators:
Hi @splitice
In db.cpp, you can update m_numexpires when KeyDB iterates the keys on startup, eg:
size_t offset = 0;
std::unique_ptr<expireEntry> spexpire = deserializeExpire((const char*)data, cbData, &offset);
if (spexpire != nullptr) {
m_numexpires += 1;
}
@keithchew I couldnt find that line in db.cpp, it appears that you mean snapshot.cpp?
But that can't be right either, that code path is called on many others (such as the KEYS
command) and will end up corrupting m_numexpires when it is.
Hi @splitice
On my local testing copy, I have created a new method that is only called on startup, to prevent the multiple flows. The snippet above is what I added, do a search for "iterate" which will have the code that does the iteration.
@keithchew could you share an actual patch? Thats far beyond just adding a line or two and requires an actual understanding of the control flow of the relatively undocumented KeyDB source code.
m_numexpires = psnapshot->m_numexpires;
needs to be added at the bottom.
This won't fix anyone whose RDB file is now corrupt as of 6.3.4, so restore from a 6.3.3 backup. I'll test this in the coming days.
diff --git a/src/snapshot.cpp b/src/snapshot.cpp
index 94956ebc2..fe6b98983 100644
--- a/src/snapshot.cpp
+++ b/src/snapshot.cpp
@@ -168,6 +168,7 @@ void redisDbPersistentData::restoreSnapshot(const redisDbPersistentDataSnapshot
dictEmpty(m_pdictTombstone, nullptr);
endSnapshot(psnapshot);
serverAssert(size() == expectedSize);
+ m_numexpires = psnapshot->m_numexpires;
}
// This function is all about minimizing the amount of work done under global lock
Hi @splitice
Sorry I don't have a patch as yet, as I am just copying and pasting snippets here and there as quick fixes to prevent crashes, as my current goal is to evaluate KeyDB for a project. Once I have completed the evaluation, hopefully I will have time to post PRs back here. In the meantime, all I can provide are guidelines for developers who are going through the same issues.
Will this error be corrected? It is surprising to catch such problems in releases. I thought that this project was much more stable
BTW while I did have a go at a fixing this I felt the current release was too much of a bad idea and ended up doing a downgrade.
We are currently considering if KeyDB is something we can consider production grade and what would be involved in migration to redis cluster.
Given the relatively large number of tweaks I made to get my copy working (and this is only for my use-cases), I agree with @splitice that you should not use v6.3.4 if you encounter this issue in your setup. Would be better to wait for the next official release from the developers and check if it is fixed then. For me, I need v6.3.4 because I have to get quite a number of dependent things working for my evaluation, eg Flash, modules, etc, so I pushed forward instead.
i have the same issue after i upgraded my keydb server from 6.3.2 to 6.3.4. My keydb server now can't save rdb file to persistent. Are there any plans to fix this issue?
Crash report
I'm having the prolem on my production server. I'm not using replication.
From what I can tell, the crashes are triggered by a client connection making a change to the DB and triggering a write of the RDB file. The crash appears to happen during the write of the DB file. This then happens every time a new change is made to the DB.
I can stop the crashes by flushing the DB.
Unfortunately, this is a production server and there's a limit to what I can do.
I've flushed the DB and then put the server under significant load with the following script. I basically create a large number of keys with large values and random expire times, and then deletes them again. Some will naturally expire before I get round to deleting. This appears to work fine.
With the system crashing, I've set up a second instance on an identical machine and used a python script to copy all keys, values and associated TTLs to the new instance. The second system works fine, dumps to the RDB when required.
If I point the production clients at this new instance after about 24 hours, the issue returns....so it's not hardware related.
I have tried
which I still have in place, but this does not resolve the issue.
It must be something to do with the contents of the DB or the way my clients (Python) are using it but I'm unable to isolate the problem.