sql-serversql-execution-plansql-server-2019

Simple insert times out in application, but fast in SSMS


In my application I have a simple insert, when captured with profiler it looks like this

insert into ford.tblFordCompoundFlowVehicle
  (FordCompoundFlowID, CompoundVehicleID, SortOrder, Status1ToSend, Status2ToSend, FordFlowTriggerID, SendTriggerSatisfied, DateSend, FordCompoundFlowDefinitionID)
select fcfd.FordCompoundFlowID, 
       9711, 
       fcfdd.SortOrder, 
       fcfdd.Status1ToSend, 
       fcfdd.Status2ToSend, 
       fcfdd.FordFlowTriggerID, 
       0, 
       null,
       2
from   ford.tblFordCompoundFlowDefinitionDetail fcfdd
  inner join ford.tblFordCompoundFlowDefinition fcfd on fcfdd.FordCompoundFlowDefinitionID = fcfd.FordCompoundFlowDefinitionID 
where  fcfdd.FordCompoundFlowDefinitionID = 2
order by fcfdd.SortOrder

This is sent to the database using Dapper like this

 string sql =
     $"""
     insert into ford.tblFordCompoundFlowVehicle
       (FordCompoundFlowID, CompoundVehicleID, SortOrder, Status1ToSend, Status2ToSend, FordFlowTriggerID, SendTriggerSatisfied, DateSend, FordCompoundFlowDefinitionID)
     select fcfd.FordCompoundFlowID, 
            {compoundVehicleID}, 
            fcfdd.SortOrder, 
            fcfdd.Status1ToSend, 
            fcfdd.Status2ToSend, 
            fcfdd.FordFlowTriggerID, 
            0, 
            null,
            {fordCompoundFlowDefinitionID}
     from   ford.tblFordCompoundFlowDefinitionDetail fcfdd
       inner join ford.tblFordCompoundFlowDefinition fcfd on fcfdd.FordCompoundFlowDefinitionID = fcfd.FordCompoundFlowDefinitionID 
     where  fcfdd.FordCompoundFlowDefinitionID = {fordCompoundFlowDefinitionID.Value}
     order by fcfdd.SortOrder 
     OPTION(RECOMPILE)
     """;

 connection.Execute(sql, null, transaction);

I did not use an SqlCommand to keep this code a bit shorter, also the values are all int so SQL injection would be difficult anyway.

Now for the problem, when this query runs it takes so long it times out, but when I capture the query in profiler and run it in SSMS it is very fast.

I also tried the option OPTION(RECOMPILE) in the application, but it does not help

Execution Plans:
So I got the execution plan from SSMS
and captured the slow application plan from Activity monitor

I do not have the knowledge myself to compare these plans and see the problem, so I am hoping someone here can compare them and help me point out the problem.

The transaction is done like this

 using (SqlConnection connection = new SqlConnection(ConnectionString))
 {
     connection.Open();

     using (SqlTransaction transaction =  connection.BeginTransaction())
     {
         try
         {
             fordCompoundFlowDefinitionID = CreateFordCompoundFlowVehicle(connection, transaction, compoundVehicleID);
             transaction.Commit();
         }
         catch (Exception ex)
         { 
             transaction.Rollback();
             throw;
         }
     }
 }
private int? CreateFordCompoundFlowVehicle(SqlConnection connection, SqlTransaction transaction, int compoundVehicleID)
{
    int? result = null;

    // check if there is any importdata for this compoundvehicleid, if not than it stops right here
    int? fordCompoundFlowDefinitionID = GetFordCompoundFlowDefinitionID(connection, transaction, compoundVehicleID);

    if (fordCompoundFlowDefinitionID.HasValue)
    {
        string sql =
            $"""
            insert into ford.tblFordCompoundFlowVehicle
              (FordCompoundFlowID, CompoundVehicleID, SortOrder, Status1ToSend, Status2ToSend, FordFlowTriggerID, SendTriggerSatisfied, DateSend, FordCompoundFlowDefinitionID)
            select fcfd.FordCompoundFlowID, 
                   {compoundVehicleID}, 
                   fcfdd.SortOrder, 
                   fcfdd.Status1ToSend, 
                   fcfdd.Status2ToSend, 
                   fcfdd.FordFlowTriggerID, 
                   0, 
                   null,
                   {fordCompoundFlowDefinitionID}
            from   ford.tblFordCompoundFlowDefinitionDetail fcfdd
              inner join ford.tblFordCompoundFlowDefinition fcfd on fcfdd.FordCompoundFlowDefinitionID = fcfd.FordCompoundFlowDefinitionID 
            where  fcfdd.FordCompoundFlowDefinitionID = {fordCompoundFlowDefinitionID.Value}
            order by fcfdd.SortOrder 
            OPTION(RECOMPILE)
            """;

        -- THIS TIMES OUT
        connection.Execute(sql, null, transaction);

        result = fordCompoundFlowDefinitionID;
    }

    return result;
}

I altered the code to a parametrized query as suggested, but get the same result

                string sql =
                    """
                    insert into ford.tblFordCompoundFlowVehicle
                      (FordCompoundFlowID, CompoundVehicleID, SortOrder, Status1ToSend, Status2ToSend, FordFlowTriggerID, SendTriggerSatisfied, DateSend, FordCompoundFlowDefinitionID)
                    select fcfd.FordCompoundFlowID, 
                           @CompoundVehicleID, 
                           fcfdd.SortOrder, 
                           fcfdd.Status1ToSend, 
                           fcfdd.Status2ToSend, 
                           fcfdd.FordFlowTriggerID, 
                           0, 
                           null,
                           @FordCompoundFlowDefinitionID
                    from   ford.tblFordCompoundFlowDefinitionDetail fcfdd
                      inner join ford.tblFordCompoundFlowDefinition fcfd on fcfdd.FordCompoundFlowDefinitionID = fcfd.FordCompoundFlowDefinitionID 
                    where  fcfdd.FordCompoundFlowDefinitionID = @FordCompoundFlowDefinitionID
                    order by fcfdd.SortOrder 
                    OPTION(RECOMPILE)
                    """;

                var parameters = new {CompoundVehicleID = compoundVehicleID, FordCompoundFlowDefinitionID = fordCompoundFlowDefinitionID };

                connection.Execute(sql, parameters, transaction);

The captured statement in profiler

exec sp_executesql N'insert into ford.tblFordCompoundFlowVehicle
  (FordCompoundFlowID, CompoundVehicleID, SortOrder, Status1ToSend, Status2ToSend, FordFlowTriggerID, SendTriggerSatisfied, DateSend, FordCompoundFlowDefinitionID)
select fcfd.FordCompoundFlowID, 
       @CompoundVehicleID, 
       fcfdd.SortOrder, 
       fcfdd.Status1ToSend, 
       fcfdd.Status2ToSend, 
       fcfdd.FordFlowTriggerID, 
       0, 
       null,
       @FordCompoundFlowDefinitionID
from   ford.tblFordCompoundFlowDefinitionDetail fcfdd
  inner join ford.tblFordCompoundFlowDefinition fcfd on fcfdd.FordCompoundFlowDefinitionID = fcfd.FordCompoundFlowDefinitionID 
where  fcfdd.FordCompoundFlowDefinitionID = @FordCompoundFlowDefinitionID
order by fcfdd.SortOrder 
OPTION(RECOMPILE)',N'@CompoundVehicleID int,@FordCompoundFlowDefinitionID int',@CompoundVehicleID=9711,@FordCompoundFlowDefinitionID=2
go

System.Data.SqlClient.SqlException HResult=0x80131904
Message=Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding. Operation cancelled by user. Source=Core .Net SqlClient Data Provider
StackTrace: at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action1 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, SqlDataReader ds) at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean asyncWrite, String method) at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 completion, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite, String methodName) at System.Data.SqlClient.SqlCommand.ExecuteNonQuery() at Dapper.SqlMapper.ExecuteCommand(IDbConnection cnn, CommandDefinition& command, Action2 paramReader) in /_/Dapper/SqlMapper.cs:line 2965 at Dapper.SqlMapper.ExecuteImpl(IDbConnection cnn, CommandDefinition& command) in /_/Dapper/SqlMapper.cs:line 656 at Dapper.SqlMapper.Execute(IDbConnection cnn, String sql, Object param, IDbTransaction transaction, Nullable1 commandTimeout, Nullable1 commandType) in /_/Dapper/SqlMapper.cs:line 527 at WebServiceMobile.Repositories.Compound.RepositoryFordFlow.CreateFordCompoundFlowVehicle(SqlConnection connection, SqlTransaction transaction, Int32 compoundVehicleID) in C:\Development\Git\WebServices\WebServiceMobile\Repositories\Compound\Ford\RepositoryFordFlow.cs:line 124 at WebServiceMobile.Repositories.Compound.RepositoryFordFlow.HandleIncomingVehicle(Int32 compoundVehicleID, Nullable1 dateInActual) in C:\Development\Git\WebServices\WebServiceMobile\Repositories\Compound\Ford\RepositoryFordFlow.cs:line 29

Inner Exception 1: Win32Exception: The wait operation timed out.

I tried without using a transaction, same result

System.Data.SqlClient.SqlException: 'Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding. Operation cancelled by user.'

New plan captured from the query running in the application

plan:
https://www.brentozar.com/pastetheplan/?id=B1vTWaMIR

live statistics:
https://www.brentozar.com/pastetheplan/?id=H1-8MpGUA

Running sp_who2

As suggested I ran exec sp_who2 while the slow query is running, this is the result

SPID Status Login HostName BlkBy DBName Command CPUTime DiskIO LastBatch ProgramName SPID REQUESTID
87 SUSPENDED PalmTest XXXX 77 xxxx INSERT 0 2 06/21 11:46:38 gttWebService 87 0

Solution

  • I have found the problem, it seems when run from the application there was a lock that puts my query in suspended state.
    I discovered this thanks to a comment of @sa-es-ir that made me run sp_who2 while the slow query was running. Then I noticed a block from the same application I was running my query from, but with another spid.

    So the query had actually not much to do with the problem and the execution plans should be quit similar I guess, but since the query kept waiting the client got tired of waiting and called a timeout.

    How did this occur?

    It seems that when your connection in C# begins a transaction, and you create a new connection that begins a new transaction, then any query that needs a row that was inserted/updated in the first transaction needs to wait until that transaction ended.

    Basically I had something like this

     using (SqlConnection connection = new SqlConnection(ConnectionString))
     {
         connection.Open();
    
         using (SqlTransaction transaction =  connection.BeginTransaction())
         {
             try
             {
                 SomeProcedure();
                 transaction.Commit();
             }
             catch (Exception ex)
             { 
                 transaction.Rollback();
                 throw;
             }
         }
     }
    
    public void SomeProcedure()
    {
        using (SqlConnection connection = new SqlConnection(ConnectionString))
         {
             connection.Open();
    
             using (SqlTransaction transaction =  connection.BeginTransaction())
             {
                 try
                 {
                     // HERE WAS MY QUERY THAT TIMED OUT
                     transaction.Commit();
                 }
                 catch (Exception ex)
                 { 
                     transaction.Rollback();
                     throw;
                 }
             }
         }
    
    }
    

    I now altered my method so it checks if it is in an existing connection/transaction and then uses that and only create a new one if that is not the case.