Add experimental mars IO task scheduler

[Wraith2]

Addresses #422 but does not "fix" it, the fix is not to overload the system thread pool starving asynchronous operations of the cpu resources needed to do the requested work.

This adds a netcore3.1 or later specific task scheduler which uses dedicated threads to handle mars io when the system thread pool has queued tasks waiting. The only work done on these dedicated threads io work required to keep mars functioning and once data has been received any other async work will proceed on user threads as normal. No user code will execute on these threads.

The behaviour observed is that as soon as the system thread pool becomes overloaded the mars io threads take over and continue to do mars io work until the system thread pool becomes less saturated, A demand changes the io is diverted to the dedicated threads as needed but we prefer the system thread pool. This is a simple scheduler taken from the dotnet example code and so it does not attempt to grow or shrink the number of threads, it is hardcoded at 3 for this PR but could be changed.

To use this requires two appsettings, preferably in Main

AppContext.SetSwitch("Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows", true);
AppContext.SetSwitch("Switch.Microsoft.Data.SqlClient.UseExperimentalMARSThreading", true);

[roji]

@Wraith2 is this ultimately needed because the managed MARS implementation does sync-over-async internally? If so, it's important to make sure everyone understands this isn't a real fix (as you've mentioned above), and I do hope there'll be a plan for properly fixing this (i.e. by modifying the managed MARS implementation to stop doing symc-over-async). I understand why you'd do this (and not criticizing at all) - it's just that adding complex temporary workarounds ultimately makes the driver even more complicated to maintain etc.

FWIW Npgsql also does sync-over-async internally in some specific scenario, and therefore also moves completions to executer in a dedicated pool - so similar to what you've done here. Though in the Npgsql case this is done because of an actual constraint in the communication with PostgreSQL, rather than a driver implementation issue which could be fixed (as I'm assuming is the case here).

[Wraith2]

is this ultimately needed because the managed MARS implementation does sync-over-async internally?

Yup.

I do hope there'll be a plan for properly fixing this (i.e. by modifying the managed MARS implementation to stop doing symc-over-async).

I don't really see a way to avoid that it because you have to keep moving messages on a muxed connection or you can block one mux with another. If you have a sync connection that isn't moving because it's waiting on something it would block all the other sync connections on the same mux, that would be a breaking change in behaviour.
If someone comes up with a better way to alleviate or entirely fix this I'm sure the team will gladly accept it but the best we've got so far is people saying that we should rewrite huge chunks of the driver. That's not feasible at this time.

This is the minimal workaround. I took a sample which is known to work and has been thoroughly audited by people in runtime familiar with it and added the smallest set of changes possible to use it. I don't really like using this approach which is why I've not pushed it to a PR before but i don't see another way to change the current behaviour. A lot of other work on the driver is stuck behind this support issue so i'd like to see this out of the way even if it is temporarily so that we can get on with the work of modernising the code and get to a situation where rewriting the code is possible.

[roji]

If you have a sync connection that isn't moving because it's waiting on something it would block all the other sync connections on the same mux, that would be a breaking change in behaviour.

I don't know anything about how MARS is implemented, but I'd assume that a muxed physical connection would involve buffering data for the various commands. If a read comes in for data that has already been buffered, it wouldn't need to do I/O at all; and if the data hasn't yet been buffered, then in any case we need to wait for the new data to come in after the currently-blocking read is done., But again, this is a completely external point of view and I may be misunderstanding the whole thing.

More importantly, unless I'm mistaken, the Windows non-managed implementation doesn't seem to be suffering from this issue. If that's so, so it may be worth looking into what it does (if it can do it, maybe the managed implementation can do the same).

[Wraith2]

More importantly, unless I'm mistaken, the Windows non-managed implementation doesn't seem to be suffering from this issue. If that's so, so it may be worth looking into what it does (if it can do it, maybe the managed implementation can do the same).

It wouldn't use a managed thread pool thread so it wouldn't have this problem. It can use a dedicated thread or another method of completion notification. The code is closed so I can't look but the MS team can and haven't pulled any inspiration from however it works so I assume it isn't applicable to the managed version.

As you say this is a workaround. It's not a great one but it does seem to work reasonably well. In testing I got a single trapped connection throw an exception with 200 parallel threads over 16 cores. The single one is the on that hits the threadpool just before it starts to have a queue length>0. Overall this keeps things moving so it's better than nothing, but only just.

[David-Engel]

It wouldn't use a managed thread pool thread so it wouldn't have this problem. It can use a dedicated thread or another method of completion notification. The code is closed so I can't look but the MS team can and haven't pulled any inspiration from however it works so I assume it isn't applicable to the managed version.

As you say this is a workaround. It's not a great one but it does seem to work reasonably well. In testing I got a single trapped connection throw an exception with 200 parallel threads over 16 cores. The single one is the on that hits the threadpool just before it starts to have a queue length>0. Overall this keeps things moving so it's better than nothing, but only just.

You are spot on for the native SNI code. Completions don't rely on the managed threadpool so they don't get blocked. I've heard the term CPIO thrown around relative to the native socket calls.

I wish there was a way to detect that first blocked thread. Is there a place we can use our own threadpool for all async network read completions so that no reads are ever blocked?

[Wraith2]

We can simply force all mars IO onto our own threads, that's as simple as changing:

if (LocalAppContextSwitches.UseExperimentalMARSThreading
-#if NETCOREAPP31_AND_ABOVE
-                    && ThreadPool.PendingWorkItemCount>0
-#endif

To take out the ThreadPool work item count, just use our ThreadPool if the switch is set. I did this in testing and it works. The problem is that it won't scale because I've just forced the number of threads to an arbitrary number, 3. If someone generates enough IO to saturate those 3 threads we're back in the same position but with a worse ThreadPool that won't add new threads. If we want it to scale we end up with our own ThreadPool implementation and that's very hard and a big resource burden for maintenance.

I may be too pessimistic though. I'd like to at some feedback from people experiencing this problem to see if much better is good enough. Much better paired with retry could entirely mask the problem.

[Wraith2]

Any feedback on this? I thought it was a fairly major issue that wanted solving.

[David-Engel]

I'm okay with this PR. It would be nice to get some feedback from users on #422. Even if no one responds there, this seems like it would be pretty safe to merge for the next preview. If it causes issues, we can easily revert it.

[Wraith2]

it would be pretty safe to merge for the next preview. If it causes issues, we can easily revert it.

That's what I was hoping for. People will need to turn it on to try it though.

[HumanAftrAll]

I'm ready to try this on sandbox, running stress tests. Problem is my API's are 2.2, not 3.1.

[Wraith2]

It'll work on 2.1 you'll just get all mars io on the dedicated scheduler.
You should really upgrade from 2.1 though it's out of support and later runtime are a lot better.

[DavoudEshtehari]

No argument on this is not a fix for #422.
I tried with the original repro on #422 and iterations 10, 20, 50, and 100 for a MARS-enabled connection string, and I didn't see a tangible difference.
May I ask you to explain how to measure the effect of this change on issue 422?

[Wraith2]

If you have 20 threadpool threads and try to start 100 connections the threadpool threads are quickly consumed trying to do open tasks and there is little time left for them to work on the async task needed to keep mars moving.

If you look at the image in the top post in this thread you'll see that there are 3 lanes for mars io dedicated threads and then a large number of existing thread pool threads, then towards the bottom you see new threads being added in a stepped pattern at a rate of roughly 1 per second. This is the thread pool hill climbing algorithm adding threads slowly under pressure.

All this change does it make it so that there is always some amount of thread time available for mars async receive operations by detecting task pressure (in an admittedly crude way) and diverting the mars task activity onto separate threads which can't be consumed by users' tasks.

I'm very surprised it makes no difference for you. That makes me wonder if it's turned on. The difference for me is clear. Instead of a large delay at the start of the test run tasks immediately start running, Without this there is a 10 second pause while a number of connections start to open and then hang because the messages aren't being pumped and then a number of them timeout after which newly opened connections start making progress. With this change I immediately see progress being made and sometimes I'll see a timeout.

[David-Engel]

I tested this against my copy of the 422 repro, too. It resulted on zero hangs and the repro passing.

The only thing I ran into was already there without these changes. The 422 repro still makes this show up (at the end) when running under the debugger:

Regardless of that issue, which I don't think even manifests in a dependent app, I think these changes are good step forward for 422.

[Wraith2]

That happens occasionally with async things that are delayed. Essentially a packet is waiting to be scheduled but the connection is closed first meaning the stream is now null, we could quite easily just null check and quietly exit in that case, It is something on my list of things to get around to and would be handled if I get the chance to extend nullability annotations down into the managed sni implementation.

[DavoudEshtehari]

It works on Windows. By running on Linux I found the following exceptions:

System.PlatformNotSupportedException: The original message is: COM Interop is not supported on this platform.
NullReferenceException: Object reference not set to an instance of an object.

Check the output from Linux:

*************** Running issue #422 **************

Waiting time: 00:00:00.0172121 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 7 for iteration number of: 0.
Waiting time: 00:00:00.0171328 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 4 for iteration number of: 0.
Waiting time: 00:00:00.0172067 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 8 for iteration number of: 0.
Waiting time: 00:00:00.0174134 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 5 for iteration number of: 0.
Waiting time: 00:00:00.0171937 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 2 for iteration number of: 0.
Waiting time: 00:00:00.0172177 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 1 for iteration number of: 0.
Waiting time: 00:00:00.0171853 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 3 for iteration number of: 0.
Waiting time: 00:00:00.0174726 The original message is: COM Interop is not supported on this platform.. exception type is: System.PlatformNotSupportedException. It happened at Number: 6 for iteration number of: 0.
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Number: 0. All Queries. Time: 00:00:00.0343319
Unhandled exception. System.AggregateException: One or more errors occurred. (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (One or more errors occurred. (Object reference not set to an instance of an object.)) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.) (Object reference not set to an instance of an object.)
---> System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.MoveNext(TInput& currentElement, Int32& currentKey)
at System.Linq.Parallel.ForAllSpoolingTask2.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) --- End of inner exception stack trace --- at System.Linq.Parallel.QueryTaskGroupState.QueryEnd(Boolean userInitiatedDispose) at System.Linq.Parallel.SpoolingTask.SpoolForAll[TInputOutput,TIgnoreKey](QueryTaskGroupState groupState, PartitionedStream2 partitions, TaskScheduler taskScheduler)
at System.Linq.Parallel.DefaultMergeHelper2.System.Linq.Parallel.IMergeHelper<TInputOutput>.Execute() at System.Linq.Parallel.MergeExecutor1.Execute()
at System.Linq.Parallel.MergeExecutor1.Execute[TKey](PartitionedStream2 partitions, Boolean ignoreOutput, ParallelMergeOptions options, TaskScheduler taskScheduler, Boolean isOrdered, CancellationState cancellationState, Int32 queryId)
at System.Linq.Parallel.PartitionedStreamMerger1.Receive[TKey](PartitionedStream2 partitionedStream)
at System.Linq.Parallel.ForAllOperator1.WrapPartitionedStream[TKey](PartitionedStream2 inputStream, IPartitionedStreamRecipient1 recipient, Boolean preferStriping, QuerySettings settings) at System.Linq.Parallel.UnaryQueryOperator2.UnaryQueryOperatorResults.ChildResultsRecipient.Receive[TKey](PartitionedStream2 inputStream) at System.Linq.Parallel.ScanQueryOperator1.ScanEnumerableQueryOperatorResults.GivePartitionedStream(IPartitionedStreamRecipient1 recipient) at System.Linq.Parallel.UnaryQueryOperator2.UnaryQueryOperatorResults.GivePartitionedStream(IPartitionedStreamRecipient1 recipient) at System.Linq.Parallel.QueryOperator1.GetOpenedEnumerator(Nullable1 mergeOptions, Boolean suppressOrder, Boolean forEffect, QuerySettings querySettings) at System.Linq.Parallel.ForAllOperator1.RunSynchronously()
at System.Linq.ParallelEnumerable.ForAll[TSource](ParallelQuery1 source, Action1 action)
at AllManagedSNITests._422.RunTest(String connString, Int32 iterationCount) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 26
at AllManagedSNITests.Program.Main(String[] args) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/Program.cs:line 51
---> (Inner Exception #1) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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)<---

---> (Inner Exception #2) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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)<---

---> (Inner Exception #3) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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)<---

---> (Inner Exception #4) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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)<---

---> (Inner Exception #5) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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)<---

---> (Inner Exception #6) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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)<---

---> (Inner Exception #7) System.NullReferenceException: Object reference not set to an instance of an object.
at AllManagedSNITests._422.Scenario4(String connString, Int32 number) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 70
at AllManagedSNITests._422.<>c__DisplayClass0_0.b__0(Int32 n) in /mnt/c/Users/deshtehari/WSL-SqlClient-Wraith2/RunAllTests/422.cs:line 24
at System.Linq.Parallel.ForAllOperator1.ForAllEnumerator1.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.RunTaskSynchronously(Object o)
at System.Threading.Tasks.Task.InnerInvoke()
at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
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.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)<---

Aborted

[Wraith2]

Is there any way you could add in a first chance exception handler and see if you can get some sort of coherent stack trace information so I can identify what's using COM? Async stack traces like that are virtually useless and adding in the xunit spam just makes them worse.

[DavoudEshtehari]

I ran it on command mode without attached debugger. If you add event source traces in your code I'll collect those logs.

[Wraith2]

I've added a first chance handler that will be initialized before any tasks are put onto the new scheduler. If triggered it should dump the stack trace to the console and sni trace log.
As you're aware I don't have a linux system or the knowledge required to set one up so I can't debug this on native linux. Linux and I don't get along despite me trying to many times.

[Wraith2]

@DavoudEshtehari can I get those traces?

[Wraith2]

Doh, of course setting ApartmentState needs com support. I've removed that from the scheduler. Can you try again including that last commit please.

[DavoudEshtehari]

The exception is fixed. But I don't see any improvement on Linux. Is this what you expected?

[Wraith2]

It working is an improvement of sorts but no that isn't what I expect. For both @David-Engel and I enabling the switch AppContext.SetSwitch("Switch.Microsoft.Data.SqlClient.UseExperimentalMARSThreading", true); changes how the repro for 422 behaves by removing the initial pause and timeouts that we see.

Given that I haven't changed the unmanaged implementation it shows that we were both using the managed implementation when testing on windows when we saw the improvement. I don't know why it wouldn't repro on linux.

[DavoudEshtehari]

I can see the improvement in Windows. Apparently, thread management is not similar on Windows and Linux. I'm wondering if it's something that should be added to the dotnet/runtime list.

[Wraith2]

Unfortunately I just don't have the skills required to track this into linux land. @roji is there any chance of getting a little of your time and expertise on this?

[Wraith2]

I checked the unix library by decompiling it to make sure all the required functionality is there, and it is. Thread scheduling is not vastly different on *nix to windows. The abstractions provided by the framework would take care of that or we, and everyone else, would be aware that threading worked differently. If we assume that you can set an appcontext switch properly by copy pasting then that only leaves one thing that can be differently, the threadpool queued count. So I've taken out the check for that and made it so that if the switch is set it will always use the dedicated threads. Can you retest please @DavoudEshtehari ? it'd be really good to get this into the latest preview.

[DavoudEshtehari]

Unfortunately, still no improvements. Please find the event source logs in the attached file.

dotnet_20220407_154615.zip

[Wraith2]

It's working. Sort of. I can only see one exception in the trace even though it's hard to work with. It looks like the IO is all being performed on the 3 IO threads but continuations of some kind are being queued back onto the threadpool and that's what you're seeing blocking the throughput at the start. So you're seeing a wait but you aren't getting many failures.

If we can work out what that continuation is and see if it's safe to do on the IO pool threads we can push it back onto the dedicated IO threads. If it could execute user code it can't go on our pool. Can you tell me what framework version you're using?

How do you work with these traces? Visual studio will open them but the options are very limited, perfview will let me poke around in them but it's got a UI that only just beats The gimp in terms of usability.

[DavoudEshtehari]

I can see the Timeout exceptions. And the target framework is netcoreapp3.1.
I'm afraid there wasn't another viewer except what you mentioned. In Addition, dotnet-trace tool has a parameter to generate speedscope format but it returns an empty file. Another solution would be collecting traces using a custom listener which won't end up with a better format.

Output:

Iterations:     50
Enabled 'Switch.Microsoft.Data.SqlClient.UseExperimentalMARSThreading'

*************** Running issue #422 **************
Waiting time: 00:00:20.0761474   The original message is: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.. exception type is: Microsoft.Data.SqlClient.SqlException. It happened at Number: 5 for iteration number of: 0.
Waiting time: 00:00:20.0764163   The original message is: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.. exception type is: Microsoft.Data.SqlClient.SqlException. It happened at Number: 0 for iteration number of: 0.
.
.
.
Number: 1. All Queries. Time: 00:00:41.9039956
Number: 25. All Queries. Time: 00:00:25.1457633
Number: 44. All Queries. Time: 00:00:06.1177331
.
.
.
Number: 0. All Queries. Time: 00:00:41.9102858
Number: 0. All Queries. Time: 00:00:41.9102858
Total: 00:00:54.9710229

[Wraith2]

Take a look at the flame graph if you load he file into perfview, you'll see the IO is happening where it's supposed to so the scheduler component is working. It's just that you still get threadpool exhaustion because of the waiting on the non-io completion.

Can you give me the project you're using to repro and the commands to gather the traces? Nothing about this should be unix specific so I want to see if I can see the same pattern in windows.

[DavoudEshtehari]

You should pass the running process Id using dotnet-trace tool. I'd suggest using "Perfview" If you liked to investigate on Windows.

dotnet-trace collect --providers "Microsoft.Data.SqlClient.EventSource" --process-id <#pid>

Find my repro here based on issue #422.

e.g: Waits 8 seconds, enables the UseExperimentalMARSThreading switch and runs 100 iterations.

.\AllManagedSNITests.exe <"connection string"> 100 8000 true

[Wraith2]

I built a vm and set it up with everything needed to test this against linux using wsl as @DavoudEshtehari has been and I can reproduce the issue. It isn't clear what is causing the problem but it looks like the networking implementation in the runtime just stops calling back when data arrives, if that's the case and it's caused by the runtime using the threadpool internally then there is no way we can fix it at this layer. I will continue to investigate.

[Wraith2]

I've been looking into what is going on here and the results are discouraging.

I started by adding Debug.WriteLine() on paths though the managed implementation and trying to identify where items were getting stuck or failing in some way. There are no errors of unexpected changes of path through the code depending on the platform, the same code is being run on windows and linux. The critical places to observe are in SNIPacket

        public void ReadFromStreamAsync(Stream stream, SNIAsyncCallback callback)
        {
            Debug.WriteLine($"ReadFromStreamAsync {Thread.CurrentThread.Name}");
            stream.ReadAsync(_data, 0, _dataCapacity, CancellationToken.None)
                .ContinueWith(
                    continuationAction: _readCallback,
                    state: callback,
                    CancellationToken.None,
                    TaskContinuationOptions.DenyChildAttach,
                    TaskScheduler.Default
                );
        }

and the method that callback delegate refers to:

        private void ReadFromStreamAsyncContinuation(Task<int> t, object state)
        {
            Debug.WriteLine($"ReadFromStreamAsyncContinuation {Thread.CurrentThread.Name}");
            SNIAsyncCallback callback = (SNIAsyncCallback)state;
            bool error = false;
            Exception e = t.Exception?.InnerException;
            if (e != null)
            {
            ...

This is where we call into the ReadAsync method of a type derived from NetworkStream and rely on the runtime implementation to execute the callback we provided when the read has completed. Using the debug statements above you can see the reproduction linked above grinding to a halt on both windows and linux.

Windows .NET Core 3.1.23 main
ReadFromStreamAsync 
ReadFromStreamAsyncContinuation 
ReadFromStreamAsync 
ReadFromStreamAsyncContinuation 
ReadFromStreamAsync 
ReadFromStreamAsyncContinuation 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 

Unix .NET Core 3.1.23 main
ReadFromStreamAsync 
ReadFromStreamAsyncContinuation 
ReadFromStreamAsync 
ReadFromStreamAsyncContinuation 
ReadFromStreamAsync 
ReadFromStreamAsyncContinuation 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 
ReadFromStreamAsync 

You can see that we get 3 callbacks and then they stop and we see only new reads queuing up. Eventually the driver code will timeout and error because we're not seeing packets come back. So why 3? Unknown.

If we enable the mars scheduler from this PR we'll see a working pattern on windows:

Windows .NET Core 3.1.23 branch
ReadFromStreamAsync MARSIOScheduler (9)
ReadFromStreamAsyncContinuation MARSIOScheduler (7)
ReadFromStreamAsync MARSIOScheduler (7)
ReadFromStreamAsyncContinuation MARSIOScheduler (5)
ReadFromStreamAsync MARSIOScheduler (5)
ReadFromStreamAsyncContinuation MARSIOScheduler (0)
ReadFromStreamAsync MARSIOScheduler (0)
ReadFromStreamAsyncContinuation MARSIOScheduler (6)
ReadFromStreamAsync MARSIOScheduler (6)
ReadFromStreamAsyncContinuation MARSIOScheduler (3)
ReadFromStreamAsync MARSIOScheduler (3)
ReadFromStreamAsyncContinuation MARSIOScheduler (2)
ReadFromStreamAsync MARSIOScheduler (2)
ReadFromStreamAsyncContinuation MARSIOScheduler (1)
ReadFromStreamAsync MARSIOScheduler (1)
ReadFromStreamAsync MARSIOScheduler (4)
ReadFromStreamAsyncContinuation MARSIOScheduler (8)
ReadFromStreamAsync MARSIOScheduler (8)
ReadFromStreamAsyncContinuation MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (9)
ReadFromStreamAsyncContinuation MARSIOScheduler (7)
ReadFromStreamAsync MARSIOScheduler (7)
ReadFromStreamAsyncContinuation MARSIOScheduler (5)
ReadFromStreamAsync MARSIOScheduler (5)
ReadFromStreamAsyncContinuation MARSIOScheduler (0)
ReadFromStreamAsync MARSIOScheduler (0)
ReadFromStreamAsyncContinuation MARSIOScheduler (6)
ReadFromStreamAsync MARSIOScheduler (6)
ReadFromStreamAsyncContinuation MARSIOScheduler (3)
ReadFromStreamAsync MARSIOScheduler (3)

But doing the same on linux doesn't have the same effect:

Unix .NET Core 3.1.23 branch
ReadFromStreamAsync MARSIOScheduler (7)
ReadFromStreamAsyncContinuation MARSIOScheduler (1)
ReadFromStreamAsync MARSIOScheduler (1)
ReadFromStreamAsyncContinuation MARSIOScheduler (5)
ReadFromStreamAsync MARSIOScheduler (5)
ReadFromStreamAsyncContinuation MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (4)
ReadFromStreamAsync MARSIOScheduler (0)
ReadFromStreamAsync MARSIOScheduler (8)
ReadFromStreamAsync MARSIOScheduler (2)
ReadFromStreamAsync MARSIOScheduler (6)
ReadFromStreamAsync MARSIOScheduler (3)
ReadFromStreamAsync MARSIOScheduler (7)
ReadFromStreamAsync MARSIOScheduler (1)
ReadFromStreamAsync MARSIOScheduler (5)
ReadFromStreamAsync MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (4)
ReadFromStreamAsync MARSIOScheduler (0)

You can see that the mars IO threads are being used but that we're not getting callbacks from the system to tell us that a read has completed. On windows the limiting factor seems to be that a high level async task was being blocked by the threadpool being unavailable and the mars scheduler fixes that problem. On Linux there is also a lower level problem somewhere in the runtime/networking implementation which means that when we hit 3 waiting callbacks we stop getting callbacks.

I went looking for the threadpool implementation in the runtime to see if there's anything interesting in there that explains what's going on. It looks like for .net 7 the was a PR last month to add the ability to use IOCompletionPorts to the threadpool on windows but before that there was just the standard ThreadPool.CoreCLR.cs implementation which is the portable version. So there is no managed difference between the threadpools on <6 which means that if there is a difference it would need to be in the os abstraction layer.

To see what patterns of behaviour we have i ran the test program using 4 differnent configuration options.

1. platform, windows or linux ()
2. runtime, 3.1 or 6.0
3. mars scheduler enabled or not
4. UsePortableThreadPool set to 0 (use defaults), 1 (use worker iocp), 2 (use worker and io iocp). This was found while looking through the runtime source and i didn't expect it to have an effect on 6 but it seemed worth trying.

Hyper-V VM with 4 cores (to keep default thread counts down) and 8Gib memory. Windows is win10 latest. Linux is ubuntu 20.04 running in wsl2 with mode set to 2 so it's using a real linux kernel. All test run through visual studio in debug mode so i could capture the output and see if any odd things happened. The database is an azure hosted empty database, the internet latency can be useful to make async operations go async but all of this can be replicated locally. Mars IO thread count is 10 when enabled.

The results are:

Platform	Runtime	MarsIO	Portable	Exceptions	Elapsed Time
Unix	.NET 6.0.3	TRUE	2	103	02:27.5
Unix	.NET 6.0.3	FALSE	2	102	02:50.1
Unix	.NET 6.0.3	TRUE	1	105	02:32.4
Unix	.NET 6.0.3	FALSE	1	106	02:54.3
Unix	.NET 6.0.3	TRUE	0	100	02:27.3
Unix	.NET 6.0.3	FALSE	0	100	02:47.8
Unix	.NET Core 3.1.23	TRUE	2	105	02:34.1
Unix	.NET Core 3.1.23	FALSE	2	100	02:50.4
Unix	.NET Core 3.1.23	TRUE	1	107	02:34.3
Unix	.NET Core 3.1.23	FALSE	1	100	02:50.4
Unix	.NET Core 3.1.23	TRUE	0	104	02:33.1
Unix	.NET Core 3.1.23	FALSE	0	104	02:52.5
Windows	.NET 6.0.3	TRUE	2	0	01:22.6
Windows	.NET 6.0.3	FALSE	2	108	03:06.0
Windows	.NET 6.0.3	TRUE	1	0	01:23.4
Windows	.NET 6.0.3	FALSE	1	108	03:01.1
Windows	.NET 6.0.3	TRUE	0	0	01:22.1
Windows	.NET 6.0.3	FALSE	0	104	02:53.0
Windows	.NET Core 3.1.23	TRUE	2	0	01:17.5
Windows	.NET Core 3.1.23	FALSE	2	102	02:56.6
Windows	.NET Core 3.1.23	TRUE	1	0	01:19.8
Windows	.NET Core 3.1.23	FALSE	1	104	02:58.9
Windows	.NET Core 3.1.23	TRUE	0	0	01:22.8
Windows	.NET Core 3.1.23	FALSE	0	104	02:54.4

Takeaways from this are:

1. without the mars scheduler the behaviour is the same on all runtimes and platforms. Exceptions.
2. portable threadpool setting has no effect, expected.
3. windows with the mars scheduler works, without the scheduler it doesn't
4. it never works on linux

So the scheduler is useful if and only if we want a way to alleviate this issue on windows.

However, there's one more set of results. In Main i added a call to ThreadPool.SetMinThreads(100,10); which will cause the system threadpool to populate up to the minimum number of threads we we'll have lots of spare capacity; i then ran the test again on windows and linux.

Platform	Runtime	MarsIO	Portable	Exceptions	Elapsed Time
Unix	.NET Core 3.1.23	FALSE	0	0	01:17.7
Windows	.NET Core 3.1.23	FALSE	0	0	01:31.2

So if you simply prepare the environment for the workload you're about to throw at it then you'll get good results.

So the problem we have is what we see in this trace:

Unix .NET Core 3.1.23 branch
ReadFromStreamAsync MARSIOScheduler (7)
ReadFromStreamAsyncContinuation MARSIOScheduler (1)
ReadFromStreamAsync MARSIOScheduler (1)
ReadFromStreamAsyncContinuation MARSIOScheduler (5)
ReadFromStreamAsync MARSIOScheduler (5)
ReadFromStreamAsyncContinuation MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (4)
ReadFromStreamAsync MARSIOScheduler (0)
ReadFromStreamAsync MARSIOScheduler (8)
ReadFromStreamAsync MARSIOScheduler (2)
ReadFromStreamAsync MARSIOScheduler (6)
ReadFromStreamAsync MARSIOScheduler (3)
ReadFromStreamAsync MARSIOScheduler (7)
ReadFromStreamAsync MARSIOScheduler (1)
ReadFromStreamAsync MARSIOScheduler (5)
ReadFromStreamAsync MARSIOScheduler (9)
ReadFromStreamAsync MARSIOScheduler (4)
ReadFromStreamAsync MARSIOScheduler (0)

Why do we stop receiving callback notifications from the system once 3 have been queued? is the 3 co-incidental/temporal in nature or is there some limit of 3 in the runtime somewhere? We rely on the NetworkStream.ReadAsync to function and it does not. This is outside the scope of this library to fix in my opinion.
We can't work around the internals of the runtime in this case. This may be an interesting case for the runtime/networking team to look at though so i'll tag @karelz who works in that area and is always helpful to see if he has any ideas on what we might be able to do.

[DavoudEshtehari]

For the record, sharing my findings with ubuntu 20.04 distribution on WSL2, netcoreapp3.1, MARS = true for 30 Iterations:

• Runing ThreadPool.SetMinThreads(WorkerThreads, CompletionPortThreads) at the app startup with following values:

Workerthreads	CompletionPortThreads	Total Time (sec)	Delay (sec)	Exception free
10	1	~20.58	~14	[❌]
20	2	~10.65	~9.6	[✔️]
30	3	~1.65	~0	[✔️]

• Repeating the test after decreasing the task scheduler threads to 1 in SNIMarsConnection:
  QueuedTaskScheduler(1, "MARSIOScheduler", false, ThreadPriority.AboveNormal)

Workerthreads	CompletionPortThreads	Total Time (sec)	Delay (sec)	Exception free
10	1	~22.86	~20	[❌]
20	2	~12.27	~9	[✔️]
30	3	~1.11	~0	[✔️]

I found a similar result by downgrading the thread's priority:
QueuedTaskScheduler(3, "MARSIOScheduler", false, ThreadPriority.Normal)

[DavoudEshtehari]

Update over the previous comment:

Running the test without enabling UseExperimentalMARSThreading switch using the ThreadPool.SetMinThreads(WorkerThreads, CompletionPortThreads) method found the same result.
It could be a workaround on Linux with the current codebase.

[Wraith2]

It is the workaround I proposed over 2 years ago now #422 (comment) but people didn't want to accept it. Unless the framework changes underneath us then imo it remains the only viable option.

[roji]

@Wraith2 it seems that in #1543 (comment) you suspect an issue with the BCL socket implementation; if so the best way forward is to reproduce it in a code sample outside of SqlClient. Doing that may not be trivial, but otherwise there's always the chance something problematic happening in SqlClient somehow triggers the problematic behavior.

[Wraith2]

I'm curious whether you've tried the same thing with the postgres driver and if it would also show the same behaviour. If the runtime is using sync over async internally then you should even though you aren't using that pattern in the library.

[roji]

I certainly haven't seen issues like this in Npgsql (except when we messed up ourselves in the driver). Npgsql only does sync-over-async itself in a very specific scenario where we can't aviod it - when batching and sync APIs are used together - though that's probably common enough that we'd have heard some complaints if it were failing as above...

[vonzshik]

Regarding ReadFromStreamAsyncContinuatiom: the problem can happen on both windows and linux.

The main issue here is NetworkStream.ReadAsync, which by calling AsTask on ValueTask still schedules an internal continuation to run on a TP, which is busy being stuck on SNIMarsHandle.Receive's mre:

SqlClient/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIMarsHandle.cs

Line 519 in a6625b3

if (!_packetEvent.Wait(timeoutInMilliseconds))

We've faced the same kind of problem in Npgsql with ValueTask.AsTask, @roji should remember that.

[roji]

Thanks for the investigation @vonzshik - yes, we faced this issue with AsTask in Npgsql's sync-over-async hack - see this comment and the workaround. Since AsTask is being used inside NetworkStream, it's likely to be more complicated to work around it. More generally, the problem here is in the assumption that an async BCL API (NetworkStream.ReadAsync) won't itself internally depend on the thread pool - this simply isn't a guarantee that the API makes for you.

If fixing this issue is important, then I really urge everyone involved in SqlClient to come up with a plan where sync-over-async isn't used. I understand that's a big thing to do, but it really is the only way to ensure the driver works correctly in all scenarios etc.

[Wraith2]

Regarding ReadFromStreamAsyncContinuatiom: the problem can happen on both windows and linux.

That fits with what I think is going on. It also makes clear that even on windows this PR isn't a fix, all it does is divert some pressure from the threadpool onto our dedicated threads it doesn't prevent the runtime below us from hitting the same problem we've just been lucky in testing. Thanks @vonzshik!

If fixing this issue is important...

There's some difference of opinion on that one. For the SQL team fixing it is a high priority.
For me I see it more as a a condition that users can avoid hitting by being careful about what they're doing. The engineering effort required to remove the problem from the library is many orders of magnitude above that required by users to avoid it. It would be nicer if users didn't have to worry about it and in an ideal world where engineering resources were not constrained it would be fixed, at the moment it's something I'd put as a long term goal along with rewriting many other things to use language async if possible.

[JRahnama]

@Wraith2 can we close this PR?