database is locked during Rancher (moderate) stress test
#8234
Comments
|
I am available in case any further support from my part could help with investigation and resolution here! |
|
I am a little surprised that the database locked error is getting passed all the way back up the stack. It might be more appropriate for kine to retry internally when this happens instead of passing it back up, as it is not a normal etcd error that most clients are going to know how to respond to. What sort of underlying disk and filesystem are you running this on? Is the response time acceptable using etcd on the same hardware, or do you see latency warnings in the apiserver logs? |
|
I am using two local SSDs (one SCSI, one NVME) in md-raid 0 on XFS. Performance is adequate under etcd to the extent I can tell. I did not notice anything suspicious in logs. As for whether it's good to pass the error up the stack, I'm unsure. IIUC, the only way error can happen is if at some point there are multiple open connections to the same database file at the same time (either from different goroutines or processes) - and at least two writing at the same time. That is something I naively thought should never happen (in my mind: one kine - one process - one connection) are there known cases/reasons where there can be multiple connections opened? |
|
There should never be concurrent access to the database from multiple processes unless you're doing something weird with trying to run multiple copies of K3s backed by the same disk and path. I think you might be thinking about SQLITE_BUSY, which is not what you're getting - you're getting SQLITE_LOCKED, which is different, and can happen within a single process. go-sqlite3 does allow for multiple concurrent reads from different goroutines within the same process. See the discussion at mattn/go-sqlite3#632 - we use WAL mode with a shared cache: https://github.com/k3s-io/kine/blob/7f6ba014aa711f83baf4b875181f8e44d5419d48/pkg/drivers/sqlite/sqlite.go#L60C2-L60C2 I suspect that you might be running into issues with the compact transaction locking the database for short periods while it cleans up old rows? That is to be expected, as the database would grow without bound if we didn't compact it periodically. |
|
I believe what we are seeing is actually /* SQLITE_BUSY */ "database is locked",
/* SQLITE_LOCKED */ "database table is locked",So we should be in this case:
Source: https://www.sqlite.org/rescode.html In this case I believe we can exclude the possibility of multiple processes acting on the same SQLite database - there is only one k3s process in the k3d container, and no shared volumes are mounted so the actual filesystem paths must be separate. OTOH, we do expect multiple open DB connections as automatically managed by sql.DB itself. Turns out there is a busy timeout retry mechanism as a SQLite PRAGMA, that can be set in the connection string. I wonder if that could help. |
|
It was unclear to me if the "usually in a separate process" comment indicated that this error is more likely to be caused by another process for architectural reasons, or if that is just a more frequently observed use pattern that causes that error. If setting a timeout would help, it should be easy enough to see if that makes a difference: |
I believe it indicates a frequently observed use pattern. In this case there is just one process - I even reproduced it with a standalone I did try with Without With (note that JFI I also re-ran the test with embedded etcd ( So from all I can tell from this microbenchmark, it would help and solve this problem to have Thanks for the guidance! |
Under stress, concurrent operations (notably while garbage collection is in progress) can result in failed calls with error SQLITE_BUSY (database is locked). The SQLITE_BUSY result code is an expected outcome when the database file could not be written (or in some cases read) because of concurrent activity: https://www.sqlite.org/rescode.html SQLite ships a busy timeout retry mechanism as a PRAGMA (https://www.sqlite.org/pragma.html#pragma_busy_timeout), that can be set via go-sqlite3's connection string. That makes go-sqlite3 retry operations that fail with SQLITE_BUSY transparently to users. Fixes k3s-io/k3s#8234
Under stress, concurrent operations (notably while garbage collection is in progress) can result in failed calls with error SQLITE_BUSY (database is locked). The SQLITE_BUSY result code is an expected outcome when the database file could not be written (or in some cases read) because of concurrent activity: https://www.sqlite.org/rescode.html SQLite ships a busy timeout retry mechanism as a PRAGMA (https://www.sqlite.org/pragma.html#pragma_busy_timeout), that can be set via go-sqlite3's connection string. That makes go-sqlite3 retry operations that fail with SQLITE_BUSY transparently to users. Fixes k3s-io/k3s#8234 Signed-off-by: Silvio Moioli <[email protected]>
|
@moio thanks for the research on this! Did you evaluate any different values for the timeout? 30 seconds was a somewhat arbitrary choice; I'm curious if there is a better value we could use as the default. |
|
Not really. As you mentioned, the value is arbitrary - It's a halting problem, undecidable by definition. My understanding is: the longer the time the less likely SQLITE_BUSY is produced - so there is an incentive to set the value as high as possible. That's because there will always be combinations of high load, slow hardware and bad timing that make a query take long, an we do not want it failed just because we were not patient enough. OTOH, there can be pathological cases in which bugs result in particularly problematic usage patterns that cause more contention than necessary - and the only way for us to discover is to see SQLITE_BUSY errors. That's an opposite incentive to set the value as low as possible. FMPOV, I do not expect dramatic changes in access patterns at this point of maturity of k3s and kine - garbage collection is "a known quantity". 30s ought to be enough for the vast majority of cases, and the occasional error should be generally tolerated by software layers above. I can only suggest to keep an eye on user reports, and tweak depending on what others see. I do not think it makes sense to over-fit a value on my current microbenchmark. HTH! |
Under stress, concurrent operations (notably while garbage collection is in progress) can result in failed calls with error SQLITE_BUSY (database is locked). The SQLITE_BUSY result code is an expected outcome when the database file could not be written (or in some cases read) because of concurrent activity: https://www.sqlite.org/rescode.html SQLite ships a busy timeout retry mechanism as a PRAGMA (https://www.sqlite.org/pragma.html#pragma_busy_timeout), that can be set via go-sqlite3's connection string. That makes go-sqlite3 retry operations that fail with SQLITE_BUSY transparently to users. Fixes k3s-io/k3s#8234 Signed-off-by: Silvio Moioli <[email protected]>
|
Reopening to track updating kine in K3s; didn't notice that the Kine PR used the Fixes keyword to auto-close this issue. |
|
I tested this on k3s v1.26.9-k3s1 / Rancher 2.7.6 and confirm this issue is fixed. Good to close! Thanks! |
Under stress, concurrent operations (notably while garbage collection is in progress) can result in failed calls with error SQLITE_BUSY (database is locked). The SQLITE_BUSY result code is an expected outcome when the database file could not be written (or in some cases read) because of concurrent activity: https://www.sqlite.org/rescode.html SQLite ships a busy timeout retry mechanism as a PRAGMA (https://www.sqlite.org/pragma.html#pragma_busy_timeout), that can be set via go-sqlite3's connection string. That makes go-sqlite3 retry operations that fail with SQLITE_BUSY transparently to users. Fixes k3s-io/k3s#8234 Signed-off-by: Silvio Moioli <[email protected]> Signed-off-by: zhiyuan <[email protected]>
Environmental Info:
K3s Version:
v1.24.12+k3s1Node(s) CPU architecture, OS, and Version:
Linux lenovo 5.14.21-150400.24.60-default #1 SMP PREEMPT_DYNAMIC Wed Apr 12 12:13:32 UTC 2023 (93dbe2e) x86_64 x86_64 x86_64 GNU/LinuxCluster Configuration:
1 server, no agents, k3d. Default SQLite store
Describe the bug:
database is lockederrors are reliably produced within seconds in Rancher logs running a (moderate) stress test script. Such errors do not appear with embedded etcd (specifying--cluster-init).Steps To Reproduce:
Use
k3d cluster delete k3s-testto delete the test environment after use.Expected behavior:
No log lines produced at point 4.
Actual behavior:
Lines appear like the following:
Additional context / logs:
I understand the reproducer is a bit convoluted, but it's been very reliable so far (and I minimized it to the extent I was able to).
I looked at past history and found quite some other previous similar reports were closed because of staleness or suspected unrelated configuration issue - I hope this helps isolating the actual root cause.
Also note that, as suspected, adding
--k3s-arg --cluster-init@server:0to the commandline in step 1 (thereby forcing embedded etcd instead of SQLite) makes the issue go away.The text was updated successfully, but these errors were encountered: