Queries with MultipleActiveResultSets=True (MARS) are very slow / time out on Linux

Describe the bug
TL;DR:
Queries using connections with MARS enabled, even when they don't use MARS, are much slower or even time out on Linux. The same queries are fast and reliable on Windows no matter whether MARS is disabled or enabled and on Linux when MARS is disabled.
Context
Octopus Cloud hosts Octopus Deploy instances in Linux containers on Azure AKS with data stored in Azure Files and Azure SQL.  A couple of months ago we noticed that some of the SQL queries were much slower or even started timing out which is not something we've experienced before on Windows using Full .NET Framework. Some of the slowdown might be caused by AKS (K8s) but we think that the SqlClient might also be playing a role here.<PHONE_NUMBER>00676 is our Azure Support Request if that helps in any way.
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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shouldReconnect)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
   at reprocli.Program.Scenario4(String connString, Int32 number)
   at reprocli.Program.<>c__DisplayClass0_0.<Main>b__0(Int32 n)
   at System.Linq.Parallel.ForAllOperator`1.ForAllEnumerator`1.MoveNext(TInput& currentElement, Int32& currentKey)
   at System.Linq.Parallel.ForAllSpoolingTask`2.SpoolingWork()
   at System.Linq.Parallel.SpoolingTaskBase.Work()
   at System.Linq.Parallel.QueryTask.BaseWork(Object unused)
   at System.Linq.Parallel.QueryTask.<>c.<.cctor>b__10_0(Object o)
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
ClientConnectionId:005d2aae-9409-4711-aaa0-b03b70f2832e
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:e3300799-fdd0-40a4-84ea-b9f383596b12
Routing Destination:fed2c41af7dc.tr5.westus2-a.worker.database.windows.net,11063<---

We also captured TCP dumps while running the tests on Linux and it looks like enabling MARS causes TCP RST.

Full TCP Dumps: https://github.com/benPearce1/k8s-sql-timeout-repro/tree/tiny/source/reprocli/tcpdumps
To reproduce
Code
Repo with the sample app: https://github.com/benPearce1/k8s-sql-timeout-repro/blob/tiny/source/reprocli/Program.cs. Compiled folder contains pre-compiled versions of the app so .NET Core SDK doesn't have to be present on the target VMs.
The first parameter is the level of parallelism. The second parameter is the connection string.
using System;
using System.Data;
using System.Diagnostics;
using System.Linq;
using Microsoft.Data.SqlClient;

namespace reprocli
{
    class Program
    {
        static void Main(string[] args)
        {
            try
            {
                var count = int.Parse(args[0]);
                var connectionString = args[1];

                var total = Stopwatch.StartNew();

                PrepareData(connectionString);
                total.Restart();
                Enumerable.Range(0,count)
                    .AsParallel()
                    .WithDegreeOfParallelism(count)
                    .ForAll(n => Scenario4(connectionString, n));

                Console.WriteLine($"Total: {total.Elapsed}");

            }
            catch (Exception e)
            {
                Console.WriteLine(e);
                throw;
            }
        }

        private static void Scenario4(string connString, int number)
        {
            var userStopWatch = Stopwatch.StartNew();

            var buffer = new object[100];
            for (var i = 0; i < 210; i++)
            {
                var queryStopWatch = Stopwatch.StartNew();

                using (var connection = new SqlConnection(connString))
                {
                    connection.Open();
                    using (var transaction = connection.BeginTransaction(IsolationLevel.ReadCommitted))
                    {
                        using (var command = new SqlCommand("SELECT * From TestTable", connection, transaction))
                        {
                            using (var reader = command.ExecuteReader())
                            {
                                while (reader.Read())
                                {
                                    reader.GetValues(buffer);
                                }
                            }
                        }

                        transaction.Commit();
                    }
                }

                queryStopWatch.Stop();
                Console.WriteLine($"Number: {number}. Query: {i} Time: {queryStopWatch.Elapsed}");
            }

            userStopWatch.Stop();
            Console.WriteLine($"Number: {number}. All Queries. Time: {userStopWatch.Elapsed}");
        }

        static void PrepareData(string connectionString)
        {
            var createTable = @"
                DROP TABLE IF EXISTS TestTable;
                CREATE TABLE TestTable
                (
                    [Id] [nvarchar](50) NOT NULL PRIMARY KEY,
                    [Name] [nvarchar](20) NOT NULL
                );";

            using (var connection = new SqlConnection(connectionString))
            {
                connection.Open();
                using (var transaction = connection.BeginTransaction(IsolationLevel.ReadCommitted))
                {
                    using (var command = new SqlCommand(createTable, connection, transaction))
                    {
                        command.ExecuteNonQuery();
                    }

                    transaction.Commit();
                }
            }

        }
    }
}

This is how we reproduced the problem which doesn't mean you need this exact config.
The database was hosted in an Azure SQL Elastic Pool (Standard: 300 eDTUs) on a SQL Server in West US 2 region.
LINUX
Run the sample app with the following arguments on a Linux (ubuntu 18.04) VM (Standard D8s v3 (8 vcpus, 32 GiB memory) in Azure West US 2 region.
MARS ON
dotnet reprocli.dll 200 'Server=tcp:YOURSERVER.database.windows.net,1433;Initial Catalog=TestDatabase;Persist Security Info=False;User ID=YOURUSER;Password=YOURPASSWORD;MultipleActiveResultSets=True;'
The expected result is that the app finishes without throwing any errors but that's not the case and Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. is thrown.
Reducing the level of parallelism to 20 stops the app from crashing.
Also, when MARS is ON the console doesn't show any progress for 10+ seconds. This is not the case when MARS is OFF.
MARS OFF
dotnet reprocli.dll 200 'Server=tcp:YOURSERVER.database.windows.net,1433;Initial Catalog=TestDatabase;Persist Security Info=False;User ID=YOURUSER;Password=YOURPASSWORD;MultipleActiveResultSets=False;'
The expected result is that the app finishes without throwing any errors which is the case. The app finished in just under 25 seconds. Total: 00:00:24.9737616.  The app also worked with much higher levels of parallelism (e.g. 500)
AKS
Same spec as above: Linux (ubuntu 18.04) VM (Standard D8s v3 (8 vcpus, 32 GiB memory) in Azure West US 2. We also ran this test in a container in AKS and the results were pretty much the same. The only difference was that we had to lower the level of parallelism even more.  K8s networking adds a bit of overhead which might make the problem more pronounced.
WINDOWS
Run the sample app with the following arguments on a Windows (Windows Server 2016 Datacenter) VM (Standard D8s v3 (8 vcpus, 32 GiB memory) in Azure West US 2 region.
dotnet reprocli.dll 200 'Server=tcp:YOURSERVER.database.windows.net,1433;Initial Catalog=TestDatabase;Persist Security Info=False;User ID=YOURUSER;Password=YOURPASSWORD;MultipleActiveResultSets=True;'
The expected result is that the app finishes without throwing an exception which is the case. The app finished in just under 24 seconds. Total: 00:00:23.4068641. It also worked with level of parallelism set to 500.  We achieved similar results with MARS disabled.
Note: We used .NET Core to run tests in Windows.
Expected behavior
The sample app should not crash and connections with MARS feature enabled should behave in the same way on both Linux and Windows.
Further technical details
Microsoft.Data.SqlClient version:  1.1.0 and 2.0.0-preview1.20021.1
.NET target: (Core 2.2 and Core 3.1)
SQL Server version: (Azure SQL)
Operating system: (Ubuntu 18.04 and AKS with Ubuntu 18.4)
Additional context
We've been battling this issue for a long time now so we are happy to help in any way we can to get it resolved.

The linux implementationof the network interface is entirely different to the one used on windows which is why you'll see different behaviour. The difference between mars and non-mars is probably caused by the fact that mars takes part of the packet size for the mars header so it can require 2 received network packets to complete a single logical connection packet and that will exascerbate timing problems, you'd see them roughly twice as fast.
One thing to note is that while sql is quite capable of doing many things at once it's not always a good idea to try and open 100 simultanous connections and to use them all in parallel. The unix sockets implementation differs from windows in ways which can exascerbate threading problems, e.g. https://github.com/dotnet/runtime/issues/32016 . There's also another issue on this repo in the past where on investigation i found thread starvation with high levels of requested connection level parallelism caused a problem.
I'll try and take a look at the repro and see anything sticks out as a problem.

Thanks @Wraith2 for looking into it.
@pawelpabich
Thanks for the detailed repro, hopefully it would help fast-track investigations!
On a side note, would you mind testing the same with System.Data.SqlClient older driver versions (4.6.1, 4.7.0...) to confirm if the behaviour has always been the same or recently this performance has degraded?

The replication works on windows and forced managed mode. By works I mean that I get a connection failure request pretty quickly (should be 10 seconds) after I start the program. If you confirm that's what's expected then the repro is good.
Initial impression is that it's simple threadpool starvation. If you add in:
ThreadPool.GetMaxThreads(out var workerThreads, out var completionThreads);
ThreadPool.SetMinThreads(count, completionThreads);

before you start the stopwatch you should find that it runs through successfully.
So why does that work? You're using Parallel which is attempting to start count number of tasks and then have as many as the specified maxdop running at once. It does this by creating tasks and then queuing them to the threadpool. When you start those tasks they all try to connect to the database synchronously which blocks but it blocks in a particular way in the managed implementation, it ends up at https://github.com/dotnet/SqlClient/blob/bac3ab4494c2a5874e56f6d8e0b27265e04f9ca7/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs#L391 which sits in a loop waiting for a ManuarlResetEventSlim to be signalled telling it that a packet has arrived. The problem is that the thing that has to set that event need to run somewhere and if you've consumed all the threadpool threads with synchronous waits there's no thread for it to run on, so the wait times out, and that causes the receive to fail and then the connection isn't established and all this lack of being able to do things either manifests as a connection or query timeout eventually.
It's be nice if we weren't going sync over async in the library so this problem couldn't occur inside the library. Changing that is challenging and short to mid term impractical, it's pretty much a core rewrite of the non-windows implementation with all the reliability and performance concerns that it would come with. So don't expect that to happen soon.
So why is this your problem? Well you're the one using all the threadpool theads. The threadpool starts with a minimum of 10 ready threads in it and at various times tasks are queued to those threads and then completed. Unless you hit a period of sustained load on the pool it's unlikely to need to grow past the minimum value so most of the time you'll have a small number of threads. The threadpool is balanced for general workloads and a lot of research and tuning has gone into it. One of the behaviours that results from this tuning is that it doesn't immediately add large numbers of threads when there are more tasks waiting to be processed than there are threads available to do them. The threadpool usually only adds one thread a second to the pool. If you load it with 100 tasks quickly you'll get 10, then 11, then 12 etc climbing slowly.
So how do you fix it? Don't do this. Don't try to use large number of simultaneous synchronous connections like this. Unless you're talking to a different server or database on each connection then it's going to be more efficient to use a pipeline approach feeding results to an open connection and having it process multiple commands with a single connection. Or, switch to using async if possible because the awaited suspension will free up threadpool threads allowing them to be used or callback signalling.

Thanks @Wraith2 for the investigation. Thread starvation on Linux (https://github.com/dotnet/runtime/issues/14304) explains some of the results we see but I think there are still some unanswered questions here.

One thing to note is that while sql is quite capable of doing many things at once it's not always a good idea to try and open 100 simultanous connections and to use them all in parallel. T

This might not be obvious but the repo is based on how Octopus actually works. It's not entirely a synthetic benchmark. A single deployment performs around that many queries to the database.  We didn't want to include thousands of lines of code here but the end result is the same. count represents the number of concurrent deployments. Our customers can run hundreds of deployments at once.
Also, we checked a bunch of metrics in the SQL Server and the resource utilization is far from being maxed out. This indicates that SQL Server is not the bottleneck here.
Question #1
Why switching MARS OFF on Linux fixes the problem entirely and the level of parallelism can be increased from 20 to 500.  Would just one additional packet cause such a massive difference?
Question #2
Why do we see TCP RST with MARS ON and we don't see it with MARS OFF?

@cheenamalhotra we saw the same problem when we were using S.D.SqlClient. We only migrated to M.D.SqlClient on at the end of December 2019.  We hoped that would solve our problem but it didn't.

ThreadPool.GetMaxThreads(out var workerThreads, out var completionThreads);
ThreadPool.SetMinThreads(count, completionThreads);

Threads on Windows are not cheap. @Wraith2 do know whether this is also the case on Linux? If not, we could start with more threads as a short term workaround.

From the little I know of it threads are even more expensive on Linux than they are on windows, iirc windows is setup for fast thread creation and Linux for fast process creation. So as you say not cheap and it's a poor way to scale. Setting MinThreads on the pool is a way to get around it. Not a great idea for production but it's a public api so it is provided andf supported for you to use if you need to do so. Read around the method and see if you think it's an acceptable thing to do in your case?
SQL server is not the bottleneck, the server is barely doing anything throughout the benchmark. The problem is the client process thread creation as far as I can see.
A1: Turning off mars on Linux removes an intermediate handle object and changes where and how receives are done. In the code I linked to you see the Receive using a packetEvent wait handle. Without mars you'd see it's caller calling into
https://github.com/dotnet/SqlClient/blob/bac3ab4494c2a5874e56f6d8e0b27265e04f9ca7/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNITcpHandle.cs#L493
which doesn't do that kind of wait at all and instead does a direct socket call. So you don't hit the problem because the wait is done in the socket implementation which may not require a threadpool.
Really if you can avoid using mars I would advise doing so, it doesn't seem to have many upsides and significantly increases the likelihood of issues on the managed network implementation. So yes one packet really can't make all the difference because that one packet on the mars path immediately causes a synchronous wait that can't be unlocked without the resource it's blocking.
A2: At a guess if it's coming from the sqlclient side I'd say it's because the socket is being shutdown because of the failure. Once successfully connected sockets are kept open until they're removed from the pool even if you close the SqlConnection object the SqlConnectionInternal object it contains stays alive for a while unless there is a failure which dooms it to immediate closure. If it's from the server side I couldn't say.

Thanks @Wraith2. I appreciate the time you took to explain the details.

Really if you can avoid using mars I would advise doing so, it doesn't seem to have many upsides and significantly increases the likelihood of issues on the managed network implementation

I would love to do that but this would be a significant change for us and we need a decent workaround/solution as soon as possible.  @cheenamalhotra, is there a chance this code can be optimized?

If it's from the server side I couldn't say.

Yes, it is coming from the server side.
 172.xxx is a private IP of the VM
@cheenamalhotra, I think we need some additional help here.

I just revalidated this using a MAC OSX 10.14.6 (Mojave) + .Net Core APP 3.1.0 + System.Data.SqlClient 4.8.1

I was able to trace the slowness of your "mid period queries" to the transactions. If you do not open transactions explicitly things will fly.
The slowness of the transaction happens whether MARS is on or not, so I don't have reasons to believe that there's a problem with the mars implementation.

This can also be solved as @Wraith2 said, by expanding the thread pool. Note that linux does not differentiate between WorkerThreads and CompletionThreads (IO threads)

We've tried this and it did not solve the problem for us because MARS connections still take much longer to open and we simply run out of connections in the pool.

I was able to trace the slowness of your "mid period queries" to the transactions. If you do not open transactions explicitly things will fly.

So what do you propose we do instead?

The slowness of the transaction happens whether MARS is on or not, so I don't have reasons to believe that there's a problem with the mars implementation.

From what I see you ran your tests in a different environment (MAC OSX) than ours so I'm not sure how you can draw this conclusion.

Well, about the validity of the tests, MAC OSX behaves very similarly to Linux, including the thread management, after all Mac OSX is a unix based... So I would take my reproducing with a grain of salt, but I'm quite confident on the analysis...
About the transactions blocking each other, there are several workarounds, but they rely on actual code changes and business-rules validations and etc. This is a database issue, not a implementation issue.
If you're out-of-your-mind you could remove the transaction all together (and when questioned, you can say that the fever from the coronavirus made you hallucinate), but in a more realistic scenario, you can try to set the isolation level to "ReadUncommited", this way the blocking/deadlocking will decrease immensely...

@pawelpabich
I have't been responding lately, but just to let you know I am investigating this issue. I'm able to reproduce the problem in linux docker containers when connecting to any SQL Server, irrespective of being Azure DB and it does seem to be related to linux memory management, as when running the same app on Windows using the same codepath of Managed SNI the problem does not reproduce. @Wraith2 seems to have provided some details.
However I'm investigating if it is specifically related to containerized environment limitations. I'm not sure at this point if this has anything to with transactions, but I'll share updates soon!

@cheenamalhotra, I don't believe that this is related to containerised applications because I was able to reproduce the issue on my local machine (up to some degree, since I did not experienced heavy delays mid-execution). Perhaps the containerised scenario exarcebates the problem but I believe that the problem is there... here is a sumup of my tests:
Count:20, Parallel:8, YES TRANSACTION - NO MARS
Number: 5. All Queries. Time: 00:00:01.0470491
Number: 3. All Queries. Time: 00:00:01.0500434
Number: 6. All Queries. Time: 00:00:01.0514407
Number: 0. All Queries. Time: 00:00:01.0542009
Number: 2. All Queries. Time: 00:00:01.0583711
Number: 4. All Queries. Time: 00:00:01.1497360
Number: 1. All Queries. Time: 00:00:01.1510161
Number: 7. All Queries. Time: 00:00:01.1630255
Number: 8. All Queries. Time: 00:00:00.6292422
Number: 10. All Queries. Time: 00:00:00.6340763
Number: 9. All Queries. Time: 00:00:00.6494815
Number: 12. All Queries. Time: 00:00:00.6463415
Number: 11. All Queries. Time: 00:00:00.6570911
Number: 14. All Queries. Time: 00:00:00.8896517
Number: 13. All Queries. Time: 00:00:00.9317428
Number: 15. All Queries. Time: 00:00:00.9248774
Number: 16. All Queries. Time: 00:00:01.2828993
Number: 17. All Queries. Time: 00:00:01.2867972
Number: 18. All Queries. Time: 00:00:01.2852665
Number: 19. All Queries. Time: 00:00:01.2847378
Total: 00:00:03.1413429
First Queries:
00:00:00.5860205
00:00:00.5860870
00:00:00.5859981
00:00:00.5860731
00:00:00.5860413
00:00:00.5860577
00:00:00.5860111
00:00:00.5873522
00:00:00.0018571
00:00:00.0018698
00:00:00.0018539
00:00:00.0020848
00:00:00.0015862
00:00:00.0024604
00:00:00.0026320
00:00:00.0022536
00:00:00.0066965
00:00:00.0068477
00:00:00.0068829
00:00:00.0065229
Count:20, Parallel:8, YES TRANSACTION - YES MARS
Number: 3. All Queries. Time: 00:00:01.8238989
Number: 2. All Queries. Time: 00:00:01.8260756
Number: 4. All Queries. Time: 00:00:01.8352712
Number: 7. All Queries. Time: 00:00:01.8375570
Number: 6. All Queries. Time: 00:00:01.8399148
Number: 5. All Queries. Time: 00:00:01.8444057
Number: 1. All Queries. Time: 00:00:01.8468115
Number: 0. All Queries. Time: 00:00:01.8583285
Number: 13. All Queries. Time: 00:00:01.4769483
Number: 15. All Queries. Time: 00:00:01.4741198
Number: 8. All Queries. Time: 00:00:01.5680454
Number: 9. All Queries. Time: 00:00:01.5665582
Number: 10. All Queries. Time: 00:00:01.5605656
Number: 12. All Queries. Time: 00:00:01.5582591
Number: 11. All Queries. Time: 00:00:01.5654078
Number: 14. All Queries. Time: 00:00:01.5613466
Number: 16. All Queries. Time: 00:00:00.4957817
Number: 17. All Queries. Time: 00:00:00.4917708
Number: 18. All Queries. Time: 00:00:00.4574173
Number: 19. All Queries. Time: 00:00:00.4571974
Total: 00:00:04.0195703
First Queries:
00:00:00.5965634
00:00:00.5965534
00:00:00.5965991
00:00:00.5965589
00:00:00.5965778
00:00:00.5965937
00:00:00.5965741
00:00:00.5965588
00:00:00.0064917
00:00:00.0066611
00:00:00.0068385
00:00:00.0067982
00:00:00.0068086
00:00:00.0066095
00:00:00.0066777
00:00:00.0066912
00:00:00.0045863
00:00:00.0058520
00:00:00.0021949
00:00:00.0018970
Count:20, Parallel:8, NO TRANSACTION - YES MARS
Number: 5. All Queries. Time: 00:00:00.8371968
Number: 3. All Queries. Time: 00:00:00.8407228
Number: 0. All Queries. Time: 00:00:00.8464102
Number: 2. All Queries. Time: 00:00:00.8510748
Number: 7. All Queries. Time: 00:00:00.8699850
Number: 4. All Queries. Time: 00:00:00.8858711
Number: 6. All Queries. Time: 00:00:00.8877594
Number: 1. All Queries. Time: 00:00:00.9125339
Number: 8. All Queries. Time: 00:00:00.4547782
Number: 9. All Queries. Time: 00:00:00.4537054
Number: 11. All Queries. Time: 00:00:00.4833543
Number: 13. All Queries. Time: 00:00:00.4650509
Number: 10. All Queries. Time: 00:00:00.5251250
Number: 12. All Queries. Time: 00:00:00.5050363
Number: 14. All Queries. Time: 00:00:00.5020542
Number: 15. All Queries. Time: 00:00:00.5916084
Number: 17. All Queries. Time: 00:00:00.5435370
Number: 18. All Queries. Time: 00:00:00.5602439
Number: 19. All Queries. Time: 00:00:00.5896770
Number: 16. All Queries. Time: 00:00:00.6996142
Total: 00:00:02.1313958
First Queries:
00:00:00.6278838
00:00:00.6279385
00:00:00.6278945
00:00:00.6278912
00:00:00.6279155
00:00:00.6279257
00:00:00.6278742
00:00:00.6279185
00:00:00.0012271
00:00:00.0006439
00:00:00.0007066
00:00:00.0006888
00:00:00.0011631
00:00:00.0006712
00:00:00.0012544
00:00:00.0049881
00:00:00.0019198
00:00:00.0005747
00:00:00.0007611
00:00:00.0006678
Count:20, Parallel:8, NO TRANSACTION - NO MARS
Number: 0. All Queries. Time: 00:00:00.7707507
Number: 5. All Queries. Time: 00:00:00.8029723
Number: 6. All Queries. Time: 00:00:00.8053098
Number: 3. All Queries. Time: 00:00:00.8165772
Number: 1. All Queries. Time: 00:00:00.8190445
Number: 2. All Queries. Time: 00:00:00.8348932
Number: 4. All Queries. Time: 00:00:00.8596580
Number: 7. All Queries. Time: 00:00:00.9215064
Number: 8. All Queries. Time: 00:00:00.6400341
Number: 10. All Queries. Time: 00:00:00.6576637
Number: 11. All Queries. Time: 00:00:00.6576382
Number: 9. All Queries. Time: 00:00:00.6908438
Number: 12. All Queries. Time: 00:00:00.6806739
Number: 13. All Queries. Time: 00:00:00.6704229
Number: 14. All Queries. Time: 00:00:00.6783818
Number: 15. All Queries. Time: 00:00:00.6482645
Number: 16. All Queries. Time: 00:00:00.4391626
Number: 18. All Queries. Time: 00:00:00.3995539
Number: 19. All Queries. Time: 00:00:00.3799171
Number: 17. All Queries. Time: 00:00:00.4165565
Total: 00:00:02.0165027
First Queries:
00:00:00.6144434
00:00:00.6144111
00:00:00.6143904
00:00:00.6144485
00:00:00.6143983
00:00:00.6175860
00:00:00.6177502
00:00:00.6193642
00:00:00.0005292
00:00:00.0022520
00:00:00.0020013
00:00:00.0022936
00:00:00.0026404
00:00:00.0021068
00:00:00.0021113
00:00:00.0027646
00:00:00.0044434
00:00:00.0067386
00:00:00.0040238
00:00:00.0034082

I do experience this issue on Azure Web App For Containers (on Linux), but not when running the same container locally on Docker Desktop. Hope this helps.

Good that this github issue exists (thanks!), we seem to have run into the same issue. Problem only appears when running the (asp core + ef core 3.1.2) app on Docker with Kubernetes with MARS on. Our background service handling lots of data would simply "die", sometimes with and sometimes without any exception thrown. As it is a BackgroundService/IHostedService, the web app continues to run, just the BackgroundService is gone.
I turned MARS off and now it works.
I got two kinds of exceptions, this one with default settings of DbContext.
An exception occurred while iterating over the results of a query for context type '***'.
Microsoft.Data.SqlClient.SqlException (0x80131904): The connection is broken and recovery is not possible.  The connection is marked by the server as unrecoverable.  No attempt was made to restore the connection.
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__164_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 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.Query.Internal.QueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(DbContext _, Boolean result, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()

When setting the command timeout to five minutes, I got this exception - same as the opener of this issue.
An exception occurred while iterating over the results of a query for context type '"***"'."
""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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.SqlDataReader.TrySetMetaData(_SqlMetaDataSet metaData, Boolean moreInfo)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
   at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.InitializeReader(DbContext _, Boolean result)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()
ClientConnectionId:3d813f87-29be-4a5a-9e6d-faff5d0e0a5f
Error Number:-2,State:0,Class:11"

This issue caused lots of working days of diagnosing, as there is no clear indication what is wrong, hindering troubleshooting.

Hi, I have exactly the same issue as @tunger.
I'm running under .net core 3.1.3 (Linux docker container as Azure Web App) with Azure MSSQL DB.
I'm just using Dapper instead of EF.
With MARS disabled everything works fine.

Have a read of https://github.com/dotnet/SqlClient/issues/502 and see if increasing packet size helps things. If it doesn't try turning off mars. If you can't turn off mars then you're stuck.

Hi Team,
We have multiple users reporting the same issue. The issue only happens on Linux. The issue does not happen on Windows.
To narrow down the issue, we have simplified the reproducing code to the following:
using System;
using System.ComponentModel.DataAnnotations;
using System.Data;
using System.Diagnostics;
using System.Linq;
using System.Threading;
using Microsoft.Data.SqlClient;
namespace reprocli
{
class Program
{
static void Main(string[] args)
{
try
{
var count = 40;
var connectionString = "Server=tcp:.database.windows.net,1433;Initial Catalog=adv;Persist Security Info=False;User ID=testadmin;Password=Ei@1fi0soi;MultipleActiveResultSets=TRUE;Connect Timeout=0;Max Pool Size=20;Packet Size=12000";
var total = Stopwatch.StartNew();
total.Restart();
Enumerable.Range(0, count)
.AsParallel()
.WithDegreeOfParallelism(count)
.ForAll(n => Scenario4(connectionString, n));
Console.WriteLine($"Total: {total.Elapsed}");
}
catch (Exception e)
{
Console.WriteLine(e);
throw;
}
}
private static void Scenario4(string connString, int number)
{
var userStopWatch = Stopwatch.StartNew();
var buffer = new object[100];
{
using (var connection = new SqlConnection(connString))
{
var StartTimestamp = DateTime.Now;
connection.Open();
var FinishTimestamp = DateTime.Now;
TimeSpan span = FinishTimestamp.Subtract(StartTimestamp);
Console.WriteLine("Task " + number.ToString("00") + ": Connection.Open started at " + StartTimestamp.ToString() + ";ended at " + FinishTimestamp.ToString() + " - Elapsed " + span.TotalMilliseconds);
StartTimestamp = DateTime.Now;
using (var transaction = connection.BeginTransaction(IsolationLevel.ReadCommitted))
{
FinishTimestamp = DateTime.Now;
span = FinishTimestamp.Subtract(StartTimestamp);
Console.WriteLine("Task " + number.ToString("00") + ": BeginTransaction started at " + StartTimestamp.ToString() + ";ended at " + FinishTimestamp.ToString() + " - Elapsed " + span.TotalMilliseconds);
transaction.Commit();
}
connection.Close();
}
}
userStopWatch.Stop();
Console.WriteLine("Task " + number.ToString("00") + $": Total - Elapsed: {userStopWatch.Elapsed}");
}
}
}
Note in the above code:

We have spawned 40 threads in parallel. With only 40 threads, thread pool starvation should not be a problem. (We can only see 51 threads when ManualResetEventSlim is being signaled)

Each thread only connects to Azure SQL Database for once. In that connection, it only starts a transaction, and commits the transaction. There're no queries.

We have modified the connection string to include several properties:

a. Connect Timeout=0
The execution timeout error can be avoided by setting connect timeout to 0. Without hitting the timeout, we can observe the slow behavior more clearly.
b. Max Pool Size=20
We specify the pool size to half number of the parallel threads so that we can see how connection pool takes effect here.
c. Packet Size=12000
We increase the packet size, but it does not show any differences.

We have logged the timestamps and duration of Connectoin.Open and BeginTransaction for each thread/task.

Test result for Windows
Total execution took only 5.8 seconds. Each thread running in parallel took no more than 3 seconds. Most of the time were spent on Connection.Open:
Task 03: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:57 PM - Elapsed 1252.0322
Task 03: BeginTransaction started at 4/27/2020 5:26:57 PM;ended at 4/27/2020 5:26:57 PM - Elapsed 99.9115
Task 07: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:57 PM - Elapsed 1454.2317
Task 03: Total - Elapsed: 00:00:02.0012941
Task 07: BeginTransaction started at 4/27/2020 5:26:57 PM;ended at 4/27/2020 5:26:57 PM - Elapsed 94.4907
Task 01: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 1641.8124
Task 07: Total - Elapsed: 00:00:02.1885435
Task 01: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.4182
Task 01: Total - Elapsed: 00:00:02.3745601
Task 00: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 1827.7951
Task 00: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.6793
Task 00: Total - Elapsed: 00:00:02.5601853
Task 11: Connection.Open started at 4/27/2020 5:26:57 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 558.5962
Task 08: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 2096.162
Task 11: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.5295
Task 08: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.8543
Task 11: Total - Elapsed: 00:00:00.7444362
Task 05: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 2199.2868
Task 08: Total - Elapsed: 00:00:02.8291427
Task 06: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 2282.408
Task 05: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.3598
Task 06: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.9552
Task 05: Total - Elapsed: 00:00:02.9313097
Task 04: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 2384.6057
Task 06: Total - Elapsed: 00:00:03.0157004
Task 09: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 2360.5249
Task 04: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 92.6181
Task 09: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 93.0764
Task 04: Total - Elapsed: 00:00:03.1168025
Task 10: Connection.Open started at 4/27/2020 5:26:57 PM;ended at 4/27/2020 5:26:58 PM - Elapsed 1463.5762
Task 09: Total - Elapsed: 00:00:02.5470265
Task 17: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 372.9687
Task 10: BeginTransaction started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.4596
Task 17: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.8557
Task 10: Total - Elapsed: 00:00:01.6491569
Task 13: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 1113.3493
Task 17: Total - Elapsed: 00:00:00.5603184
Task 14: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 1014.9437
Task 13: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.3817
Task 14: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 93.0985
Task 02: Connection.Open started at 4/27/2020 5:26:56 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 2937.5539
Task 13: Total - Elapsed: 00:00:01.2987254
Task 16: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 741.6992
Task 02: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.2785
Task 14: Total - Elapsed: 00:00:01.2020219
Task 18: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 645.2825
Task 16: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.3808
Task 02: Total - Elapsed: 00:00:03.6693590
Task 19: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 653.5425
Task 18: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.8252
Task 16: Total - Elapsed: 00:00:00.9270470
Task 20: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 556.2838
Task 19: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.6183
Task 18: Total - Elapsed: 00:00:00.8327458
Task 12: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 1598.5975
Task 20: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.3875
Task 19: Total - Elapsed: 00:00:00.8397575
Task 21: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 701.6779
Task 12: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 93.0304
Task 20: Total - Elapsed: 00:00:00.7413675
Task 22: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 655.9256
Task 21: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.6944
Task 12: Total - Elapsed: 00:00:01.7852348
Task 23: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 648.3088
Task 22: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.4581
Task 21: Total - Elapsed: 00:00:00.8880851
Task 24: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 652.2877
Task 22: Total - Elapsed: 00:00:00.8415095
Task 25: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 555.9168
Task 23: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:26:59 PM - Elapsed 92.791
Task 24: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.6832
Task 25: BeginTransaction started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.3799
Task 23: Total - Elapsed: 00:00:00.8348116
Task 26: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 559.4023
Task 24: Total - Elapsed: 00:00:00.8388235
Task 28: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 555.3253
Task 25: Total - Elapsed: 00:00:00.7411146
Task 27: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 559.6749
Task 26: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.9759
Task 28: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 93.3051
Task 27: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.7269
Task 26: Total - Elapsed: 00:00:00.7461889
Task 29: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 559.9274
Task 15: Connection.Open started at 4/27/2020 5:26:58 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 1764.509
Task 28: Total - Elapsed: 00:00:00.7427732
Task 31: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 557.6932
Task 15: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 91.3374
Task 27: Total - Elapsed: 00:00:00.7468952
Task 34: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 372.3959
Task 29: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.7142
Task 15: Total - Elapsed: 00:00:01.9484886
Task 35: Connection.Open started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 371.0839
Task 31: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.5221
Task 29: Total - Elapsed: 00:00:00.7463724
Task 34: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.283
Task 32: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 559.6628
Task 35: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 91.6887
Task 31: Total - Elapsed: 00:00:00.7448745
Task 33: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 561.1435
Task 34: Total - Elapsed: 00:00:00.5597399
Task 36: Connection.Open started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 449.6328
Task 32: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.8304
Task 35: Total - Elapsed: 00:00:00.5563786
Task 37: Connection.Open started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 465.2997
Task 33: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.5839
Task 36: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.3554
Task 32: Total - Elapsed: 00:00:00.7463895
Task 38: Connection.Open started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 467.4738
Task 37: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 91.6418
Task 33: Total - Elapsed: 00:00:00.7467624
Task 39: Connection.Open started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 464.5236
Task 36: Total - Elapsed: 00:00:00.6352385
Task 38: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.8737
Task 37: Total - Elapsed: 00:00:00.6496484
Task 39: BeginTransaction started at 4/27/2020 5:27:00 PM;ended at 4/27/2020 5:27:00 PM - Elapsed 92.489
Task 38: Total - Elapsed: 00:00:00.6536980
Task 39: Total - Elapsed: 00:00:00.6576849
Task 30: Connection.Open started at 4/27/2020 5:26:59 PM;ended at 4/27/2020 5:27:01 PM - Elapsed 1316.457
Task 30: BeginTransaction started at 4/27/2020 5:27:01 PM;ended at 4/27/2020 5:27:01 PM - Elapsed 92.3981
Task 30: Total - Elapsed: 00:00:01.5020711
Total: 00:00:05.7179428
Test Result for Linux
Run the same on Linux. Total execution took 34 seconds. The connection.Open does not really execute in parallel. Once a BeginTransaction starts in one connection, it slows down the other thread to start Connection.Open. The more connection.open, the more delay. Once the connection pool was full, it was blocked for x0 seconds until one of the BeginTransaction finished. Then the later connections queued into the connection pool could run properly without any delays:
dragon@marlonvm:~/k8s-sql-timeout-repro/source/reprocli$ dotnet run
Task 04: Connection.Open started at 4/27/2020 9:34:31 AM;ended at 4/27/2020 9:34:32 AM - Elapsed 481.6339
Task 00: Connection.Open started at 4/27/2020 9:34:31 AM;ended at 4/27/2020 9:34:32 AM - Elapsed 510.3399
Task 02: Connection.Open started at 4/27/2020 9:34:31 AM;ended at 4/27/2020 9:34:32 AM - Elapsed 556.4548
Task 01: Connection.Open started at 4/27/2020 9:34:31 AM;ended at 4/27/2020 9:34:32 AM - Elapsed 591.7924
Task 03: Connection.Open started at 4/27/2020 9:34:31 AM;ended at 4/27/2020 9:34:32 AM - Elapsed 617.9443
Task 05: Connection.Open started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:34:32 AM - Elapsed 27.8998
Task 06: Connection.Open started at 4/27/2020 9:34:33 AM;ended at 4/27/2020 9:34:33 AM - Elapsed 30.827
Task 07: Connection.Open started at 4/27/2020 9:34:33 AM;ended at 4/27/2020 9:34:34 AM - Elapsed 27.4854
Task 08: Connection.Open started at 4/27/2020 9:34:34 AM;ended at 4/27/2020 9:34:35 AM - Elapsed 31.2146
Task 09: Connection.Open started at 4/27/2020 9:34:35 AM;ended at 4/27/2020 9:34:35 AM - Elapsed 30.8095
Task 10: Connection.Open started at 4/27/2020 9:34:36 AM;ended at 4/27/2020 9:34:36 AM - Elapsed 30.4743
Task 11: Connection.Open started at 4/27/2020 9:34:37 AM;ended at 4/27/2020 9:34:37 AM - Elapsed 30.617
Task 12: Connection.Open started at 4/27/2020 9:34:38 AM;ended at 4/27/2020 9:34:38 AM - Elapsed 29.1201
Task 13: Connection.Open started at 4/27/2020 9:34:39 AM;ended at 4/27/2020 9:34:39 AM - Elapsed 36.9007
Task 14: Connection.Open started at 4/27/2020 9:34:40 AM;ended at 4/27/2020 9:34:40 AM - Elapsed 30.8955
Task 15: Connection.Open started at 4/27/2020 9:34:41 AM;ended at 4/27/2020 9:34:41 AM - Elapsed 31.2848
Task 16: Connection.Open started at 4/27/2020 9:34:42 AM;ended at 4/27/2020 9:34:42 AM - Elapsed 29.2114
Task 17: Connection.Open started at 4/27/2020 9:34:43 AM;ended at 4/27/2020 9:34:43 AM - Elapsed 24.7978
Task 18: Connection.Open started at 4/27/2020 9:34:44 AM;ended at 4/27/2020 9:34:44 AM - Elapsed 32.4253
Task 19: Connection.Open started at 4/27/2020 9:34:45 AM;ended at 4/27/2020 9:34:45 AM - Elapsed 37.3471
Task 08: BeginTransaction started at 4/27/2020 9:34:35 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 30011.9233
Task 00: BeginTransaction started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 32982.9174
Task 09: BeginTransaction started at 4/27/2020 9:34:35 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 29512.0317
Task 10: BeginTransaction started at 4/27/2020 9:34:36 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 28508.912
Task 02: BeginTransaction started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 32936.5808
Task 11: BeginTransaction started at 4/27/2020 9:34:37 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 27462.8604
Task 04: BeginTransaction started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 33008.9028
Task 06: BeginTransaction started at 4/27/2020 9:34:33 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 31512.4423
Task 07: BeginTransaction started at 4/27/2020 9:34:34 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 31016.4188
Task 12: BeginTransaction started at 4/27/2020 9:34:38 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 26512.2184
Task 13: BeginTransaction started at 4/27/2020 9:34:39 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 25504.2651
Task 03: BeginTransaction started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 32875.1887
Task 05: BeginTransaction started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 32517.823
Task 01: BeginTransaction started at 4/27/2020 9:34:32 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 32901.4141
Task 14: BeginTransaction started at 4/27/2020 9:34:40 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 24504.4908
Task 15: BeginTransaction started at 4/27/2020 9:34:41 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 23473.666
Task 16: BeginTransaction started at 4/27/2020 9:34:42 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 22510.7361
Task 17: BeginTransaction started at 4/27/2020 9:34:43 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 21515.0665
Task 18: BeginTransaction started at 4/27/2020 9:34:44 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 20984.4067
Task 19: BeginTransaction started at 4/27/2020 9:34:45 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 19970.1126
Task 22: Connection.Open started at 4/27/2020 9:34:48 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 17040.9565
Task 24: Connection.Open started at 4/27/2020 9:34:49 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 15542.3034
Task 20: Connection.Open started at 4/27/2020 9:34:46 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 19045.6091
Task 13: Total - Elapsed: 00:00:25.5511950
Task 06: Total - Elapsed: 00:00:31.5553711
Task 08: Total - Elapsed: 00:00:30.0551484
Task 15: Total - Elapsed: 00:00:23.5144020
Task 10: Total - Elapsed: 00:00:28.5512858
Task 28: Connection.Open started at 4/27/2020 9:34:53 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 12040.2609
Task 25: Connection.Open started at 4/27/2020 9:34:50 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 14541.4863
Task 19: Total - Elapsed: 00:00:20.0156375
Task 26: Connection.Open started at 4/27/2020 9:34:51 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 14040.7895
Task 21: Connection.Open started at 4/27/2020 9:34:47 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 18045.5826
Task 01: Total - Elapsed: 00:00:33.5539375
Task 07: Total - Elapsed: 00:00:31.0564162
Task 00: Total - Elapsed: 00:00:33.5541849
Task 30: Connection.Open started at 4/27/2020 9:34:55 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 10039.1023
Task 18: Total - Elapsed: 00:00:21.0258884
Task 23: Connection.Open started at 4/27/2020 9:34:49 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 16044.2951
Task 09: Total - Elapsed: 00:00:29.5554896
Task 31: Connection.Open started at 4/27/2020 9:34:56 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 9036.8845
Task 03: Total - Elapsed: 00:00:33.5544169
Task 17: Total - Elapsed: 00:00:21.5493243
Task 33: Connection.Open started at 4/27/2020 9:34:58 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 7036.9824
Task 12: Total - Elapsed: 00:00:26.5529391
Task 34: Connection.Open started at 4/27/2020 9:34:59 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 6035.7954
Task 02: Total - Elapsed: 00:00:33.5545999
Task 35: Connection.Open started at 4/27/2020 9:35:00 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 5035.7386
Task 16: Total - Elapsed: 00:00:22.5499312
Task 36: Connection.Open started at 4/27/2020 9:35:01 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 4035.4121
Task 04: Total - Elapsed: 00:00:33.5546821
Task 14: Total - Elapsed: 00:00:24.5453515
Task 27: Connection.Open started at 4/27/2020 9:34:52 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 13040.8999
Task 11: Total - Elapsed: 00:00:27.5058150
Task 29: Connection.Open started at 4/27/2020 9:34:54 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 11036.1083
Task 37: Connection.Open started at 4/27/2020 9:35:02 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 3035.0194
Task 32: Connection.Open started at 4/27/2020 9:34:57 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 8038.2898
Task 38: Connection.Open started at 4/27/2020 9:35:03 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2023.0241
Task 05: Total - Elapsed: 00:00:32.5594002
Task 39: Connection.Open started at 4/27/2020 9:35:04 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1033.8102
Task 25: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.9938
Task 21: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8662
Task 22: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.5818
Task 28: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.0527
Task 33: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.5791
Task 31: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.7331
Task 30: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.0152
Task 24: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.8402
Task 23: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8164
Task 26: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.3343
Task 20: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.898
Task 34: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8759
Task 35: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8686
Task 36: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8287
Task 37: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.7166
Task 29: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.889
Task 32: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8629
Task 38: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8027
Task 27: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 2.0957
Task 39: BeginTransaction started at 4/27/2020 9:35:05 AM;ended at 4/27/2020 9:35:05 AM - Elapsed 1.8029
Task 25: Total - Elapsed: 00:00:14.5450434
Task 21: Total - Elapsed: 00:00:18.0492143
Task 22: Total - Elapsed: 00:00:17.0452281
Task 28: Total - Elapsed: 00:00:12.0440717
Task 33: Total - Elapsed: 00:00:07.0400924
Task 30: Total - Elapsed: 00:00:10.0426584
Task 31: Total - Elapsed: 00:00:09.0402773
Task 23: Total - Elapsed: 00:00:16.0478210
Task 26: Total - Elapsed: 00:00:14.0450272
Task 24: Total - Elapsed: 00:00:15.5469980
Task 34: Total - Elapsed: 00:00:06.0394797
Task 35: Total - Elapsed: 00:00:05.0394576
Task 36: Total - Elapsed: 00:00:04.0390648
Task 37: Total - Elapsed: 00:00:03.0384628
Task 38: Total - Elapsed: 00:00:02.0265013
Task 32: Total - Elapsed: 00:00:08.0421579
Task 27: Total - Elapsed: 00:00:13.0456037
Task 29: Total - Elapsed: 00:00:11.0406611
Task 20: Total - Elapsed: 00:00:19.0509156
Task 39: Total - Elapsed: 00:00:01.0373777
Total: 00:00:33.5828616
The interesting thing is that from the managed call stack, we see the threads were waiting on SNIMarsHandle.Receive:
(lldb) clrstack
OS Thread Id: 0x9654 (20)
Child SP               IP Call Site
00007EFF421D6C00 00007effbe084360 [GCFrame: 00007eff421d6c00]
00007EFF421D6CE0 00007effbe084360 [HelperMethodFrame_1OBJ: 00007eff421d6ce0] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
00007EFF421D6E10 00007EFF42F207B4 System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)
00007EFF421D6EA0 00007EFF455A4595 Microsoft.Data.SqlClient.SNI.SNIMarsHandle.Receive(Microsoft.Data.SqlClient.SNI.SNIPacket ByRef, Int32)
00007EFF421D6F10 00007EFF44110B12 Microsoft.Data.SqlClient.SNI.SNIProxy.ReadSyncOverAsync(Microsoft.Data.SqlClient.SNI.SNIHandle, Microsoft.Data.SqlClient.SNI.SNIPacket ByRef, Int32)
00007EFF421D6F40 00007EFF44110A9D Microsoft.Data.SqlClient.SNI.TdsParserStateObjectManaged.ReadSyncOverAsync(Int32, UInt32 ByRef)
00007EFF421D6F90 00007EFF441103C1 Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
00007EFF421D6FF0 00007EFF441102B9 Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
00007EFF421D7010 00007EFF4412D7FB Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
00007EFF421D7030 00007EFF4412D6EE Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
00007EFF421D7060 00007EFF4412C778 Microsoft.Data.SqlClient.TdsParser.TryRun(Microsoft.Data.SqlClient.RunBehavior, Microsoft.Data.SqlClient.SqlCommand, Microsoft.Data.SqlClient.SqlDataReader, Microsoft.Data.SqlClient.BulkCopySimpleResultSet, Microsoft.Data.SqlClient.TdsParserStateObject, Boolean ByRef)
00007EFF421D7200 00007EFF4412C132 Microsoft.Data.SqlClient.TdsParser.Run(Microsoft.Data.SqlClient.RunBehavior, Microsoft.Data.SqlClient.SqlCommand, Microsoft.Data.SqlClient.SqlDataReader, Microsoft.Data.SqlClient.BulkCopySimpleResultSet, Microsoft.Data.SqlClient.TdsParserStateObject)
00007EFF421D7270 00007EFF455A3A53 Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[], TransactionManagerRequestType, System.String, TransactionManagerIsolationLevel, Int32, Microsoft.Data.SqlClient.SqlInternalTransaction, Microsoft.Data.SqlClient.TdsParserStateObject, Boolean)
00007EFF421D7320 00007EFF455A2723 Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest, System.String, System.Data.IsolationLevel, Microsoft.Data.SqlClient.SqlInternalTransaction, Boolean)
00007EFF421D73F0 00007EFF455A235D Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest, System.String, System.Data.IsolationLevel, Microsoft.Data.SqlClient.SqlInternalTransaction, Boolean)
00007EFF421D7440 00007EFF455A18D0 Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(System.Data.IsolationLevel, System.String, Boolean)
00007EFF421D74D0 00007EFF455A14EF Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(System.Data.IsolationLevel, System.String)
00007EFF421D7520 00007EFF455A13EF Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(System.Data.IsolationLevel)
00007EFF421D7540 00007EFF4340E81B reprocli.Program.Scenario4(System.String, Int32) [/home/dragon/k8s-sql-timeout-repro/source/reprocli/Program.cs @ 54]
And we can track to where ManualResetEventSlim was signaled:
(lldb) clrstack
OS Thread Id: 0x9d24 (51)
Child SP               IP Call Site
00007EFEA8FF85B0 00007EFF42F20C46 System.Threading.ManualResetEventSlim.UpdateStateAtomically(Int32, Int32) [//src/System.Private.CoreLib/shared/System/Threading/ManualResetEventSlim.cs @ 720]
00007EFEA8FF85F0 00007EFF42F2026A System.Threading.ManualResetEventSlim.Set(Boolean) [//src/System.Private.CoreLib/shared/System/Threading/ManualResetEventSlim.cs @ 310]
00007EFEA8FF8640 00007EFF42F2022D System.Threading.ManualResetEventSlim.Set() [//src/System.Private.CoreLib/shared/System/Threading/ManualResetEventSlim.cs @ 297]
00007EFEA8FF8650 00007EFF455C644B Microsoft.Data.SqlClient.SNI.SNIMarsHandle.HandleReceiveComplete(Microsoft.Data.SqlClient.SNI.SNIPacket, Microsoft.Data.SqlClient.SNI.SNISMUXHeader)
00007EFEA8FF86E0 00007EFF455C54A0 Microsoft.Data.SqlClient.SNI.SNIMarsConnection.HandleReceiveComplete(Microsoft.Data.SqlClient.SNI.SNIPacket, UInt32)
00007EFEA8FF8750 00007EFF455C4F1B Microsoft.Data.SqlClient.SNI.SNIPacket+<>c__DisplayClass33_0.b__0(System.Threading.Tasks.Task1<Int32>) 00007EFEA8FF8800 00007EFF4310DE1A System.Threading.Tasks.ContinuationTaskFromResultTask1[[System.Int32, System.Private.CoreLib]].InnerInvoke() [//src/System.Private.CoreLib/shared/System/Threading/Tasks/TaskContinuation.cs @ 135]
00007EFEA8FF8820 00007EFF42F3A142 System.Threading.Tasks.Task+<>c.<.cctor>b__274_0(System.Object) [//src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2427]
00007EFEA8FF8830 00007EFF42F1ECE2 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [//src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 289]
00007EFEA8FF8870 00007EFF42F345C1 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [//src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2389]
00007EFEA8FF88F0 00007EFF42F343D8 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread) [//src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2321]
00007EFEA8FF8910 00007EFF42F3436B System.Threading.Tasks.Task.ExecuteFromThreadPool(System.Threading.Thread) [//src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2312]
00007EFEA8FF8920 00007EFF42F28B14 System.Threading.ThreadPoolWorkQueue.Dispatch() [//src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 663]
00007EFEA8FF89A0 00007EFF42F16B3B System.Threading.ThreadPoolWaitCallback.PerformWaitCallback() [//src/System.Private.CoreLib/src/System/Threading/ThreadPool.CoreCLR.cs @ 29]
00007EFEA8FF8D50 00007effbc817f7f [DebuggerU2MCatchHandlerFrame: 00007efea8ff8d50]
The above managed call stack gives the impression that thread was waiting to receive data from the network.
However, from TCPDump trace, we see server side had already sent back the packet (Frame 487) and client has acknowledged it (Frame 562). And then the client side waited for 35+ seconds, and then sent another packet to server (Frame 2177). And later network traffic became normal without delays.

It looks like the client socket layer received the data, but it did not notify the application in real time and was blocked somewhere.
How can we tell what blocked it?

@junchen2000 Hey, man, are you sure you'd like to share connection string containing password?

@voroninp, Thanks! Revised.

@junchen2000 would mind re-running your tests WITHOUT the transaction?

@Leonardo-Ferreira, I comment out the transaction. It only opens the connection and closes the connection for each thread.
No delays:
dragon@marlonvm:~/k8s-sql-timeout-repro/source/reprocli$ dotnet run
Task 00: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 381.0838
Task 00: Total - Elapsed: 00:00:00.4389760
Task 02: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 390.1555
Task 02: Total - Elapsed: 00:00:00.4405980
Task 01: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 390.2725
Task 01: Total - Elapsed: 00:00:00.4406879
Task 04: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 390.3906
Task 04: Total - Elapsed: 00:00:00.4405574
Task 05: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 1.8329
Task 05: Total - Elapsed: 00:00:00.0019143
Task 06: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2083
Task 06: Total - Elapsed: 00:00:00.0002659
Task 07: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2609
Task 07: Total - Elapsed: 00:00:00.0003122
Task 08: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2356
Task 08: Total - Elapsed: 00:00:00.0003324
Task 09: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.269
Task 09: Total - Elapsed: 00:00:00.0003064
Task 10: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2555
Task 10: Total - Elapsed: 00:00:00.0003168
Task 11: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2079
Task 11: Total - Elapsed: 00:00:00.0002616
Task 12: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1608
Task 12: Total - Elapsed: 00:00:00.0002120
Task 13: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1788
Task 13: Total - Elapsed: 00:00:00.0002219
Task 14: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1594
Task 14: Total - Elapsed: 00:00:00.0002130
Task 15: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1685
Task 15: Total - Elapsed: 00:00:00.0002248
Task 16: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1765
Task 16: Total - Elapsed: 00:00:00.0002265
Task 17: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1884
Task 17: Total - Elapsed: 00:00:00.0002391
Task 18: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1702
Task 19: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1653
Task 18: Total - Elapsed: 00:00:00.0002414
Task 19: Total - Elapsed: 00:00:00.0002107
Task 20: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1636
Task 20: Total - Elapsed: 00:00:00.0003681
Task 21: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.3245
Task 21: Total - Elapsed: 00:00:00.0003703
Task 22: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2136
Task 22: Total - Elapsed: 00:00:00.0002727
Task 23: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1729
Task 23: Total - Elapsed: 00:00:00.0002188
Task 24: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1678
Task 24: Total - Elapsed: 00:00:00.0002231
Task 25: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1831
Task 25: Total - Elapsed: 00:00:00.0002202
Task 26: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1574
Task 26: Total - Elapsed: 00:00:00.0002061
Task 27: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1653
Task 27: Total - Elapsed: 00:00:00.0001979
Task 28: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1363
Task 28: Total - Elapsed: 00:00:00.0002044
Task 29: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1558
Task 29: Total - Elapsed: 00:00:00.0002112
Task 30: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1525
Task 30: Total - Elapsed: 00:00:00.0002049
Task 31: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1786
Task 31: Total - Elapsed: 00:00:00.0002470
Task 32: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1836
Task 32: Total - Elapsed: 00:00:00.0002417
Task 33: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2061
Task 33: Total - Elapsed: 00:00:00.0002580
Task 35: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.2134
Task 35: Total - Elapsed: 00:00:00.0002727
Task 37: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1847
Task 37: Total - Elapsed: 00:00:00.0002219
Task 39: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1435
Task 39: Total - Elapsed: 00:00:00.0001966
Task 34: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1441
Task 34: Total - Elapsed: 00:00:00.0001977
Task 36: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1657
Task 36: Total - Elapsed: 00:00:00.0002115
Task 38: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 0.1429
Task 38: Total - Elapsed: 00:00:00.0002218
Task 03: Connection.Open started at 5/6/2020 5:55:53 AM;ended at 5/6/2020 5:55:53 AM - Elapsed 404.2743
Task 03: Total - Elapsed: 00:00:00.4545276
Total: 00:00:00.4811442

If I add SqlCommand part without the explicitly declared transaction, it shows the similar behavior as the transaction one.
Also, connection.BeginTransaction with different IsolationLevel （ReadCommitted, ReadUncommitted, or Snapshot) does not make any differences. It is always slow.

Can you run a second test?:
With and without a transaction, run a very fast command inside the loop, like a select on a table with a single row. I'm afraid that without actual work, the results are not that meaningful.
This should work with and without MARS be the SQLConnection object is not shared or re-used.

I was looking into this issue. I made couple of changes to the sample test. instead of using PLINQ as: Enumerable.Range(0, count)
.AsParallel()
.WithDegreeOfParallelism(count)
.ForAll(n => Scenario4(connectionString, n)); I used Parallel:                Parallel.For(0, count, (n=> { Scenario4(connectionString, n); }));
`
The application started to run and it ran to completion. It runs slower the NativeSNI and there are intermittent failures every couple of runs.
As it has been mentioned before there is a delay before running the application. Managed SNI uses ManualResetEventSlim to signal the thread synchronization. As MARS is not async it has been signaled to false. Read more here. I will look deeper into the issue next week.

Here is an update on the issue. As it was mentioned before the issue was using all available threads while using MangedSNI on windows or Linux. It took me a while to understand the pattern and connections in different classes.
When a packet is received there is a part of code that makes _packeEvent  which is an implementation of ManuaResetEventSlim wait for connectiontime out. by default connection timeout is 15 seconds. if you run the application you will see a delay of 15-17 seconds and errors start to run down. If the ConnectTimeOut is increased then the delay is increased.
This all go back to implementation of SNIMarsHandle inside the driver. The part that makes the delay is inside public override uint Receive(out SNIPacket packet, int timeoutInMilliseconds) which is get called by in the hierarchy by syncOverAsync method.
it forces the threads to wait by
if (!_packetEvent.Wait(timeoutInMilliseconds))
                    {
                        SNILoadHandle.SingletonInstance.LastError = new SNIError(SNIProviders.SMUX_PROV, 0, SNICommon.ConnTimeoutError, string.Empty);
                        return TdsEnums.SNI_WAIT_TIMEOUT;
                    }

I am trying to change the logic to use SpinWait class and SpinCount parameter inside the driver.
I will update here hopefully by end of this weekend.

I am trying to change the logic to use SpinWait class and SpinCount parameter inside the driver.

As I understand it what is happening here is that SNIMarsHandle.Receive is being called and is either pulling a packet out of the _receivedPacketQueue if one is already available or if there isn't a packet ready it hits the wait that you highlight above. At that point we really are waiting for data but we're doing sync over async so we can't release the current thread until we either have a packet or have failed by timing out. Whether you block or spin at this point it's still got to be a sync behaviour.
Can you identify why the packet isn't being received setting _packetEvent in the mars connection HandleReceiveComplete? tracing back through the jungle that is ManagedSNI I end up at SNIPacket.ReadFromStreamAsync which contains modern async code:
        public void ReadFromStreamAsync(Stream stream, SNIAsyncCallback callback)
        {
            stream.ReadAsync(_data, 0, _dataCapacity, CancellationToken.None)
                .ContinueWith(
                    continuationAction: _readCallback,
                    state: callback,
                    CancellationToken.None,
                    TaskContinuationOptions.DenyChildAttach,
                    TaskScheduler.Default
                );
        }

and that is going to use a threadpool thread to implement callback, no threadpool thread available no packet receipt. It might be worth looking at a custom task scheduler which handles this and give it a dedicated thread so threadpool exhaustion can't affect it. Let me know what you think.
Also looking at that we've not observing the read task which we should be.

It took longer than what we expected and it is going to take longer to solve the issue completely, but a quick workaround to use PLINQ with the M.D.S is changing the PLINQ part to the following:
 Enumerable.Range(0, count)                 .AsParallel()                 .WithDegreeOfParallelism(count)                 .ToList().ForEach(n => Scenario4(connectionString, n));
using this condition the code will run with no delay and hesitation.

Enumerable.Range(0, count) .AsParallel() .WithDegreeOfParallelism(count) .ToList().ForEach(n => Scenario4(connectionString, n))

This is the original code. Were you meant to paste something else here?

@pawelpabich the original code is:
Enumerable.Range(0,count)                     .AsParallel()                     .WithDegreeOfParallelism(count)                     .ForAll(n => Scenario4(connectionString, n));

This changes multi-threaded code into single-threaded code.  Unfortunately, that is not a realistic workaround.

nuget from the CI build above is at https://dev.azure.com/sqlclientdrivers-ci/7540d8a3-c1bc-4428-a007-d4b50b7762f4/_apis/build/builds/12581/artifacts?artifactName=Nuget&api-version=5.1&%24format=zip if any of you want to give it a try.

I will try to give it a try later on this week and I will report results.

Cool, let us know if you can. If that doesn't work I can open a draft PR with my task scheduler version which makes the test case above run like native on my machine.

Used https://github.com/benPearce1/k8s-sql-timeout-repro/tree/tiny again as the test case and the results are the same :(.
The app did not show anything for some time and then it crashed with the following error:
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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shouldReconnect)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
   at reprocli.Program.Scenario4(String connString, Int32 number)
   at reprocli.Program.<>c__DisplayClass0_0.<Main>b__0(Int32 n)
   at System.Linq.Parallel.ForAllOperator`1.ForAllEnumerator`1.MoveNext(TInput& currentElement, Int32& currentKey)
   at System.Linq.Parallel.ForAllSpoolingTask`2.SpoolingWork()
   at System.Linq.Parallel.SpoolingTaskBase.Work()
   at System.Linq.Parallel.QueryTask.BaseWork(Object unused)
   at System.Linq.Parallel.QueryTask.<>c.<.cctor>b__10_0(Object o)
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
ClientConnectionId:deefa466-454d-4de4-bdc7-6d5b0a50727b
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:8d5a3343-4785-4444-a328-2f99422b67a6
Routing Destination:d34e962792ea.tr2008.westus2-a.worker.database.windows.net,11015<---

ok, give this one a try if you can. Absolutely not production grade but it seems to solve the problem.
https://dev.azure.com/sqlclientdrivers-ci/7540d8a3-c1bc-4428-a007-d4b50b7762f4/_apis/build/builds/12658/artifacts?artifactName=Nuget&api-version=5.1&%24format=zip

@pawelpabich I cloned your code and tried it with the nuget that @Wraith2 posted in Managed SNI on Windows and it worked fine. I have not tried it on Linux. Can you double check if you are using the correct nuget package please?

@JRahnama which one? the first link was https://github.com/dotnet/SqlClient/pull/606 and the second from https://github.com/dotnet/SqlClient/pull/608 , they're different approaches.

@Wraith2 the first one. 606. I will test the second one today. Thnaks.

@JRahnama yes, even the current version of the client works on Windows. This issue is entirely about  Linux. It might be a good idea for you to set up a test env on Linux so you can get a quicker feedback cycle.

@Wraith2 , will do.

@Wraith2, unfortunately, I can still see the initial delay and then the app blows up with:
 ---> (Inner Exception #8) 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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shouldReconnect)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
   at reprocli.Program.Scenario4(String connString, Int32 number)
   at reprocli.Program.<>c__DisplayClass0_0.<Main>b__0(Int32 n)
   at System.Linq.Parallel.ForAllOperator`1.ForAllEnumerator`1.MoveNext(TInput& currentElement, Int32& currentKey)
   at System.Linq.Parallel.ForAllSpoolingTask`2.SpoolingWork()
   at System.Linq.Parallel.SpoolingTaskBase.Work()
   at System.Linq.Parallel.QueryTask.BaseWork(Object unused)
   at System.Linq.Parallel.QueryTask.<>c.<.cctor>b__10_0(Object o)
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
ClientConnectionId:e3f24189-e5f5-48dc-b62d-f84fb469a807
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:f94ba3f0-e1de-4ea0-bbb1-cbcde87872df
Routing Destination:d34e962792ea.tr2008.westus2-a.worker.database.windows.net,11015<---

@pawelpabich I have tested on docker with this fix and it ran to competition. I am setting up an ubuntu VM right now to see how it works on a dedicated VM. I will get back here after tests are done.

Weird. Using the original repro provided the current GA freezes 100% of the time so the replication is good and my PR unblocks it using the managed SNI. No idea why you're not seeing the same result. I'll have to leave it to the team to investigate further.

Just to make sure I'm not making a silly mistake here.
This is the version of the code I'm running:

MARS OFF (n=10)
There is no delay and the app finishes in 1 second.

MARS ON(n=10)
There is a delay and the app finishes in 10 seconds.

When I set n to 50 the app crashes with MARS is ON. The app finishes in 9 seconds when MARS is OFF

I tested on Unnix VM  got same result as yours @pawelpabich. I am not sure why Managed SNI works on Windows, but fails on Unix.
I am going to investigate 2 options:

Classes dedicated in the driver for Unix ( to see if any is involved)
Investigate threading in Unix  and Windows (to see if a dedicated class for Unix is needed in this case)

Thanks again for your patience.

@JRahnama could you give my solution a try on your real Linux build and see what happens?
Like you I really don't understand why we would see a platform difference when forcing the managed code but we need to identify it and stop it happening given the cost in support time.

@Wraith2

could you give my solution a try on your real Linux build and see what happens?

sure, I will test it today.

Like you I really don't understand why we would see a platform difference when forcing the managed code but we need to identify it and stop it happening given the cost in support time.

I am a bit confuses by the code behavior and totally agree with you, we need to fix this issue and put reliability back to managed SNI.

@Wraith2 I tested your solution on Ubuntu 18.04 and it failed. It behaved same as before. I will be debugging the driver on Ubuntu starting tomorrow and will update you on my findings soon. Thanks for doing this.

I noticed the fixes we introduced above are not fixing the issue on Windows as well. Simply, Windows swallows the error messages and does not run them. In order to see that, you need to move try/catch block from main to the Scenario4 for each request and run the application for 500, you will some of the numbers for 'n' are missing. The main problem is, threads are getting into a race/deadlock and to fix that we need to re-design Managed SNI. That is a big task to do and it is going to take a longer period of time to achieve that goal. I just wanted to mention that we are working on it. Thanks for your patience.

Hi Everyone,
Just to add additional context to this issue, if you're blocked by this issue and are bound to use MARS, please consider going Async as calling Async APIs does not cause threadpool starvation and can be used as a workaround, if possible to do so.
The above repro from issue description if modified to call Async APIs, works good: Link to Full Repro
We thank you for being patient, as we continue to investigate the issue on MARS + Sync operations in Managed SNI.

Are there any updates on a fix for this?
We've been having some major problems and have started rewriting anything that touches the database to use async as @cheenamalhotra recommended, but it's a massive refactor for us. Should we see any improvement from moving our most hit calls to be async, or will we only see a reduction in problems when we are no longer making any synchronous calls?
We're also considering moving back to Windows because it sounds like that would resolve the issue here?

@cheenamalhotra I had a look at your code it processes tasks sequentially which is why the thread pool is never exhausted and the code doesn't crash.  async2 option represents tyour code.
I implemented the async scenario slightly differently so more work is done in parallel and managed to trigger crash again.
Code: https://github.com/benPearce1/k8s-sql-timeout-repro/blob/tiny/source/reprocli/Program.cs
Total for sync with MARS(False): 00:00:12.8980585
Total for async with MARS(False): 00:00:16.9422388
Total for 'async2' with MARS(False): 00:01:00.5869437
Total for 'async2' with MARS(True): 00:01:05.7636023
Total for 'sync' with MARS(True):
riod elapsed prior to completion of the operation or the server is not responding.)) (One or more errors occurred. (Execution Tim
eout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.)) (One or more er
rors occurred. (Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not
responding.)) (One or more errors occurred. (Execution Timeout Expired.  The timeout period elapsed prior to completion of the op
eration or the server is not responding.)) (One or more errors occurred. (Execution Timeout Expired.  The timeout period elapsed
prior to completion of the operation or the server is not responding.)) (One or more errors occurred. (Execution Timeout Expired.
  The timeout period elapsed prior to completion of the operation or the server is not responding.)) (One or more errors occurred
. (Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.))
 (One or more errors occurred. (Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or th
e server is not responding.)) (One or more errors occurred. (Execution Timeout Expired.  The timeout period elapsed prior to comp
letion of the operation or the server is not responding.)) (Execution Timeout Expired.  The timeout period elapsed prior to compl
etion of the operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to complet
ion of the operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completio
n of the operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completion
of the operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completion of
 the operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completion of t
he operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completion of the
 operation or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completion of the o
peration or the server is not responding.) (Execution Timeout Expired.  The timeout period elapsed prior to completion of the ope
ration or the server is not responding.)
 ---> Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to complet
ion of the operation or the server is not responding.
 ---> System.ComponentModel.Win32Exception (258): Unknown error 258
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseI
nAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock,
 Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCop
ySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySi
mpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request
, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParser
StateObject stateObj, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String tra
nsactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, Is
olationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shou
ldReconnect)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
   at reprocli.Program.Sync(String connString, Int32 number)
   at reprocli.Program.<>c__DisplayClass0_0.<Main>b__0(Int32 n)
   at System.Linq.Parallel.ForAllOperator`1.ForAllEnumerator`1.MoveNext(TInput& currentElement, Int32& currentKey)
   at System.Linq.Parallel.ForAllSpoolingTask`2.SpoolingWork()
   at System.Linq.Parallel.SpoolingTaskBase.Work()
   at System.Linq.Parallel.QueryTask.BaseWork(Object unused)
   at System.Linq.Parallel.QueryTask.<>c.<.cctor>b__10_0(Object o)
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext,
 ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext,
 ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
ClientConnectionId:f184fcef-18d6-4d3c-8863-f93457a659a3
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:3aec6906-4b5c-4927-9d81-663145c94871
Routing Destination:f15d52b408d7.tr2639.westus2-a.worker.database.windows.net,11048```

`Total for 'async' with MARS(True)`

```---> (Inner Exception #30) Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period el
apsed prior to completion of the operation or the server is not responding.
 ---> System.ComponentModel.Win32Exception (258): Unknown error 258
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseI
nAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock,
 Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCop
ySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySi
mpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request
, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParser
StateObject stateObj, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String tra
nsactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, Is
olationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shou
ldReconnect)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
   at Microsoft.Data.SqlClient.SqlConnection.BeginDbTransaction(IsolationLevel isolationLevel)
   at System.Data.Common.DbConnection.BeginDbTransactionAsync(IsolationLevel isolationLevel, CancellationToken cancellationToken)
--- End of stack trace from previous location where exception was thrown ---
   at reprocli.Program.Async(String connString, Int32 number)
ClientConnectionId:baa36076-82d2-4be6-9c98-dcf6b50680f0
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:c9942102-8655-42d2-ad4c-deaf7d80be9a
Routing Destination:f15d52b408d7.tr2639.westus2-a.worker.database.windows.net,11048<---

 ---> (Inner Exception #31) Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period el
apsed prior to completion of the operation or the server is not responding.
 ---> System.ComponentModel.Win32Exception (258): Unknown error 258
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseI
nAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock,
 Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
   at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCop
ySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySi
mpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request
, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParser
StateObject stateObj, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String tra
nsactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, Is
olationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at Microsoft.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shou
ldReconnect)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Microsoft.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
   at Microsoft.Data.SqlClient.SqlConnection.BeginDbTransaction(IsolationLevel isolationLevel)
   at System.Data.Common.DbConnection.BeginDbTransactionAsync(IsolationLevel isolationLevel, CancellationToken cancellationToken)
--- End of stack trace from previous location where exception was thrown ---
   at reprocli.Program.Async(String connString, Int32 number)
ClientConnectionId:6350ab92-d4fa-4e0e-aa34-677c9761a6cb
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:4c7dd573-7d2c-436d-bd88-a04f4077b76c```

Tasks processed sequentially:

I spent the day doing some more digging into this because I wanted to know why my previous suggestions didn't work. I understand now.
The root cause of the problem is the difference between how receives are dispatched when using a physical handle directly and through a mars handle.
When using a physical handle (tcp or named pipes, both end up as a socket/stream, i'm going to use tcp examples) directly if you request to read from it you will block waiting for the read. This is ok because the caller is the only person who will be interacting with the handle.
Mars is a multiplexing of abstract mars handles layered on top of a single physical handle. That means that multiple receives could be requests for a single physical handle and you can't block on the handle waiting for data because you'll end up with serializing behaviour which contrary to the goals of mars. When the code enables mars on a connection it wraps the physical handle in a MarsConnection object and changes the data receipt callbacks so that instead of calling the physical handle receive they call the mars connection receive in SNIMarsConnection.HandleReceiveComplete, and then it initiates an async receive in SNIMarsConnection.StartReceive which effectively starts a runloop which is kept moving by the receive handler. When a packet is recieved the mars header is checked, the marching abstract handle is found and it is passed the contents of the packet minus the header. So multiplexing is handled using async calls and that's the root cause of the problem because that async infrastructure requires worker threads to handle continuations and if there aren't any it stops working.
I tried plumbing my sni task scheduler which forces the use of a dedicated thread into this and it didn't work because I can't get deep enough and I realise that even if I do manage to make it work there's a scalability problem. If I dedicate a thread to processing those async receives it will inevitably end up doing arbitrary work that is going to include locks and waits but this can't be permitted because if a wait occurs for one on one connection it can now affect another connection. So then you think that we could have multiple but how many do you need? how do measure load and adapt to it correctly to not waste resources? Fine, one thread per connection! but now you're doing to end up with a dedicated thread for every mars enabled connection that you open which is incredibly wasteful. What you need is a way to get a usable thread from something that can scale, a threadpool... and now we're back to the start.
The problem is that exhausting the threadpool by requesting far more threads than it can provide prevents the use of that threadpool by internal parts of the driver because you weren't expecting it to be doing async things. It is doing async things and it's doing them for pragmatic and explainable reasons. You can avoid the problem by using the threadpool api to force scale the threadpool for your needs. I don't see a good way to architect around this behaviour in a way that doesn't waste masses of threads.

Looks like this issue has hit The Register :) https://www.theregister.com/2020/12/11/buggy_behavior_sqlclient/

Interesting. Perhaps all those extra eyes can help identify a solution. What I think we need is a cross platform way to do non-blocking async io which doesn't rely on the threadpool. On windows that's IOCP but dropping to planform specifics in this implementation is highly undesirable. The goal of the managed SNI is to have implementation parity for all supported OS' so behaviour and perf are identical at this layer

What I think we need is a cross platform way to do non-blocking async io which doesn't rely on the threadpool. On windows that's IOCP but dropping to platform specifics in this implementation is highly undesirable. The goal of the managed SNI is to have implementation parity for all supported OS' so behaviour and perf are identical at this layer

I agree. The fundamental building blocks of CLR need to be predictable no matter what supported platform they run on.

I also agree that The fundamental building blocks of the platform need to be predictable no matter what supported OS they run on. but we must acknowledge that is fantasy... unless we mean predictable=same output... if predictable=same output in the same time frame we are going to have a big problem that will probably never be predictable.
When dealing with such specific matters (OS Thread pooling strategy such as IOCP for windows vs. ePoll for linux) I think its completely reasonable to have OS specific implementations because the underlying strategy is different! It would be lovely to have a cross-platform API to unify this feature but the hard truth is that there is not and we need to do deliver the best performance we can, so, with that in mind, I think that a nasty, cringe-worthy, #if Linux approach, until new opportunities comes along.

Looks like this issue has hit The Register :) https://www.theregister.com/2020/12/11/buggy_behavior_sqlclient/

that became the front-page for the Code-Project newsletter today...

Are there any updates on this? It looks like this is slated for v4.0 of SqlClient, do we have an estimated release date for that?

I think that the milestone means that it is hoped to be addressed in V4, it doesn't mean that there is a known fix yet, and as far as I know there isn't. Extensive use of tasks can overload the threadpool and there isn't a lot you can do about it.

In other thread suggested update dependency
instead of relying on SqlServer peer-dependency itself, because it requires just 2.0.4 as I remember. Manually added this to my project and issue has gone for me as I see.

We are having the same issue. But we are not starting a lot of Tasks. We have EF6 and net core 5 in Linux. And when we send about 10 request/sec to a REST endpoint that does some EF6 queries then we receive deadlocks and SQL timeouts. When we disable MARS then everything is fine.

E

you can manually add nuget Microsoft.Data.SqlClient with version 3.0.0 to DB project. It will stop failing, but still will work not so fast.
Because by default EF core with lower version of this library (2.0.1)

@DanielHillebrandSWMS Just add an explicit reference to 3.0.1 from your project.
EF Core 6 still uses 2.1.x, as 3.0 is not LTS (long term support)

@ErikEJ Thanks, that is what we did. I will also try with 3.0.1 instead of 3.0.0.
I just wanted to know when we get the fix right out of the box. The workaround via explicit ref is not easy to find and I guess there are many people out there losing time with this issue.

@Wraith2 Exactly. And you're right, that is not an issue of SqlClient but of Entity Framework. Will have a look at the EF repo. Thank you
BTW: We are not using MARS
Version 3.0.x fixes our problem. But reading about pending implementation for v4 I am not sure if there are still issues that can occur that I should be worried about.

Changed to "some" - maybe also some authentication limitations, and thread pool limitations?

There are some issues with Linux, as you can see here - switching platform requires due diligence!

That's why we are testing the app. We didn't just deploy it to production.

@cheenamalhotra thanks, will do. Enabling MARS and we still get the same issue just FYI.

@Will-Bill as @cheenamalhotra mention:

This issue specifically is for MARS enabled connections.

Enabling MARS will cause the issue.
Can you post stack trace or the exception by any chance?

@JRahnama this error is happening with and without MARS enabled. I moved over to Windows app service and no longer see the issue. Here are some logs / stack traces from the issue in Linux app service:
2021-11-08T03:20:48.503991031Z fail: M.Tasks.ScheduledTaskRunner[0]
2021-11-08T03:20:48.504061232Z       Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
2021-11-08T03:20:48.504069732Z       Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
2021-11-08T03:20:48.504075632Z        ---> System.ComponentModel.Win32Exception (258): Unknown error 258
2021-11-08T03:20:48.504081332Z          at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) 2021-11-08T03:20:48.504086732Z          at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) 2021-11-08T03:20:48.504092132Z          at Microsoft.Data.SqlClient.SqlCommand.InternalEndExecuteNonQuery(IAsyncResult asyncResult, Boolean isInternal, String endMethod) 2021-11-08T03:20:48.504097332Z          at Microsoft.Data.SqlClient.SqlCommand.EndExecuteNonQueryInternal(IAsyncResult asyncResult) 2021-11-08T03:20:48.504102432Z          at Microsoft.Data.SqlClient.SqlCommand.EndExecuteNonQueryAsync(IAsyncResult asyncResult) 2021-11-08T03:20:48.504107632Z          at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization) 2021-11-08T03:20:48.504115932Z       --- End of stack trace from previous location --- 2021-11-08T03:20:48.504121033Z          at Dapper.SqlMapper.ExecuteImplAsync(IDbConnection cnn, CommandDefinition command, Object param) in /_/Dapper/SqlMapper.Async.cs:line 654 2021-11-08T03:20:48.504126533Z          at M.Web.Apps.BS.Tasks.CleanupSessions.OnExecute() in C:\projects\a\src\Apps\M.Web.Apps.BS\Tasks\CleanupSessions.cs:line 48 2021-11-08T03:20:48.504132833Z          at M.Tasks.SchedulableTask.Execute() in C:\projects\a\src\Lib\M\Tasks\SchedulableTask.cs:line 10 2021-11-08T03:20:48.504138833Z          at M.Tasks.ScheduledTaskRunner1.Execute(IJobExecutionContext context) in C:\projects\a\src\Lib\M\Tasks\ScheduledTaskRunner.cs:line 58
2021-11-08T03:20:48.504144633Z       ClientConnectionId:8145ffe1-849c-4e75-ad66-e898c1e04af4
2021-11-08T03:20:48.504149733Z       Error Number:-2,State:0,Class:11
2021-11-08T03:20:48.504156133Z       ClientConnectionId before routing:43a6bdf1-8448-4515-b635-0c7278c9393a
2021-11-08T03:20:48.504162333Z       Routing Destination:b3cf7253e378.HS2.tr2050.uksouth1-a.worker.database.windows.net,11010
2021-11-08T04:38:56.846664034Z fail: Quartz.Impl.AdoJobStore.ConnectionAndTransactionHolder[0]
2021-11-08T04:38:56.846712234Z       Couldn't rollback ADO.NET connection. Transaction not connected, or was disconnected
2021-11-08T04:38:56.846718434Z       System.InvalidOperationException: Transaction not connected, or was disconnected
2021-11-08T04:38:56.846723735Z          at Quartz.Impl.AdoJobStore.ConnectionAndTransactionHolder.CheckNotZombied()
2021-11-08T04:38:56.846738635Z          at Quartz.Impl.AdoJobStore.ConnectionAndTransactionHolder.Rollback(Boolean transientError)
2021-11-08T04:38:56.849420668Z fail: Quartz.Impl.AdoJobStore.ClusterManager[0]
2021-11-08T04:38:56.849450168Z       Error managing cluster: Couldn't commit ADO.NET transaction. Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
2021-11-08T04:38:56.849456468Z       Operation cancelled by user.
2021-11-08T04:38:56.849460568Z       Quartz.JobPersistenceException: Couldn't commit ADO.NET transaction. Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
2021-11-08T04:38:56.849465568Z       Operation cancelled by user.
2021-11-08T04:38:56.849470169Z        ---> Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
2021-11-08T04:38:56.849474769Z       Operation cancelled by user.
2021-11-08T04:38:56.849479069Z        ---> System.ComponentModel.Win32Exception (258): Unknown error 258
2021-11-08T04:38:56.849483369Z          at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction) 2021-11-08T04:38:56.849487569Z          at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) 2021-11-08T04:38:56.849492369Z          at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) 2021-11-08T04:38:56.849497369Z          at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) 2021-11-08T04:38:56.849502569Z          at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest) 2021-11-08T04:38:56.849508369Z          at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest) 2021-11-08T04:38:56.849513769Z          at Microsoft.Data.SqlClient.SqlInternalTransaction.Commit() 2021-11-08T04:38:56.849530569Z          at Microsoft.Data.SqlClient.SqlTransaction.Commit() 2021-11-08T04:38:56.849535169Z          at Quartz.Impl.AdoJobStore.ConnectionAndTransactionHolder.Commit(Boolean openNewTransaction) 2021-11-08T04:38:56.849539569Z       ClientConnectionId:50c6fe7b-a09c-4776-b348-30b679be9bef 2021-11-08T04:38:56.849543969Z       Error Number:-2,State:0,Class:11 2021-11-08T04:38:56.849548470Z       ClientConnectionId before routing:fe2eba90-b964-47c3-9953-8ae0e962c0e7 2021-11-08T04:38:56.849552670Z       Routing Destination:b3cf7253e378.HS2.tr2050.uksouth1-a.worker.database.windows.net,11010 2021-11-08T04:38:56.849556670Z          --- End of inner exception stack trace --- 2021-11-08T04:38:56.849560670Z          at Quartz.Impl.AdoJobStore.ConnectionAndTransactionHolder.Commit(Boolean openNewTransaction) 2021-11-08T04:38:56.849564770Z          at Quartz.Impl.AdoJobStore.JobStoreSupport.DoCheckin(Guid requestorId, CancellationToken cancellationToken) 2021-11-08T04:38:56.849568870Z          at Quartz.Impl.AdoJobStore.JobStoreSupport.DoCheckin(Guid requestorId, CancellationToken cancellationToken) 2021-11-08T04:38:56.849573070Z          at Quartz.Impl.AdoJobStore.ClusterManager.Manage() [See nested exception: Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. 2021-11-08T04:38:56.849577770Z       Operation cancelled by user. 2021-11-08T04:38:56.849581570Z        ---> System.ComponentModel.Win32Exception (258): Unknown error 258 2021-11-08T04:38:56.849586070Z          at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
2021-11-08T04:38:56.849589970Z          at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
2021-11-08T04:38:56.849594470Z          at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
2021-11-08T04:38:56.849598770Z          at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
2021-11-08T04:38:56.849604170Z          at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
2021-11-08T04:38:56.849609270Z          at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
2021-11-08T04:38:56.849614370Z          at Microsoft.Data.SqlClient.SqlInternalTransaction.Commit()
2021-11-08T04:38:56.849618770Z          at Microsoft.Data.SqlClient.SqlTransaction.Commit()
2021-11-08T04:38:56.849628871Z          at Quartz.Impl.AdoJobStore.ConnectionAndTransactionHolder.Commit(Boolean openNewTransaction)
2021-11-08T04:38:56.849633671Z       ClientConnectionId:50c6fe7b-a09c-4776-b348-30b679be9bef
2021-11-08T04:38:56.849637671Z       Error Number:-2,State:0,Class:11
2021-11-08T04:38:56.849641871Z       ClientConnectionId before routing:fe2eba90-b964-47c3-9953-8ae0e962c0e7
2021-11-08T04:38:56.849646771Z       Routing Destination:b3cf7253e378.HS2.tr2050.uksouth1-a.worker.database.windows.net,11010]

@Will-Bill this is more like issue #647 than this one. If you have a stand a loan repro that could reproduce the issue, feel free to open a new issue please. Many factors could be causing the issue #647. Having a repro will help us to identify the issue and speed up the investigation at our side.
Also, please re-evaluate your queries and server indexes in standalone repro apps. I would also highly recommend testing your case with latest driver Microsoft.Data.SqlClient version v3.0.1 or very latest preview release4.0.0-preview3.21293.2 to get benefit from fixes already done. If queries do not complete on time "genuinely" due to large row data being read, you may want to modify queries or increase "CommandTimeout" if required to do so.

@JRahnama thanks for the reply. If we would be able to reproduce in a repo that would of course be helpful but we cannot. It seems random. The website might run 48 hours or 2 hours before it crashes.
Moving to Windows App service with zero code changes 'fixes' the issue.
We are using 3.0.1 - will try 4 in the future. Right now just happy the site isn't going down randomly.

@JRahnama thanks for the reply. If we would be able to reproduce in a repo that would of course be helpful but we cannot. It seems random. The website might run 48 hours or 2 hours before it crashes.

Just an idea: Would you be able to log the (SQL) statement +params that triggered the exception right before the app hangs? Just in case it is something specific in terms of size, complexity, transactions that could be used to reproduce the bug. When we had a similiar problem I could reproduce it every time with a certain query-size (insert).

@JRahnama at least for me the problem was using MARS with .net core 2.2 (I know we must upgrade, but in the time being we can't)
The same code is working with .net core 3.1, .net 5 and .net 6.
I could repro that by messing with the Synchronization Context when running on docker. It hangs on connection.BeginTransaction(). What I couldn't figure out is why (when running on docker) the call to BeginTransaction tries to execute some action on the CustomSynchronizationContext causing a deadlock and in my case that's the cause of the timeouts. That call to the Synchronization Context only happens on Docker using MARS.
Below you can find the Events generate by the Source:
<prov.DbConnectionHelper.ConnectionString_Set|API> 1, 'Server=tcp:host.docker.internal;Database=master;User ID=sa;MultipleActiveResultSets=true;Trusted_Connection=False;Trust Server Certificate = true;'
<sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.
<sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `SqlConfigurableRetryLogicConnection`. Default value of `T` type returns.
<sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `SqlConfigurableRetryLogicCommand`. Default value of `T` type returns.
<sc|SqlAuthenticationProviderManager|Ctor|Info>No SqlAuthProviders configuration section found.
TdsParser.Connect | SEC | Connection Object Id 4, Authentication Mode: SqlPassword
<sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `AppContextSwitchOverrides`. Default value of `T` type returns.
<sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Entry point.
<sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Exit point.
SNIProxy.CreateConnectionHandle | Info | Session Id abffadde-8175-4bcd-8132-8960223f0e22, SNI Handle Type: Microsoft.Data.SqlClient.SNI.SNITCPHandle
TdsParserStateObjectManaged.CreatePhysicalSNIHandle | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22, ServerName tcp:host.docker.internal, Async = True
TdsParserStateObjectManaged.GetConnectionId | Info | Session Id abffadde-8175-4bcd-8132-8960223f0e22
<sc.TdsParser.Connect|SEC> Sending prelogin handshake
<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID abffadde-8175-4bcd-8132-8960223f0e22, ActivityID d3b55897-3d50-4877-adfa-11f71b95329c:2
TdsParserStateObjectManaged.WritePacket | Info | Session Id abffadde-8175-4bcd-8132-8960223f0e22, SendAsync Result 0
<sc.TdsParser.Connect|SEC> Consuming prelogin handshake
TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22
TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22, Packet DataLeft 54
TdsParserStateObjectManaged.EnableSsl | Info | Session Id abffadde-8175-4bcd-8132-8960223f0e22
TdsParserStateObjectManaged.WritePacket | Info | Session Id abffadde-8175-4bcd-8132-8960223f0e22, SendAsync Result 0
TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22
TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22, Packet DataLeft 485
<sc.TdsParser.TryRun|SEC> Received login acknowledgement token
TdsParserStateObjectManaged.EnableMars | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22
TdsParserStateObjectManaged.CreateMarsSession | Info | State Object Id 1, Session Id abffadde-8175-4bcd-8132-8960223f0e22, Async = True
TdsParserStateObjectManaged.CreateSessionHandle | Info | State Object Id 2, Session Id 0565fdc5-c639-4abb-bea2-249effdf4b2c
<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn.
<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created.
TdsParserStateObjectManaged.WritePacket | Info | Session Id 0565fdc5-c639-4abb-bea2-249effdf4b2c, SendAsync Result 0
TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 2, Session Id 0565fdc5-c639-4abb-bea2-249effdf4b2c
SqlError.ctor | ERR | Info Number -2, Error State 0, Error Class 11, Error Message 'Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.', Procedure '', Line Number 0
TdsParserStateObjectManaged.CreateAndSetAttentionPacket | Info | State Object Id 2, Session Id 0565fdc5-c639-4abb-bea2-249effdf4b2c
TdsParserStateObjectManaged.WritePacket | Info | Session Id 0565fdc5-c639-4abb-bea2-249effdf4b2c, SendAsync Result 0
TdsParserStateObject.SendAttention | Info | State Object Id 2, Sent Attention.
TdsParserStateObject.SendAttention | Info | State Object Id 2, Attention sent to the server.
TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 2, Session Id 0565fdc5-c639-4abb-bea2-249effdf4b2c
<sc.SqlInternalConnectionTds.BreakConnection|RES|CPOOL> 4, Breaking connection.