entity-framework-coreef-core-3.1

EF Core: SaveChanges() error when exactly 167 records


The following is the log output from the DbContext:

13:48:54.572 [1]  dbug: 3/6/2024 13:48:54.572 RelationalEventId.BatchReadyForExecution[20700] (Microsoft.EntityFrameworkCore.Update)
13:48:54.574 [1]        Executing 41 update commands as a batch.
13:48:54.575 [1]  dbug: 3/6/2024 13:48:54.575 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
13:48:54.577 [1]        Creating DbCommand for 'ExecuteReader'.
13:48:54.577 [1]  dbug: 3/6/2024 13:48:54.577 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
13:48:54.579 [1]        Created DbCommand for 'ExecuteReader' (2ms).
13:48:54.580 [1]  dbug: 3/6/2024 13:48:54.580 RelationalEventId.CommandInitialized[20106] (Microsoft.EntityFrameworkCore.Database.Command)
13:48:54.582 [1]        Initialized DbCommand for 'ExecuteReader' (5ms).
13:48:54.583 [1]  dbug: 3/6/2024 13:48:54.583 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
13:48:54.584 [1]        Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='86400']
13:48:54.586 [1]
13:48:54.587 [1]  fail: 3/6/2024 13:48:54.587 RelationalEventId.CommandError[20102] (Microsoft.EntityFrameworkCore.Database.Command)
13:48:54.589 [1]        Failed executing DbCommand (4ms) [Parameters=[], CommandType='Text', CommandTimeout='86400']
13:48:54.591 [1]
13:48:54.602 [1]  dbug: 3/6/2024 13:48:54.602 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction)
13:48:54.604 [1]        Disposing transaction.
13:48:54.605 [1]  dbug: 3/6/2024 13:48:54.605 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
13:48:54.607 [1]        Closing connection to database 'vp_mar5' on server 'localhost'.
13:48:54.609 [1]  dbug: 3/6/2024 13:48:54.609 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
13:48:54.611 [1]        Closed connection to database 'vp_mar5' on server 'localhost' (3ms).
13:48:54.618 [1]  fail: 3/6/2024 13:48:54.618 CoreEventId.SaveChangesFailed[10000] (Microsoft.EntityFrameworkCore.Update)
13:48:54.619 [1]        An exception occurred in the database while saving changes for context type 'VisionPlai.VPDatabaseContext'.
13:48:54.621 [1]        Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
13:48:54.624 [1]         ---> System.InvalidOperationException: The CommandText property has not been properly initialized.
13:48:54.625 [1]           at MySql.Data.MySqlClient.Interceptors.ExceptionInterceptor.Throw(Exception exception)
13:48:54.627 [1]           at MySql.Data.MySqlClient.MySqlConnection.Throw(Exception ex)
13:48:54.628 [1]           at MySql.Data.MySqlClient.MySqlCommand.Throw(Exception ex)
13:48:54.629 [1]           at MySql.Data.MySqlClient.MySqlCommand.ExecuteReaderAsync(CommandBehavior behavior, Boolean execAsync, CancellationToken cancellationToken)
13:48:54.632 [1]           at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior)
13:48:54.633 [1]           at MySql.Data.MySqlClient.MySqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
13:48:54.634 [1]           at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
13:48:54.637 [1]           at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
13:48:54.639 [1]           --- End of inner exception stack trace ---
13:48:54.640 [1]           at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
13:48:54.641 [1]           at MySql.EntityFrameworkCore.Update.MySQLModificationCommandBatch.Execute(IRelationalConnection connection)
13:48:54.644 [1]           at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)
13:48:54.646 [1]           at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChanges(IList`1 entries)
13:48:54.647 [1]           at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)
13:48:54.649 [1]           at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(StateManager stateManager, Boolean acceptAllChangesOnSuccess)
13:48:54.651 [1]           at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.<>c.<SaveChanges>b__112_0(DbContext _, ValueTuple`2 t)
13:48:54.653 [1]           at MySql.EntityFrameworkCore.Storage.Internal.MySQLExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
13:48:54.656 [1]           at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)
13:48:54.658 [1]           at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)

For this call to SaveChanges(), there are many other log entries in the form of

12:23:59.077 [1]        Executed DbCommand (6ms) [Parameters=[@p0='2023-12-27T00:00:05.5120000' (DbType = DateTime), @p1='1061', @p2='11603' (Nullable = true), @p3='3', 
12:23:59.725 [1]        INSERT INTO `PlayData` (`date_time`, `playerId`, `Sessionid`, `agentId`, ...
12:23:59.739 [1]        VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10, @p11, @p12 ...

that are all executed properly. In each of these, the [Parameters=[...]] is followed by SQL (inserts, updates, etc). However, on the step causing the error, there is no SQL following the empty parameters [Parameters=[], CommandType='Text', CommandTimeout='86400'] .

The SaveChanges has a single new "Session" record that is inserted into the database. That session has 167 child records in a simple collection.

If I REMOVE any one or a few of the 167 child records, SaveChanges() works perfectly.

So long as I remove at least one record, I can add a few more records (tested up to 20) and the SaveChanges() works fine.

At timestamp 13:48:54.574 the log indicates that it will update 41 records, but then at timestamp 13:48:54.584 the DbCommand does not contain an UPDATE statement.

Some of the 167 records are updated and some are inserted. Whether the removed record is updated or inserted doesn't matter- removing one of either makes SaveChanges() work

Why does arbitrarily changing the count of records resolve the error?


Solution

  • How big (# of columns and size of text columns) is this entity being updated? EF Core will use a default batch size of 42, (since EF Core 5) however if your tables are particularly large in terms of # of columns and length of things like VARCHAR columns this may need to be tweaked downwards to avoid overruns if you have very large tables being updated.

    You can decrease the batch size using in the DbContext .OnConfiguring():

    .MinBatchSize(1)
    .MaxBatchSize(30));
    

    For instance to drop the maximum statements in a batch to 30. Some testing may be necessary to find a "safe" level based on the worst tables, or disable it entirely. (MaxBatchSize(1))

    The typical culprit for issues like this where large tables are necessary is using the Update() method on the DbContext instead of leveraging the change tracking. When you use context.Update(entity) EF core generates an UPDATE statement for every property in the entity, regardless of whether than property actually changed or not. Instead, when updating a set of entities, you are better off reading those entities from the DbContext with tracking enabled (by default) then copy the values across from the detached copies of entities that you were normally passing into the Update calls. The change tracker will then generate UPDATE statements for the entities and only the properties that have actually changed. This will result in much shorter UPDATE statements that won't overflow the statement length limit of the database. This is often overlooked in favour of trying to avoid an extra read from the database, but that read also serves a purpose of validating that the entities about to be updated are actually present, and ensures that only values you intend to actually update are altered. Update(entity) can make your system (particularly web applications) vulnerable to data tampering.