EF Core保存167条关联记录时SaveChanges()异常排查

问题现象 #

• 调用EF Core DbContext的SaveChanges()保存包含167条子记录的新Session时，抛出DbUpdateException，内部异常为System.InvalidOperationException: The CommandText property has not been properly initialized
• 日志显示系统准备批量执行41条更新命令，但实际生成的DbCommand无SQL语句且参数为空；正常执行的DbCommand会在参数后附带INSERT/UPDATE等SQL语句
• 移除任意一条子记录后，SaveChanges()可正常执行，后续即使将子记录增加至186条也无异常

错误日志 #

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)

正常执行的DbCommand示例 #

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 ...

解决方案 #

该问题属于EF Core MySQL驱动批处理组件的边界场景bug，可尝试以下修复方案：

1. 禁用批量处理：
   在DbContext的OnConfiguring方法中关闭批处理功能，强制逐条执行数据库命令：

   protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
   {
       optionsBuilder.UseMySQL("your_connection_string")
                     .UseBatchExecutor(BatchExecutorType.NoBatch);
   }
   

   也可以手动拆分保存批次，将子记录分成若干组，每组调用一次SaveChanges()，比如每100条保存一次。

2. 升级MySQL EF Core驱动：
   该问题大概率是驱动的已知bug，升级到最新稳定版的MySql.EntityFrameworkCore或Pomelo.EntityFrameworkCore.MySql（若使用Pomelo驱动），查看官方更新日志确认是否有相关修复。

3. 检查实体关系配置：
   确认Session与子记录的实体外键、导航属性配置无错误，避免循环引用或特殊配置导致批处理逻辑异常。

内容的提问来源于stack exchange，提问作者Veldaeven