Silent data loss when inserting records using RETURNING clause in C# multithreaded scenario
(1.1) By enickson on 2023-05-12 08:28:44 edited from 1.0 [link] [source]
Hi,
I'm experiencing a data loss issue when inserting single records using the RETURNING clause in a multi threaded scenario.
This bug seems to only happen if PRAGMA journal_mode=DELETE. I can't replicate it in WAL mode.
I originally found this using EF Core and created a GitHub issue here but have replicated below using System.Data.SQLite so this appears to be an SQLite bug.
This code inserts 250 records 1 by 1 in individual Tasks. At the same time it does each insert it queries the database in a different Task.
At the end it counts how many records are in the DB.
It does all that once using inserts without the RETURNING clause, and then again with the clause.
The output looks like this:
SQL Statement:
INSERT INTO 'LogEvents' ('ID', 'Message')
VALUES (1, 'test message');
250 Inserts
250 Records Created
Time Taken: 3516
SQL Statement:
INSERT INTO 'LogEvents' ('ID', 'Message')
VALUES (1, 'test message')
returning ID;
250 Inserts
236 Records Created
Time Taken: 505
You can see that for the inserts using the RETURNING clause we ended up with some records missing from the DB.
In addition the inserts using the RETURNING clause took far less time to run, so it seems like there's some locking which is being skipped due the RETURNING clause and that's causing data loss.
I've found that wrapping the insert in a transaction resolves this issue, but that shouldn't be necessary for a single statement insert.
Note: original use case of RETURNING was for an auto incremented ID column but this repros the bug without that so I removed to make the example simpler.
Code
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<OutputType>Exe</OutputType>
<TargetFramework>net7.0</TargetFramework>
<ImplicitUsings>enable</ImplicitUsings>
<Nullable>enable</Nullable>
</PropertyGroup>
<ItemGroup>
<PackageReference Include="System.Data.SQLite" Version="1.0.117" />
</ItemGroup>
</Project>
using System.Data.SQLite;
using System.Diagnostics;
namespace collisionTest2;
public class Program
{
public static string CreateTempDB()
{
string filePath = Path.GetTempFileName();
SQLiteConnection.CreateFile(filePath);
var connectionString = $"Data Source={filePath}";
using SQLiteConnection sqlite = new(connectionString);
try
{
sqlite.Open();
using SQLiteCommand cmd = sqlite.CreateCommand();
cmd.CommandText = @"
CREATE TABLE IF NOT EXISTS 'LogEvents' (
'Id' INTEGER NOT NULL,
'Message' TEXT NOT NULL
);
PRAGMA journal_mode=DELETE;";
cmd.ExecuteScalar();
}
finally
{
sqlite.Close();
}
return connectionString;
}
public static long CountRecords(string connectionString)
{
using SQLiteConnection sqlite = new(connectionString);
try
{
sqlite.Open();
using SQLiteCommand cmd = sqlite.CreateCommand();
cmd.CommandText = $"Select count(*) from 'LogEvents';";
return (long) cmd.ExecuteScalar();
}
finally
{
sqlite.Close();
}
}
static async Task Main(string[] _)
{
var connectionString = CreateTempDB();
string notReturning = @$"
INSERT INTO 'LogEvents' ('ID', 'Message')
VALUES (1, 'test message');";
string returning = @$"
INSERT INTO 'LogEvents' ('ID', 'Message')
VALUES (1, 'test message')
returning ID;";
foreach (var statement in new string[]{notReturning, returning})
{
var startingCount = CountRecords(connectionString);
int inserts = 250;
var stopWatch = Stopwatch.StartNew();
for (int i = 0; i < inserts; i++)
{
var taskOne = Task.Run(() =>
{
using SQLiteConnection sqlite = new(connectionString);
try
{
sqlite.Open();
using SQLiteCommand cmd = sqlite.CreateCommand();
cmd.CommandText = statement;
cmd.ExecuteScalar();
}
finally
{
sqlite.Close();
}
});
var taskTwo = Task.Run(() =>
{
CountRecords(connectionString);
});
await taskOne;
await taskTwo;
}
stopWatch.Stop();
var finalCount = CountRecords(connectionString);
Debug.WriteLine($"SQL Statement: {statement}");
Debug.WriteLine($"{inserts} Inserts");
Debug.WriteLine($"{finalCount - startingCount} Records Created");
Debug.WriteLine($"Time Taken: {stopWatch.ElapsedMilliseconds}");
}
}
}
(2) By Donal Fellows (dkfellows) on 2023-05-12 08:32:48 in reply to 1.0 [link] [source]
Just checking the obvious things here:
- Was the SQLite library itself built with multithreaded support and was it enabled for the connections you made?
- Each thread/task is getting its own connection, yes? (It appears to be, but C# is not a language I'm deep into the nuances of.)
- What filesystem was the database on? Please say "local disk with NTFS" as that's a relatively well-known scenario!
(3) By enickson on 2023-05-12 09:08:38 in reply to 2 [link] [source]
- This example uses the System.Data.SQLite library maintained by the Sqlite team here. The documentation states:
You May create multiple threads, and those threads can create their own SQLiteConnection and subsequent objects for accessing a database. Multiple connections on multiple threads to the same database file are perfectly acceptable and will behave predictably. - Yes, although these Tasks are run in a thread-pool. But the
using
statements will make sure each SQLite connection is created and disposed of within the scope of the Task. - local disk with EXT4
(4) By Donal Fellows (dkfellows) on 2023-05-12 09:59:36 in reply to 3 [source]
That's fine. I was asking to make sure we weren't in any of the crazy scenarios where things are expected to go wrong.
Sounds like it needs deeper expert attention than I can provide.
(5.1) By mistachkin on 2023-05-13 23:34:40 edited from 5.0 in reply to 1.1 [link] [source]
Thanks for the report. I've reproduced the issue locally and come up with an experimental fix, which can be seen here: https://system.data.sqlite.org/index.html/info/8c9e834b95d82ebc After testing is completed, this fix will be included in the upcoming 1.0.118.0 release of System.Data.SQLite. EDIT #1: Further refinements were necessary for this fix. It is still being tested.
(6) By enickson on 2023-05-14 23:20:24 in reply to 5.1 [link] [source]
Thanks for looking at this so quickly.
I was going through the code changes you made. This new comment you added seems to describe the cause of the bug.
// BUGFIX: There are SQL statements that cause a write transaction
// to be started and that always require more than one step
// to be successfully completed, e.g. INSERT with RETURNING
// clause. Therefore, if there is a write transaction in
// progress, keep stepping until done unless forbidden from
// doing so by the caller.
I can see you've only added the fix to ExecuteScalar. I was just having a play around with the 1.0.117 version and this bug also occurs using ExecuteNonQuery.
I guess the RETURNING clause inside ExecuteNonQuery is not a particularly valid use case for that API but I can see people making the mistake.
There is also has some strange behaviour where ExecuteNonQuery is returning -1 when inserting a record using the RETURNING clause instead of 1.
Also, the EF Core team thought this was an SQLite bug. How did you know it was a System.Data.SQLite bug and not an SQLite bug?
(7.2) By mistachkin on 2023-05-15 04:20:51 edited from 7.1 in reply to 6 [link] [source]
Thanks for the feedback. I think you may be right about ExecuteNonQuery. Originally, I thought its use of a NextResult loop made it immune to the problem; however, I should probably add a new test case and then (maybe) give it the same new handling as the ExecuteScalar method. Originally, I was not sure where the actual bug was. However, Dan added a new multi-threaded test case for the core library itself, see: https://www.sqlite.org/src/info/559cb1c6de384fd1 After we were unable to reproduce the issue with it, I began to (more) strongly suspect that the underlying bug was in System.Data.SQLite. EDIT #1: Reproduced the issue using ExecuteNonQuery, via a new test case, and updated the fix, here: https://system.data.sqlite.org/index.html/ci/b71ee43a09 EDIT #2: I've adjusted the ExecuteNonQuery test case to double-check the count of records affected and attempted to correct several minor problems, here: https://system.data.sqlite.org/index.html/info/ea4c3f4f82a7b456
(8) By Roy Hashimoto (rhashimoto) on 2023-05-15 15:08:11 in reply to 7.2 [link] [source]
Can you please explain what caused the original bug? The comment that INSERT with RETURNING requires more than one step confuses me. I understand that stepping would be needed to collect all the output, but my understanding was that all writes were done on the first step based on the RETURNING documentation:
When a DELETE, INSERT, or UPDATE statement with a RETURNING clause is run, all of the database changes occur during the first invocation of sqlite3_step().
My reading of that is that the OP's original behavior of missing inserted rows wouldn't be fixed by adding more steps (because all the insertions are done on the first step). Am I wrong, is the documentation wrong, or is there a separate part of the fix that addresses that?
The reason I'm asking is I want to make sure I don't need a similar fix in my own code that calls the SQLite API. Also, I see the WASM OO1 API will skip extra stepping when output isn't needed so I'm wondering whether that needs attention. Thanks!
(9) By Stephan Beal (stephan) on 2023-05-15 15:28:18 in reply to 8 [link] [source]
The reason I'm asking is I want to make sure I don't need a similar fix in my own code that calls the SQLite API. Also, I see the WASM OO1 API will skip extra stepping when output isn't needed so I'm wondering whether that needs attention.
FYI, investigating the equivalent in detail for the JS API is on my TODO list but a real-world relocation at the end of this week is going to delay that. The RETURNING construct never entered my mind while writing the JS code and it's quite possible that "something" needs to be done to handle that case properly. Hopefully i can say more on that by next week.
(10) By Richard Hipp (drh) on 2023-05-19 14:16:46 in reply to 1.1 [link] [source]
My C-language test program to reproduce this behavior is shown below. This is what the program does:
- Open a database connection to the database "x1.db".
- Prepare statement "INSERT INTO t1(a) VALUES(?) RETURNING rowid;"
- Step the statement once only, then finalize the statement.
- Close the connection.
The test database is initialized using
CREATE TABLE t1(a,b,c);
A separate process holds a read transaction open on the database file during all tests. When the database is in journal_mode=DELETE, the INSERT will fail because the database cannot be changed while another connection is holding a read transaction. (This is because any change to the database might change content out from under the connection holding the read transaction.) When the database is in journal_mode=WAL, on the other hand, the INSERT can proceed even though another read transaction is active.
When the INSERT fails because of being in DELETE mode, the sqlite3_finalize() call will always return SQLITE_BUSY. So SQLite always alerts the application that the INSERT failed. The call to sqlite_step() also always returns SQLITE_BUSY, though not necessarily on the first call to sqlite3_step(). If there is a RETURNING clause, then sqlite3_step() might return SQLITE_ROW a few times before it returns SQLITE_BUSY. It will, however, always return SQLITE_BUSY before it returns SQLITE_DONE.
So I think the bug here is in either the application, or in the System.Data.SQLite methods that the application is calling. One or the other of these codes is assuming that if the first call to sqlite3_step() on a DML statement does not return SQLITE_BUSY then the DML statement must have succeeded. This is not true. The application or library needs to either run sqlite3_step() until it completes or else check the return value from sqlite3_finalize() or sqlite3_reset() to see if the INSERT really did complete.
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#include "sqlite3.h"
int main(int argc, char **argv){
sqlite3 *db = 0;
sqlite3_stmt *pStmt = 0;
int v, rc;
char *zSql;
if( argc!=2 ){
fprintf(stderr, "Usage: %s NUMBER\n", argv[0]);
exit(1);
}
sqlite3_open("x1.db", &db);
v = atoi(argv[1]);
zSql = sqlite3_mprintf("INSERT INTO t1(a) VALUES(%d) RETURNING rowid;", v);
printf("SQL: %s\n", zSql);
sqlite3_prepare(db, zSql, -1, &pStmt, 0);
sqlite3_free(zSql);
rc = sqlite3_step(pStmt);
printf("step returns %d\n", rc);
rc = sqlite3_finalize(pStmt);
printf("finalize returns %d\n", rc);
sqlite3_close(db);
return 0;
}
(11) By Roy Hashimoto (rhashimoto) on 2023-05-19 15:29:42 in reply to 10 [link] [source]
Thanks, that's good to understand.
The application or library needs to either run sqlite3_step() until it completes or else check the return value from sqlite3_finalize() or sqlite3_reset() to see if the INSERT really did complete.
I think the sqlite3_reset() page could mention the behavior for that special case. If sqlite3_step() returns SQLITE_ROW before it would eventually return SQLITE_BUSY, the doc says sqlite3_reset() will return SQLITE_OK:
If the most recent call to sqlite3_step(S) for the prepared statement S returned SQLITE_ROW or SQLITE_DONE, or if sqlite3_step(S) has never before been called on S, then sqlite3_reset(S) returns SQLITE_OK.
(12.2) By Stephan Beal (stephan) on 2023-05-19 17:55:25 edited from 12.1 in reply to 9 [link] [source]
The reason I'm asking is I want to make sure I don't need a similar fix in my own code that calls the SQLite API. Also, I see the WASM OO1 API will skip extra stepping when output isn't needed so I'm wondering whether that needs attention.
FYI, investigating the equivalent in detail for the JS API is on my TODO...
(Edited to reflect changes made after this post...)
In the current trunk, both oo1.Stmt.finalize() and Stmt.reset() will now throw if the underlying sqlite3_finalize/sqlite3_reset() returns non-0. Prior to this change, finalize() ignored non-0 result codes per the long-standing wisdom that "destructors do not throw" and reset() ignored the result due to an oversight on my part.
Per Richard's explanation further down in this thread:
So I think the bug here is in either the application, or in the System.Data.SQLite methods that the application is calling. One or the other of these codes is assuming that if the first call to sqlite3_step() on a DML statement does not return SQLITE_BUSY then the DML statement must have succeeded. This is not true. The application or library needs to either run sqlite3_step() until it completes or else check the return value from sqlite3_finalize() or sqlite3_reset() to see if the INSERT really did complete.
The INSERT RETURNING case described in this thread will now trigger an exception in DB.exec() instead of ignoring the potential SQLITE_LOCKED reported via sqlite3_finalize()/reset(), and similar constructs implemented in client code will trigger an exception via either finalize() or reset() or may actively check the result code of Stmt.finalize() for an error.
These changes will apply as of 3.42.1 and 3.43.
EDIT: Larry has convinced me that having finalize() throw is just plain bad, so the above solution will be reworked so that finalize() no longer throws, but reset() will continue to.