Performance with SQLite and Microsoft.EntityFrameworkCore.Sqlite.Core and SQLitePCLRaw.bundle_e_sqlcipher

[wjvii]

We recently updated an application from EF Core 2.1 to EF Core 3.1 and have noticed that the performance of our queries against SQLite has decreased significantly with simple single table queries taking considerably longer, often just under a full second. The same operations that used to take 7 seconds now take around 75 seconds. Most of these tables are simple with an Integer primary key. We have WAL enabled and during OnConfiguring have run PRAGMA synchronous = 'NORMAL'.

We are continuing to investigate but right now wondering if anyone else has run into something similar and if they found the cause.

Thank you in advance for any insight or suggestions.

Include provider and version information

EF Core version: 3.1.9 and SQLitePCLRaw.bundle_e_sqlcipher 2.0.4
Database provider: Microsoft.EntityFrameworkCore.Sqlite.Core
Target framework: (e.g. .NET Core 3.1)
Operating system: Windows 10 20H2
IDE: (e.g. Visual Studio 2019 16.8)

[wjvii]

We created a small .NET Core console app that demonstrates the performance. After further testing it appears that the Encryption is the culprit. With a non-encrypted database, the queries execute in about 20ms with the encryption enabled the same query takes over 600ms. Out of curiosity we tried it with the latest EF Core 5.0 RC2 and it is even slower at over 900ms.

Is there any way to speed this up and keep the encryption? Any pragma settings that help, any encryption settings that help? We accepted the defaults for everything and made sure WAL was enabled.

Packages used in the last round of tests:

    <PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite.Core" Version="5.0.0-rc.2.20475.6" />
    <PackageReference Include="SQLitePCLRaw.bundle_e_sqlcipher" Version="2.0.4" />

Thank you in advance for any ideas or suggestions.

[wjvii]

We took the same example and dropped back to EF Core 2.2 and the queries, even with encryption, only take about 20ms, similar to the non-encrypted performance. I am now thinking this should be considered a bug.

    <PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite.Core" Version="2.2.6" />
    <PackageReference Include="SQLitePCLRaw.bundle_sqlcipher" Version="1.1.14" />

[ericsink]

"We created a small .NET Core console app that demonstrates the performance."

Can we see it? :-)

[wjvii]

@ericsink , thank you for the quick reply!
Absolutely, give me a few minutes to clean it up and I will attach it here.

[wjvii]

ConsoleSqliteTest.zip
@ericsink here you go. Hope this makes sense, one solution two console apps. It is just a simple case to replicate what we saw in the fact that if we start the console app, put a breakpoint on the dbcontext creation in the Program.cs and then step over each query you can see with EF Core 2.1 after the first one it takes < 20ms on my system. With EF Core 3.1 or 5 it takes 600+ms on my system. Hopefully we are just doing somethng wrong but thank you for looking and I am glad to help in any way I can so please let me know.

[ajcvickers]

@wjvii It appears that in the 2.1 repro, a single SqliteConnection is opened and passed to the DbContext. EF will then use this open connection, rather than opening and closing the connection as happens when a closed connection or a connection string is given to EF Core.

The 5.0 repro, on the other hand, results in the connection being opened and closed repeatedly because an open connection is no longer passed to DbContext. This causes poor perf since opening a connection to an encrypted SQLite database is very slow.

I would recommend limiting the number of times the SQLite connection is opened in the 5.0 case by passing an open connection to the context, or by opening the connection explicitly before running EF queries and closing afterwards so that EF won't be opening and closing the connection for each query. (Keep in mind though that SqliteConnection, like all DbConnection implementations, is not thread-safe.

2.1 Logs:

/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTestEF2/bin/Debug/netcoreapp3.1/ConsoleSqliteTestEF2.dll
dbug: Microsoft.EntityFrameworkCore.Infrastructure[10409]
      An additional 'IServiceProvider' was created for internal use by Entity Framework. An existing service provider was not used due to the following configuration changes: configuration added for 'Sqlite', configuration added for 'Core:UseLoggerFactory', configuration added for 'Core:UseMemoryCache', configuration added for 'Core:EnableSensitiveDataLogging', configuration added for 'Core:EnableDetailedErrors', configuration added for 'Core:ConfigureWarnings'.
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
      Entity Framework Core 2.2.6-servicing-10079 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite' with options: None
dbug: Microsoft.EntityFrameworkCore.Query[10101]
      => Microsoft.EntityFrameworkCore.Query.RelationalQueryModelVisitor
      Compiling query model: 
      '(from TableAnchors testc in DbSet<TableAnchors>
      where [testc].TableName == "FormDefinition"
      select [testc]).FirstOrDefault()'
dbug: Microsoft.EntityFrameworkCore.Query[10104]
      => Microsoft.EntityFrameworkCore.Query.RelationalQueryModelVisitor
      Optimized query model: 
      '(from TableAnchors testc in DbSet<TableAnchors>
      where [testc].TableName == "FormDefinition"
      select [testc]).FirstOrDefault()'
dbug: Microsoft.EntityFrameworkCore.Query[10107]
      => Microsoft.EntityFrameworkCore.Query.RelationalQueryModelVisitor
      (QueryContext queryContext) => IEnumerable<TableAnchors> _InterceptExceptions(
      |__ source: IEnumerable<TableAnchors> _TrackEntities(
      |   |__ results: IEnumerable<TableAnchors> _ToSequence(() => TableAnchors FirstOrDefault(IEnumerable<TableAnchors> _ShapedQuery(
      |   |   |__ queryContext: queryContext, 
      |   |   |__ shaperCommandContext: SelectExpression: 
      |   |   |       SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      |   |   |       FROM "TableAnchors" AS "testc"
      |   |   |       WHERE "testc"."TableName" = 'FormDefinition'
      |   |   |       LIMIT 1, 
      |   |   |__ shaper: (MaterializationContext materializationContext) => 
      |   |       {
      |   |           instance = new TableAnchors()
      |   |           instance.<TableAnchorsID>k__BackingField = int TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 0, TableAnchors.TableAnchorsID)
      |   |           instance.<NextTrxID>k__BackingField = int TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 1, TableAnchors.NextTrxID)
      |   |           instance.<ReceivedAnchor>k__BackingField = DateTime TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 2, TableAnchors.ReceivedAnchor)
      |   |           instance.<SentTrxID>k__BackingField = int TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 3, TableAnchors.SentTrxID)
      |   |           instance.<TableName>k__BackingField = string TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 4, TableAnchors.TableName)
      |   |           return instance
      |   |       }))), 
      |   |__ queryContext: queryContext, 
      |   |__ entityTrackingInfos: { itemType: TableAnchors }, 
      |   |__ entityAccessors: List<Func<TableAnchors, object>> 
      |       { 
      |           Func<TableAnchors, TableAnchors>, 
      |       }), 
      |__ contextType: Entities.TestDbContext, 
      |__ logger: DiagnosticsLogger<Query>, 
      |__ queryContext: queryContext)
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      FROM "TableAnchors" AS "testc"
      WHERE "testc"."TableName" = 'FormDefinition'
      LIMIT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (104ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      FROM "TableAnchors" AS "testc"
      WHERE "testc"."TableName" = 'FormDefinition'
      LIMIT 1
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
      Context 'TestDbContext' started tracking 'TableAnchors' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: Microsoft.EntityFrameworkCore.Query[10101]
      => Microsoft.EntityFrameworkCore.Query.RelationalQueryModelVisitor
      Compiling query model: 
      '(from TableAnchors testc in DbSet<TableAnchors>
      where [testc].TableName == "DocumentImage"
      select [testc]).FirstOrDefault()'
dbug: Microsoft.EntityFrameworkCore.Query[10104]
      => Microsoft.EntityFrameworkCore.Query.RelationalQueryModelVisitor
      Optimized query model: 
      '(from TableAnchors testc in DbSet<TableAnchors>
      where [testc].TableName == "DocumentImage"
      select [testc]).FirstOrDefault()'
dbug: Microsoft.EntityFrameworkCore.Query[10107]
      => Microsoft.EntityFrameworkCore.Query.RelationalQueryModelVisitor
      (QueryContext queryContext) => IEnumerable<TableAnchors> _InterceptExceptions(
      |__ source: IEnumerable<TableAnchors> _TrackEntities(
      |   |__ results: IEnumerable<TableAnchors> _ToSequence(() => TableAnchors FirstOrDefault(IEnumerable<TableAnchors> _ShapedQuery(
      |   |   |__ queryContext: queryContext, 
      |   |   |__ shaperCommandContext: SelectExpression: 
      |   |   |       SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      |   |   |       FROM "TableAnchors" AS "testc"
      |   |   |       WHERE "testc"."TableName" = 'DocumentImage'
      |   |   |       LIMIT 1, 
      |   |   |__ shaper: (MaterializationContext materializationContext) => 
      |   |       {
      |   |           instance = new TableAnchors()
      |   |           instance.<TableAnchorsID>k__BackingField = int TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 0, TableAnchors.TableAnchorsID)
      |   |           instance.<NextTrxID>k__BackingField = int TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 1, TableAnchors.NextTrxID)
      |   |           instance.<ReceivedAnchor>k__BackingField = DateTime TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 2, TableAnchors.ReceivedAnchor)
      |   |           instance.<SentTrxID>k__BackingField = int TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 3, TableAnchors.SentTrxID)
      |   |           instance.<TableName>k__BackingField = string TryReadValue(ValueBuffer materializationContext.get_ValueBuffer(), 4, TableAnchors.TableName)
      |   |           return instance
      |   |       }))), 
      |   |__ queryContext: queryContext, 
      |   |__ entityTrackingInfos: { itemType: TableAnchors }, 
      |   |__ entityAccessors: List<Func<TableAnchors, object>> 
      |       { 
      |           Func<TableAnchors, TableAnchors>, 
      |       }), 
      |__ contextType: Entities.TestDbContext, 
      |__ logger: DiagnosticsLogger<Query>, 
      |__ queryContext: queryContext)
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      FROM "TableAnchors" AS "testc"
      WHERE "testc"."TableName" = 'DocumentImage'
      LIMIT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      FROM "TableAnchors" AS "testc"
      WHERE "testc"."TableName" = 'DocumentImage'
      LIMIT 1
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
      Context 'TestDbContext' started tracking 'TableAnchors' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      FROM "TableAnchors" AS "testc"
      WHERE "testc"."TableName" = 'DocumentImage'
      LIMIT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "testc"."TableAnchorsID", "testc"."NextTrxID", "testc"."ReceivedAnchor", "testc"."SentTrxID", "testc"."TableName"
      FROM "TableAnchors" AS "testc"
      WHERE "testc"."TableName" = 'DocumentImage'
      LIMIT 1
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.

5.0 logs:

net /home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/ConsoleSqliteTest.dll
dbug: Microsoft.EntityFrameworkCore.Infrastructure[10401]
      An 'IServiceProvider' was created for internal use by Entity Framework.
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
      Entity Framework Core 5.0.0-rc.2.20475.6 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite' with options: None
dbug: Microsoft.EntityFrameworkCore.Query[10111]
      Compiling query expression: 
      'DbSet<TableAnchors>()
          .FirstOrDefault(testc => testc.TableName == "FormDefinition")'
dbug: Microsoft.EntityFrameworkCore.Query[10107]
      Generated query execution expression: 
      'queryContext => new SingleQueryingEnumerable<TableAnchors>(
          (RelationalQueryContext)queryContext, 
          RelationalCommandCache.SelectExpression(
              Projection Mapping:
                  EmptyProjectionMember -> Dictionary<IProperty, int> { [Property: TableAnchors.TableAnchorsID (int) Required PK AfterSave:Throw ValueGenerated.OnAdd, 0], [Property: TableAnchors.NextTrxID (int) Required, 1], [Property: TableAnchors.ReceivedAnchor (DateTime) Required, 2], [Property: TableAnchors.SentTrxID (int) Required, 3], [Property: TableAnchors.TableName (string), 4], }
              SELECT TOP(1) t.TableAnchorsID, t.NextTrxID, t.ReceivedAnchor, t.SentTrxID, t.TableName
              FROM TableAnchors AS t
              WHERE t.TableName == 'FormDefinition'), 
          Func<QueryContext, DbDataReader, ResultContext, SingleQueryResultCoordinator, TableAnchors>, 
          Entities.TestDbContext, 
          False, 
          False
      )
          .SingleOrDefault()'
dbug: Microsoft.EntityFrameworkCore.Database.Command[20103]
      Creating DbCommand for 'ExecuteReader'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20104]
      Created DbCommand for 'ExecuteReader' (6ms).
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20000]
      Opening connection to database 'main' on server 'EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20001]
      Opened connection to database 'main' on server '/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "t"."TableAnchorsID", "t"."NextTrxID", "t"."ReceivedAnchor", "t"."SentTrxID", "t"."TableName"
      FROM "TableAnchors" AS "t"
      WHERE "t"."TableName" = 'FormDefinition'
      LIMIT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (3ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "t"."TableAnchorsID", "t"."NextTrxID", "t"."ReceivedAnchor", "t"."SentTrxID", "t"."TableName"
      FROM "TableAnchors" AS "t"
      WHERE "t"."TableName" = 'FormDefinition'
      LIMIT 1
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
      Context 'TestDbContext' started tracking 'TableAnchors' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20002]
      Closing connection to database 'main' on server '/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20003]
      Closed connection to database 'main' on server 'EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Query[10111]
      Compiling query expression: 
      'DbSet<TableAnchors>()
          .FirstOrDefault(testc => testc.TableName == "DocumentImage")'
dbug: Microsoft.EntityFrameworkCore.Query[10107]
      Generated query execution expression: 
      'queryContext => new SingleQueryingEnumerable<TableAnchors>(
          (RelationalQueryContext)queryContext, 
          RelationalCommandCache.SelectExpression(
              Projection Mapping:
                  EmptyProjectionMember -> Dictionary<IProperty, int> { [Property: TableAnchors.TableAnchorsID (int) Required PK AfterSave:Throw ValueGenerated.OnAdd, 0], [Property: TableAnchors.NextTrxID (int) Required, 1], [Property: TableAnchors.ReceivedAnchor (DateTime) Required, 2], [Property: TableAnchors.SentTrxID (int) Required, 3], [Property: TableAnchors.TableName (string), 4], }
              SELECT TOP(1) t.TableAnchorsID, t.NextTrxID, t.ReceivedAnchor, t.SentTrxID, t.TableName
              FROM TableAnchors AS t
              WHERE t.TableName == 'DocumentImage'), 
          Func<QueryContext, DbDataReader, ResultContext, SingleQueryResultCoordinator, TableAnchors>, 
          Entities.TestDbContext, 
          False, 
          False
      )
          .SingleOrDefault()'
dbug: Microsoft.EntityFrameworkCore.Database.Command[20103]
      Creating DbCommand for 'ExecuteReader'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20104]
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20000]
      Opening connection to database 'main' on server 'EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20001]
      Opened connection to database 'main' on server '/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "t"."TableAnchorsID", "t"."NextTrxID", "t"."ReceivedAnchor", "t"."SentTrxID", "t"."TableName"
      FROM "TableAnchors" AS "t"
      WHERE "t"."TableName" = 'DocumentImage'
      LIMIT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "t"."TableAnchorsID", "t"."NextTrxID", "t"."ReceivedAnchor", "t"."SentTrxID", "t"."TableName"
      FROM "TableAnchors" AS "t"
      WHERE "t"."TableName" = 'DocumentImage'
      LIMIT 1
dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10806]
      Context 'TestDbContext' started tracking 'TableAnchors' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20002]
      Closing connection to database 'main' on server '/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20003]
      Closed connection to database 'main' on server 'EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20103]
      Creating DbCommand for 'ExecuteReader'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20104]
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20000]
      Opening connection to database 'main' on server 'EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20001]
      Opened connection to database 'main' on server '/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Command[20100]
      Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "t"."TableAnchorsID", "t"."NextTrxID", "t"."ReceivedAnchor", "t"."SentTrxID", "t"."TableName"
      FROM "TableAnchors" AS "t"
      WHERE "t"."TableName" = 'DocumentImage'
      LIMIT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "t"."TableAnchorsID", "t"."NextTrxID", "t"."ReceivedAnchor", "t"."SentTrxID", "t"."TableName"
      FROM "TableAnchors" AS "t"
      WHERE "t"."TableName" = 'DocumentImage'
      LIMIT 1
dbug: Microsoft.EntityFrameworkCore.Database.Command[20300]
      A data reader was disposed.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20002]
      Closing connection to database 'main' on server '/home/ajcvickers/Repros/ConsoleSqliteTest/ConsoleSqliteTest/bin/Debug/netcoreapp3.1/EFV3.db'.
dbug: Microsoft.EntityFrameworkCore.Database.Connection[20003]
      Closed connection to database 'main' on server 'EFV3.db'.

[wjvii]

@ajcvickers that is some excellent sleuthing. So when I new up a DbContext what is the recommended way to tell it I do not wish it to close the connection between uses? The way it was done for 2.1 was really done to handle the password via the Pragma which is now done in the connection string thanks to the new Microsoft.Data.Sqlite.

[ajcvickers]

@wjvii In general, if you open the connection, then EF will leave it open. So the way to get EF to not open/close the connection is to manually open the connection at the appropriate time (based on your application needs) and then manually close it after having EF do stuff.

[wjvii]

@ajcvickers that worked great. I just created the DbContext as db and then used db.Database.OpenConnection() and if I didn't close it performance is back where I expected it to be.

One more question for you, that debug output is awesome, is there an article you can point me to on how-to setup to get that output from EF 3.1 and 5?

Thank you again, this was a huge help!

[ajcvickers]

@wjvii I'm currently working on updated docs for logging--this PR is a good place to look until we get this merged live: dotnet/EntityFramework.Docs#2787

[iplusMario]

We are currently testing encrypted SQLite and we are experiencing slow performance (500 ms for commiting transaction) when inserting into database.
Any idea what could be causing this slow performance on encrypted SQLite database?

dbug: 8/18/2022 08:20:39.382 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking)
      'TestDBContext' generated temporary value '-9223372036854774805' for the property 'DrawCardId.DrawCard'.
dbug: 8/18/2022 08:20:39.382 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'TestDBContext' started tracking 'DrawCard' entity with key '{DrawCardId: -9223372036854774805}'.
dbug: 8/18/2022 08:20:39.383 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update)
      SaveChanges starting for 'TestDBContext'.
dbug: 8/18/2022 08:20:39.383 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges starting for 'TestDBContext'.
dbug: 8/18/2022 08:20:39.383 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking)
      DetectChanges completed for 'TestDBContext'.
dbug: 8/18/2022 08:20:39.384 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'main' on server 'TestDatabase.db'.
dbug: 8/18/2022 08:20:39.384 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'main' on server 'TestDatabase.db'.
dbug: 8/18/2022 08:20:39.384 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Beginning transaction with isolation level 'Unspecified'.
dbug: 8/18/2022 08:20:39.385 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Began transaction with isolation level 'Serializable'.
dbug: 8/18/2022 08:20:39.385 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 8/18/2022 08:20:39.385 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 8/18/2022 08:20:39.386 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@p0='1', @p1='52', @p2=NULL, @p3='2022-08-18T06:20:39.3822396Z' (DbType = DateTime), @p4='1', @p5='3', @p6='1'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "DrawCard" ("DrawId", "Card", "ChangeUser", "DrawDate", "Hand", "Index", "Status")
      VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6);
      SELECT "DrawCardId", "ChangeDate"
      FROM "DrawCard"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
info: 8/18/2022 08:20:39.386 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (1ms) [Parameters=[@p0='1', @p1='52', @p2=NULL, @p3='2022-08-18T06:20:39.3822396Z' (DbType = DateTime), @p4='1', @p5='3', @p6='1'], CommandType='Text', CommandTimeout='30']
      INSERT INTO "DrawCard" ("DrawId", "Card", "ChangeUser", "DrawDate", "Hand", "Index", "Status")
      VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6);
      SELECT "DrawCardId", "ChangeDate"
      FROM "DrawCard"
      WHERE changes() = 1 AND "rowid" = last_insert_rowid();
dbug: 8/18/2022 08:20:39.387 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The foreign key property 'DrawCard.DrawCardId' was detected as changed from '-9223372036854774805' to '3' for entity with key '{DrawCardId: 3}'.
dbug: 8/18/2022 08:20:39.388 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
- dbug: 8/18/2022 08:20:39.388 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
- dbug: 8/18/2022 08:20:39.856 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.
dbug: 8/18/2022 08:20:39.856 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'main' on server 'TestDatabase.db'.
dbug: 8/18/2022 08:20:39.857 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'main' on server 'TestDatabase.db'.
dbug: 8/18/2022 08:20:39.858 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Disposing transaction.
dbug: 8/18/2022 08:20:39.858 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking)
      The 'DrawCard' entity with key '{DrawCardId: 3}' tracked by 'TestDBContext' changed state from 'Added' to 'Unchanged'.
dbug: 8/18/2022 08:20:39.858 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 and SQLitePCLRaw.bundle_e_sqlcipher 2.1.0
Database provider: Microsoft.EntityFrameworkCore.Sqlite.Core 6.0.8
Target framework: (e.g. .NET Core 6.0)
Operating system: Windows 10
IDE: (e.g. Visual Studio 2022)

[ajcvickers]

@iplusMario If you believe this is an issue with EF Core or the ADO.NET driver, as opposed to with SQLite itself, then please open a new issue and attach a small, runnable project or post a small, runnable code listing that reproduces what you are seeing so that we can investigate.

[iplusMario]

@iplusMario If you believe this is an issue with EF Core or the ADO.NET driver, as opposed to with SQLite itself, then please open a new issue and attach a small, runnable project or post a small, runnable code listing that reproduces what you are seeing so that we can investigate.

Thank you for your answer. I opened new a issue https://github.com/dotnet/efcore/issues/28774.