EF 5 Timeout on Update; Possibly due to deadlock

Question

I have a command-line tool for performing bulk import/export of data records via Entity Framework into an application database. The tool works well for inserting new records into the database, but I've been encountering timeout error when trying to update existing records which seem to be related to EF locking.

I have read some of the many other posts about Entity Framework and deadlocks, but none of the answers seem to apply to this situation. I have tried wrapping my import code within a TransactionScope as well as executing a SET TRANSACTION ISOLATION LEVEL SQL command, but neither addresses the timeout.

The timeout happens regardless of how many entities are being updated in a single call to SaveChanges. In the sample code below, I have set the batch size to values between 1 and 500, always with the same exception being thrown.

Here is a condensed version of the update code, followed by the exception details and a screenshot of the SQL Server Activity monitor.

I am using Entity Framework 5 DbContext objects which are initialized from EDMX models (Model First).

using(var readContext = new MySourceEntities())
using(var readWriteContext = new MyTargetEntities())
{
    var query = "SELECT ...";  // Determine which records to update
    var keys  = readContext.Database.SQLQuery<int>(query);

    // Group the update into batches to improve performance. Batch()
    // extension method from MoreLINQ
    foreach (var batch in keys.Batch(BATCH_SIZE))
    {
        var sourceRecords = readContext
            .AsNoTracking()
            .Where(x => batch.Contains(x.SharedId))
            .ToList();

        var targetRecords = readWriteContext
            .Where(x => batch.Contains(x.SharedId))
            .ToLookup(x => x.SharedId);

        foreach (var record in sourceRecords)
        {
            // Enforce a constraint on having only a single match
            var target = targetRecords[record.SharedId].Single();

            target.Field = record.Field;
        }

        readWriteContext.SaveChanges();  // <--- Timeout happens here
    }
}

I am running this from a command line application, and the specific stack trace that it throws up is as follows:

An error occurred while updating the entries. See the inner exception for details.
   at System.Data.Entity.Internal.InternalContext.SaveChanges()
   at System.Data.Entity.Internal.LazyInternalContext.SaveChanges()
   at System.Data.Entity.DbContext.SaveChanges()
   at <snip>

An error occurred while updating the entries. See the inner exception for details.
   at System.Data.Mapping.Update.Internal.UpdateTranslator.Update(IEntityStateManager stateManager, IEntityAdapter adapter)
   at System.Data.EntityClient.EntityAdapter.Update(IEntityStateManager entityCache)
   at System.Data.Objects.ObjectContext.SaveChanges(SaveOptions options)
   at System.Data.Entity.Internal.InternalContext.SaveChanges()

Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. The statement has been terminated.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
   at System.Data.Mapping.Update.Internal.DynamicUpdateCommand.Execute(UpdateTranslator translator, EntityConnection connection, Dictionary`2 identifierValues, List`1 generatedValues)
   at System.Data.Mapping.Update.Internal.UpdateTranslator.Update(IEntityStateManager stateManager, IEntityAdapter adapter)

While the SaveChanges method is hanging, the SQL Server Activity Monitor shows the following queries, all in a SUSPENDED state. The red queries are from the database targeted by the readContext and the blue queries are from the database targeted by the readWriteContext.

Also, the suspended queried themselves do not look suspicious, just straighforward SELECT and UPDATE command. I am able to run them manually without errors.

Edit

Here are the details of the query clause that is run, since it seems to be pertinent. The query performs a joins across databases to match up records with the SharedId. Running the sys.dm_os_waiting_tasks query from this page, gives the following table.

session_id wait_duration_ms wait_type         blocking_session_id resource_description program_name    text
55         15               ASYNC_NETWORK_IO  NULL                NULL                 EntityFramework <cross-db join query>
54         29310            LCK_M_IX          55                  pagelock fileid=1... EntityFramework <update query>

The content of the query is like this

SELECT DB1.dbo.Table1.SharedId 
FROM DB2.dbo.Table2 INNER JOIN DB1.dbo.Table1.SharedId
ON DB1.dbo.Table1.SharedId = DB2.dbo.Table2.SharedId
WHERE (
    (DB1.dbo.Table1.Field1 <> DB2.dbo.Table2.Field1) OR
    (DB1.dbo.Table1.Field2 <> DB2.dbo.Table2.Field2)
)

The most surprising observation to me is that the query is still active. Any ideas why the readContext.Database.SQLQuery() call would not complete the query? It sounds like this wait type usually indicates an application error, but I'm unsure how I am triggering this behavior.

Answer 1

The solution was to materialize the results from the SQLQuery() explicitly using a ToList() extension method. This allowed the results to be fully consumed before attempting to UPDATE the underlying tables.

It was surprising (to me) that a direct SQL command did not return the full result immediately -- especially since the query was returning a primitive type and not an Entity object. Upon closer reading of the MSDN documentation, it does state that the IEnumerable<T> returned by the SQLQuery method, "will execute the query when it is enumerated".

I like that in EF6, this method returns a DbRawSqlQuery<T> object, which probably will help people like myself stop and read the documentation a little more carefully next time.