Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Slow performance when commiting transaction to SQLite encrypted file #28774

Closed
iplusMario opened this issue Aug 18, 2022 · 12 comments · Fixed by #28966
Closed

Slow performance when commiting transaction to SQLite encrypted file #28774

iplusMario opened this issue Aug 18, 2022 · 12 comments · Fixed by #28966
Assignees
@bricelam
Labels
area-adonet-sqlite area-perf closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. customer-reported type-bug
Milestone
7.0.0

Comments

@iplusMario
Copy link

iplusMario commented Aug 18, 2022 •
edited
Loading

We are currently testing encrypted SQLite and we are experiencing slow performance (about 500 ms for commiting transaction) when inserting into database.

info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
      Entity Framework Core 6.0.8 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite:6.0.8' with options: MaxPoolSize=1024
info: 18. 08. 2022 13:49:11.936 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure)
      Entity Framework Core 6.0.8 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite:6.0.8' with options: MaxPoolSize=1024
dbug: 18. 08. 2022 13:49:11.987 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:12.466 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:12.470 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.063 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.064 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.066 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.070 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.072 RelationalEventId.ConnectionError[20004] (Microsoft.EntityFrameworkCore.Database.Connection)
      An error occurred using the connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.073 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.073 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.078 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteNonQuery'.
dbug: 18. 08. 2022 13:49:13.080 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteNonQuery' (2ms).
dbug: 18. 08. 2022 13:49:13.082 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      PRAGMA journal_mode = 'wal';
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (596ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      PRAGMA journal_mode = 'wal';
info: 18. 08. 2022 13:49:13.680 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (596ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      PRAGMA journal_mode = 'wal';
dbug: 18. 08. 2022 13:49:13.680 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.681 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:13.733 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:13.734 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:13.752 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.214 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.216 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 18. 08. 2022 13:49:14.217 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 18. 08. 2022 13:49:14.218 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteNonQuery'.
dbug: 18. 08. 2022 13:49:14.218 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteNonQuery' (0ms).
dbug: 18. 08. 2022 13:49:14.218 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      CREATE TABLE "TestModel" (
          "DrawId" INTEGER NOT NULL CONSTRAINT "PK_TestModel" PRIMARY KEY AUTOINCREMENT,
          "ChangeUser" TEXT NULL,
          "ChangeDate" AS (DATETIME()) STORED
      );
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      CREATE TABLE "TestModel" (
          "DrawId" INTEGER NOT NULL CONSTRAINT "PK_TestModel" PRIMARY KEY AUTOINCREMENT,
          "ChangeUser" TEXT NULL,
          "ChangeDate" AS (DATETIME()) STORED
      );
info: 18. 08. 2022 13:49:14.219 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      CREATE TABLE "TestModel" (
          "DrawId" INTEGER NOT NULL CONSTRAINT "PK_TestModel" PRIMARY KEY AUTOINCREMENT,
          "ChangeUser" TEXT NULL,
          "ChangeDate" AS (DATETIME()) STORED
      );
+ dbug: 18. 08. 2022 13:49:14.221 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
+ dbug: 18. 08. 2022 13:49:14.227 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 18. 08. 2022 13:49:14.227 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 18. 08. 2022 13:49:14.228 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.228 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.251 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking)
      'TestDbContext' generated a temporary value for the property 'DrawId.TestModel'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 18. 08. 2022 13:49:14.280 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'TestDbContext' started tracking 'TestModel' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 18. 08. 2022 13:49:14.284 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges starting for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:14.284 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:14.288 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:14.300 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.301 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.302 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 18. 08. 2022 13:49:14.304 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 18. 08. 2022 13:49:14.332 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 18. 08. 2022 13:49:14.332 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 18. 08. 2022 13:49:14.337 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeUser")
      VALUES (@p0);
      SELECT "DrawId", "ChangeDate"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: 18. 08. 2022 13:49:14.339 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (4ms) [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeUser")
      VALUES (@p0);
      SELECT "DrawId", "ChangeDate"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (4ms) [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeUser")
      VALUES (@p0);
      SELECT "DrawId", "ChangeDate"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
dbug: 18. 08. 2022 13:49:14.364 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The foreign key property 'TestModel.DrawId' was detected as changed. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values.
dbug: 18. 08. 2022 13:49:14.371 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
- dbug: 18. 08. 2022 13:49:14.373 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
- dbug: 18. 08. 2022 13:49:14.834 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 18. 08. 2022 13:49:14.836 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.837 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:14.840 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 18. 08. 2022 13:49:14.846 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking)
      An entity of type 'TestModel' tracked by 'TestDbContext' changed state from 'Added' to 'Unchanged'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 18. 08. 2022 13:49:14.847 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges completed for 'TestDbContext' with 1 entities written to the database.
dbug: 18. 08. 2022 13:49:54.918 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking)
      'TestDbContext' generated a temporary value for the property 'DrawId.TestModel'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 18. 08. 2022 13:49:54.925 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'TestDbContext' started tracking 'TestModel' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 18. 08. 2022 13:49:54.927 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges starting for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:54.928 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:54.930 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDbContext'.
dbug: 18. 08. 2022 13:49:54.931 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:54.931 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:54.932 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 18. 08. 2022 13:49:54.932 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 18. 08. 2022 13:49:54.933 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 18. 08. 2022 13:49:54.934 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 18. 08. 2022 13:49:54.935 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeUser")
      VALUES (@p0);
      SELECT "DrawId", "ChangeDate"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: 18. 08. 2022 13:49:54.936 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (2ms) [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeUser")
      VALUES (@p0);
      SELECT "DrawId", "ChangeDate"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (2ms) [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeUser")
      VALUES (@p0);
      SELECT "DrawId", "ChangeDate"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
dbug: 18. 08. 2022 13:49:54.940 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The foreign key property 'TestModel.DrawId' was detected as changed. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values.
dbug: 18. 08. 2022 13:49:54.951 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
- dbug: 18. 08. 2022 13:49:54.952 RelationalEventId.TransactionCommitting[20210] - -(Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
- dbug: 18. 08. 2022 13:49:55.457 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 18. 08. 2022 13:49:55.457 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\TestDatabase.db'.
dbug: 18. 08. 2022 13:49:55.459 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'main' on server 'TestDatabase.db'.
dbug: 18. 08. 2022 13:49:55.463 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 18. 08. 2022 13:49:55.463 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking)
      An entity of type 'TestModel' tracked by 'TestDbContext' changed state from 'Added' to 'Unchanged'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 18. 08. 2022 13:49:55.465 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges completed for 'TestDbContext' with 1 entities written to the database.

P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\EFCoreEncryptionTest.exe (process 49672) exited with code -1.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.

Press any key to close this window . . .

Include provider and version information

Include provider and version information
EF Core version: 6.0
Database provider: Microsoft.EntityFrameworkCore.Sqlite.Core 6.0.8 and SQLitePCLRaw.bundle_e_sqlcipher 2.1.0
Target framework: NET Core 6.0
Operating system: Windows 10
IDE: Visual Studio 2022

Simple test project
EFCoreEncryptionTest.zip
@ajcvickers
Copy link
Member

@iplusMario Is the performance significantly better when you don't use EF?

@ericsink
Copy link

Are you opening and closing the db connection for each transaction? That is a performance killer with sqlcipher.

@ajcvickers
Copy link
Member

@ericsink We have connection pooling by default now, so this shouldn't be an issue in a typical app.

@bricelam bricelam mentioned this issue Aug 18, 2022
Closed
@bricelam
Copy link
Contributor

Hmm, I thought we had an issue to investigate this, but I can't seem to find it.

@bricelam
Copy link
Contributor

My theory is that sending the PRAGMA key statement again after we retrieve the internal connection from the pool is causing it to re-derive the encryption key making it just as slow as before pooling. Sending PRAGMA key shouldn't be required in this situation and we should avoid sending it.

@iplusMario
Copy link
Author

We have now tried encrypting the SQLite database with SQLitePCLRaw.bundle_zetetic 2.1.0 and the zetetic-sqlcipher-windows 4.5.2 driver.
We noticed in the logs that the connection to the database is not terminated after each query execution.
If you look at the log above, you will see that the connection is terminated after each query execution.

info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
      Entity Framework Core 6.0.8 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite:6.0.8' with options: None
info: 19. 08. 2022 09:24:03.792 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure)
      Entity Framework Core 6.0.8 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite:6.0.8' with options: None
dbug: 19. 08. 2022 09:24:03.866 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'Test1Database.db'.
dbug: 19. 08. 2022 09:24:03.868 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'P:\C#Projects\EFCoreEncryptionTest\bin\Debug\net6.0\Test1Database.db'.
dbug: 19. 08. 2022 09:24:03.876 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteScalar'.
dbug: 19. 08. 2022 09:24:03.878 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteScalar' (2ms).
dbug: 19. 08. 2022 09:24:03.881 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*) FROM "sqlite_master" WHERE "type" = 'table' AND "rootpage" IS NOT NULL;
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (168ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*) FROM "sqlite_master" WHERE "type" = 'table' AND "rootpage" IS NOT NULL;
info: 19. 08. 2022 09:24:04.051 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (168ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*) FROM "sqlite_master" WHERE "type" = 'table' AND "rootpage" IS NOT NULL;
dbug: 19. 08. 2022 09:24:04.073 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking)
      'TestDbContext' generated a temporary value for the property 'DrawId.TestModel'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.101 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'TestDbContext' started tracking 'TestModel' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.103 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges starting for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.104 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.109 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.116 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 19. 08. 2022 09:24:04.118 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 19. 08. 2022 09:24:04.151 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 19. 08. 2022 09:24:04.151 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 19. 08. 2022 09:24:04.155 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (8ms) [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: 19. 08. 2022 09:24:04.161 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (8ms) [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
dbug: 19. 08. 2022 09:24:04.173 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The foreign key property 'TestModel.DrawId' was detected as changed. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values.
dbug: 19. 08. 2022 09:24:04.178 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 19. 08. 2022 09:24:04.179 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
dbug: 19. 08. 2022 09:24:04.182 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 19. 08. 2022 09:24:04.183 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 19. 08. 2022 09:24:04.190 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking)
      An entity of type 'TestModel' tracked by 'TestDbContext' changed state from 'Added' to 'Unchanged'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.191 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges completed for 'TestDbContext' with 1 entities written to the database.
dbug: 19. 08. 2022 09:24:04.193 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking)
      'TestDbContext' generated a temporary value for the property 'DrawId.TestModel'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.195 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'TestDbContext' started tracking 'TestModel' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.195 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges starting for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.195 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.195 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.195 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 19. 08. 2022 09:24:04.195 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 19. 08. 2022 09:24:04.196 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 19. 08. 2022 09:24:04.196 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 19. 08. 2022 09:24:04.199 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (2ms) [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: 19. 08. 2022 09:24:04.201 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (2ms) [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
dbug: 19. 08. 2022 09:24:04.205 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The foreign key property 'TestModel.DrawId' was detected as changed. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values.
dbug: 19. 08. 2022 09:24:04.205 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 19. 08. 2022 09:24:04.206 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
dbug: 19. 08. 2022 09:24:04.208 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 19. 08. 2022 09:24:04.208 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 19. 08. 2022 09:24:04.209 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking)
      An entity of type 'TestModel' tracked by 'TestDbContext' changed state from 'Added' to 'Unchanged'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.218 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges completed for 'TestDbContext' with 1 entities written to the database.
dbug: 19. 08. 2022 09:24:04.219 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking)
      'TestDbContext' generated a temporary value for the property 'DrawId.TestModel'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.220 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'TestDbContext' started tracking 'TestModel' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.220 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges starting for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.221 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.221 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDbContext'.
dbug: 19. 08. 2022 09:24:04.221 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 19. 08. 2022 09:24:04.222 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 19. 08. 2022 09:24:04.222 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 19. 08. 2022 09:24:04.222 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 19. 08. 2022 09:24:04.223 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (1ms) [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: 19. 08. 2022 09:24:04.224 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (1ms) [Parameters=[@p0='?' (DbType = DateTime), @p1='?' (Size = 4)], CommandType='Text', CommandTimeout='30']
      INSERT INTO "TestModel" ("ChangeDate", "ChangeUser")
      VALUES (@p0, @p1);
      SELECT "DrawId"
      FROM "TestModel"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
dbug: 19. 08. 2022 09:24:04.230 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The foreign key property 'TestModel.DrawId' was detected as changed. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values.
dbug: 19. 08. 2022 09:24:04.234 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 19. 08. 2022 09:24:04.236 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
dbug: 19. 08. 2022 09:24:04.239 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 19. 08. 2022 09:24:04.245 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 19. 08. 2022 09:24:04.245 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking)
      An entity of type 'TestModel' tracked by 'TestDbContext' changed state from 'Added' to 'Unchanged'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: 19. 08. 2022 09:24:04.246 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges completed for 'TestDbContext' with 1 entities written to the database.

Include provider and version information
EF Core version: 6.0
Database provider: Microsoft.EntityFrameworkCore.Sqlite.Core 6.0.8, SQLitePCLRaw.bundle_zetetic 2.1.0 and zetetic-sqlcipher-windows 4.5.2
Target framework: NET Core 6.0
Operating system: Windows 10
IDE: Visual Studio 2022

@ajcvickers ajcvickers added this to the 7.0.0 milestone Aug 30, 2022
@bricelam
Copy link
Contributor

bricelam commented Sep 2, 2022

Confirmed. Re-sending PRAGMA key is slowing it waaaay down. I'll prepare a fix and discuss with the team whether we should patch 6.0.

/cc @james1301 @LauraLaura (Sorry it took so long to investigate this.)

@bricelam bricelam mentioned this issue Sep 2, 2022
Merged
@bricelam bricelam added the closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. label Sep 2, 2022
@bricelam bricelam mentioned this issue Sep 2, 2022
Closed
@bricelam bricelam modified the milestones: 7.0.0, 7.0.0-rc2 Sep 2, 2022
@james1301
Copy link

Thanks @bricelam, any outcome about patching 6.0? Would be a big boost 🙂

@ajcvickers
Copy link
Member

@james1301 We plan to bring this to 6.0, but it needs to go through the internal process and get approved first.

@james1301
Copy link

james1301 commented Sep 12, 2022 •
edited
Loading

@ajcvickers awesome thanks for the update. And now I have actually seen that other issue for 6.0 so apologies for me being a bit blind 🙂

@rgroenewoudt rgroenewoudt mentioned this issue Sep 28, 2022
Open
@ajcvickers ajcvickers modified the milestones: 7.0.0-rc2, 7.0.0 Nov 5, 2022
@iplusMario
Copy link
Author

@bricelam After your commits were merged in 6.0.11 the Database.Migrate() fails with dll error stated below.

'Attempted to read or write protected memory. This is often an indication that other memory is corrupt.'

Simple test project
In EFCoreEncryptionTest.zip update entity framework nuget packages to a version > 6.0.10 and in TestDbContext add Database.Migrate() and you will get Unhandeled execption.

@roji
Copy link
Member

roji commented Jan 30, 2023

@iplusMario can you please open a new issue?

@iplusMario iplusMario mentioned this issue Jan 31, 2023
Closed
@bricelam bricelam mentioned this issue Apr 4, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bricelam bricelam

Labels
area-adonet-sqlite area-perf closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. customer-reported type-bug
Projects
None yet
Milestone
7.0.0
Development

Successfully merging a pull request may close this issue.

Microsoft.Data.Sqlite: Avoid re-initialization of pooled connections bricelam/efcore
6 participants
@bricelam @ajcvickers @roji @ericsink @james1301 @iplusMario