Execution Timeout Expired Error (258, ReadSniSyncOverAsync)

[frankyuan]

Describe the bug

When executing SQL such as SELECT FieldA, FieldB FROM A INNER JOIN C ON A.FieldId = C.FieldId UNION SELECT FieldA, FieldD FROM A INNER JOIN D ON A.FieldId = D.FieldId, throw the error like below, not every time, just a little part of queries have this issue.

Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.\n
---> System.ComponentModel.Win32Exception (258): Unknown error 258\n
at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)\n 
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\n 
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)\n 
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()\n 
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()\n 
at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()\n 
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByteArray(Span1 buff, Int32 len, Int32& totalRead)\n
at Microsoft.Data.SqlClient.TdsParser.TrySkipValue(SqlMetaDataPriv md, Int32 columnOrdinal, TdsParserStateObject stateObj)\n
at Microsoft.Data.SqlClient.TdsParser.TrySkipRow(SqlMetaDataSet columns, Int32 startCol, TdsParserStateObject stateObj)\n
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\n
at Microsoft.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)\n
at Microsoft.Data.SqlClient.SqlDataReader.ReadAsync(CancellationToken cancellationToken)\n
--- End of stack trace from previous location where exception was thrown ---\n
at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in //Dapper/SqlMapper.Async.cs:line 437\n

To reproduce

Sorry, currently can't reproduce in the local environment, so can't provide more detail to reproduce.

Expected behavior

SQL should execute successfully every time.

Further technical details

Microsoft.Data.SqlClient version: 1.1.3
.NET target: Core 3.1
Operating system: Docker container

What I found/tried

https://stackoverflow.com/questions/57270245/sql-server-dbcommand-timeout-with-net-core-container-under-load

DapperLib/Dapper#1435

[ErikEJ]

Have you tried increasing the command timeout?

[frankyuan]

Thanks, @ericstj, No, I didn't try increasing command timeout. Currently, the command timeout is 3s. If a query executes timeout, I got stack like below, seems it is different than the above stack, do you mean the above stack is also a SQL execution timeout? By the way, from New relic, the select query's duration is 83.4ms, I'm not sure if it is the execution time.

Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding
Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.\n
---> System.ComponentModel.Win32Exception (258): Unknown error 258\n
at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__164_0(Task`1 result)\n
at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()\n
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)\n
--- End of stack trace from previous location where exception was thrown ---\n
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)\n
--- End of stack trace from previous location where exception was thrown ---\n
at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 419\n

[JRahnama]

@frankyuan, thanks for bringing this up to our attention, can you please let me know if:

• Docker container is using Linux?
• Are you using Azure Sql?
• If I have noticed correctly you could not see the error on your local machine. If I am right, is your local machine using
  Windows OS?
• Is multi threading, such as PLINQ or Parallel queries are used inside the code?

Thank you

[frankyuan]

Sorry for reply delay, here is more detail information(by the way, not every cluster have above error, just in one cluster):

• Docker container is using Linux?
  Yes

• Are you using Azure SQL?
  No

• If I have noticed correctly you could not see the error on your local machine. If I am right, is your local machine using
  Windows OS?
  Yes, my local machine is windows 10.

• Is multi-threading, such as PLINQ or Parallel queries are used inside the code?
  No, we didn't use multi-threading, just using Dapper.SqlMapper's async method (QueryAsync). And I have asked in Dapper. Unknown error 258 : The timeout period elapsed prior to completion DapperLib/Dapper#1435

[JRahnama]

@frankyuan thanks for the response. Can you provide sample repro code? If sample repro is not possible (without sample app it is really difficult to understand what is happening), can you share the connection string properties please?

[frankyuan]

SqlConnectionString like this: Data Source=xxx;Initial Catalog=xx;User ID=xx;Password=xx;Min Pool Size=5;Max Pool Size=100;Connect Timeout=8. CommandTimeout=3. As I can't reproduce in my local environment, I'm afraid can't provide sample repro for now. But I'm trying to reproduce, if find a method, will update here.

[frankyuan]

Seems only the SQL mentioned in description will throw the exception. And sometimes there is another similar exception like below when executing the same SQL.

Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.\n
 ---> System.ComponentModel.Win32Exception (258): Unknown error 258\n
 at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\n
 at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\n
 at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\n
 at Microsoft.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)\n
 at Microsoft.Data.SqlClient.SqlDataReader.ReadAsync(CancellationToken cancellationToken)\n
 --- End of stack trace from previous location where exception was thrown ---\n
 at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 437\n

[JRahnama]

@frankyuan any update on the issue on your side? Were you able to repro the issue? If not, can you kindly share your code or a similar code with me? I need the query you run and setting you have on your machine please. On the other note, can you test it with increasing Connection and command time out as well?

[Svisstack]

I'm experiencing a similar issue

Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while updating the entries. See the inner exception for details. ---> Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (258): No error information at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__164_0(Task1 result)
at System.Threading.Tasks.ContinuationResultTaskFromResultTask2.InnerInvoke() at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) --- End of stack trace from previous location where exception was thrown --- at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) --- End of stack trace from previous location where exception was thrown --- at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken) ClientConnectionId:559501c9-13be-4150-a8bc-ef047cfe491a Error Number:-2,State:0,Class:11 --- End of inner exception stack trace --- at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList1 entriesToSave, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(DbContext _, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
`

.NET target: Core 3.1
Operating system: Docker container (alpine)

[lukas-navratil]

We are also having similar issue like @Svisstack .

Microsoft.Data.SqlClient 2.0.1, .NET Core 3.1, running in Windows container and connecting to SQL Azure Hyperscale DB.

We have a multi-threaded service, lets say about 30 parallel threads that are writing data to the same database. There is a transaction per thread. The service is running fine for most of the time, but from time to time, some threads start to get the exceptions below and they are stuck on it. The command that is failing on this timeout is the same for all threads, but in each occurrence it's usually a different command. Quite often it's a command that is sending some table valued parameters, but we saw it to fail on a very basic SELECT with a single parameter as well. There is no activity on the DB side, connections are in awaiting command state.

From our observations it seems that when this exception is thrown, all threads are blocked on it. They never recovered from it.

 ---> System.ComponentModel.Win32Exception (258): The wait operation timed out.
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__169_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location where exception was thrown ---
   at Dapper.SqlMapper.QueryRowAsync[T](IDbConnection cnn, Row row, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 483

When we noticed this exception, it seems that only some threads were affected and after approximately 30 minutes the issue disappeared.

 ---> System.ComponentModel.Win32Exception (121): The semaphore timeout period has expired.
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__169_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location where exception was thrown ---
   at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 419

I would like to provide a repro, but it's quite hard to reproduce that nondeterministic behavior.

Interesting is that we have 6 instances of this service, where each instance is connecting to different DB and has different number of threads, but we noticed the issue only on 2 instances. One of them is the above mentioned one with 30-35 threads, another one is way smaller, only 3-4 threads.

[frankyuan]

@frankyuan any update on the issue on your side? Were you able to repro the issue? If not, can you kindly share your code or a similar code with me? I need the query you run and setting you have on your machine please. On the other note, can you test it with increasing Connection and command time out as well?

Sorry for getting back to you late, I couldn't reproduce this issue currently, and the only clue is that there are more than 3000 records in the result, after I changed the logic to get fewer records, the exception is gone.

[JRahnama]

@frankyuan thanks for the update.

@Svisstack, @lukas-navratil can any of you guys provide a sample repro application please?

[Svisstack]

I dont have this possibility unfortunately.

…

Sent from my iPhone

On 25 Sep 2020, at 19:27, Javad ***@***.***> wrote:  @frankyuan thanks for the update. @Svisstack, @lukas-navratil can any of you guys provide a sample repro application please? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[mischaherbrand]

We are having the same issue, it happens randomly on our Azure SQL Server instance. Usually the query is very fast and sometimes it raises the error: