Fixed ReadAsync blocking issue #26595

geleems · 2018-01-26T01:08:57Z

This fix is for the issue https://github.com/dotnet/corefx/issues/26594

Customer reported an issue for SqlDataReader.ReadAsync() method actually runs synchronously, and it blocks the calling thread until data is fed from SQL Server.

corivera · 2018-01-26T01:12:28Z

src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs

@@ -2499,9 +2499,6 @@ private bool TryProcessDone(SqlCommand cmd, SqlDataReader reader, ref RunBehavio
            ushort status;
            int count;

-            // Can't retry TryProcessDone
-            stateObj._syncOverAsync = true;


Why this change specifically? Framework TdsParser also has this line

The comment // Can't retry TryProcessDone seems interesting. Looks like syncOverAsync was set to true to prevent a retry of processing the Done TDS token. Have you checked if this "retry" is not invoked after your changes?

@corivera TryProcessDone sets syncOverAsync during async execution which makes the execution sync for pretty much everything, since syncOverAsync forces a blocking network call. TryProcessDone was turning out to be a bottleneck that @geleems figured out.

I checked, and TryProcessDone() was not retried after my change. However, I have just become curious what happens if I force it to retry TryProcessDone() by following code:

I meant , are there code paths which could retry Done token processing in certain scenarios for a single SqlDataReader Read operation, instead of multiple Read() operations, which needs to be prevented?

@saurabh500
TryProcessDone() runs multiple times until ReadSni() actually returns packets, and it is processed by TryProcessDone(). Once DONE token is processed, codeflow moves forward, and there is no code path to RETRY the DONE token processing, which is already done.

saurabh500 · 2018-01-26T01:39:42Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/ReadAsyncTest.cs

@@ -0,0 +1,107 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.


This test could be moved to AsyncTest.cs

saurabh500 · 2018-01-26T01:40:02Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/ReadAsyncTest.cs

+    public class ReadAsyncTest
+    {
+        [CheckConnStrSetupFact]
+        public static void Run()


Provide a more descriptive name for this Run() method.

saurabh500 · 2018-01-26T01:42:28Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/ReadAsyncTest.cs

+        {
+            double elapsedAsync = await RunReadAsync();
+            double elapsedSync = RunRead();
+            Assert.True(elapsedAsync < (elapsedSync / 2.0d));


The test Asserts that Async should take half the time taken by Sync.
This doesn't seems right. Async should take close to 0 ms.

Can this assert be improved?

It took about 15~30ms in my environment for asynchronous operation.
For synchronous read, it took about 2000ms.

I checked, and TryProcessDone() was not retried after my change. However, I have just become curious what happens if I force it to retry TryProcessDone() by following code:

Task<bool> t1, t2; do { t1 = reader.ReadAsync(); t2 = reader.ReadAsync(); } while (await t1 && await t2);

It took about 15~30ms in my environment for asynchronous operation.
For synchronous read, it took about 2000ms.

Based on this can you provide a better Assert for this test.
My concern is that if ReadSync takes 30 seconds in some cases, then ReadAsync should still take ~30 ms. So a proportionate comparison with the time taken by ReadAsync and ReadSync doesn't make sense

Task t1, t2;
do
{
t1 = reader.ReadAsync();
t2 = reader.ReadAsync();
}
while (await t1 && await t2);

This Code will not retry Done token processing in the middle of the TDS stream.

saurabh500 · 2018-01-26T01:45:08Z

src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs

@@ -2499,9 +2499,6 @@ private bool TryProcessDone(SqlCommand cmd, SqlDataReader reader, ref RunBehavio
            ushort status;
            int count;

-            // Can't retry TryProcessDone
-            stateObj._syncOverAsync = true;


The comment // Can't retry TryProcessDone seems interesting. Looks like syncOverAsync was set to true to prevent a retry of processing the Done TDS token. Have you checked if this "retry" is not invoked after your changes?

saurabh500 · 2018-01-26T01:46:04Z

src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs

@@ -2499,9 +2499,6 @@ private bool TryProcessDone(SqlCommand cmd, SqlDataReader reader, ref RunBehavio
            ushort status;
            int count;

-            // Can't retry TryProcessDone
-            stateObj._syncOverAsync = true;


@corivera TryProcessDone sets syncOverAsync during async execution which makes the execution sync for pretty much everything, since syncOverAsync forces a blocking network call. TryProcessDone was turning out to be a bottleneck that @geleems figured out.

geleems · 2018-01-26T02:00:17Z

What causes this issue?

The issue resides in both .NET Framework and .NET Core.
Here is the stack trace of main thread when it was blocking after ReadAsync() call.

System.Data.dll!SNINativeMethodWrapper::SNIReadSyncOverAsync(System::Runtime::InteropServices::SafeHandle^ pConn, __int64 packet, int timeout) Line 1113 + 0xc bytes             C++
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync() Line 1957 + 0x18 bytes                C#
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket() Line 1913 C#
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer() Line 1075 + 0x8 bytes    C#
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.TryReadByteArray(byte[] buff, int offset, int len, out int totalRead) Line 1227 + 0x8 bytes C#
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.TryReadInt64(out long value) Line 1401 + 0x23 bytes     C#
System.Data.dll!System.Data.SqlClient.TdsParser.TryProcessDone(System.Data.SqlClient.SqlCommand cmd, System.Data.SqlClient.SqlDataReader reader, ref System.Data.SqlClient.RunBehavior run, System.Data.SqlClient.TdsParserStateObject stateObj) Line 2698 + 0xc bytes        C#
System.Data.dll!System.Data.SqlClient.TdsParser.TryRun(System.Data.SqlClient.RunBehavior runBehavior, System.Data.SqlClient.SqlCommand cmdHandler, System.Data.SqlClient.SqlDataReader dataStream, System.Data.SqlClient.BulkCopySimpleResultSet bulkCopyHandler, System.Data.SqlClient.TdsParserStateObject stateObj, out bool dataReady) Line 1986 + 0x25 bytes     C#
System.Data.dll!System.Data.SqlClient.SqlDataReader.TryHasMoreRows(out bool moreRows) Line 2887 + 0x31 bytes          C#
System.Data.dll!System.Data.SqlClient.SqlDataReader.TryReadInternal(bool setTimeout, out bool more) Line 3171 + 0xd bytes              C#
System.Data.dll!System.Data.SqlClient.SqlDataReader.ReadAsync.AnonymousMethod__0(System.Threading.Tasks.Task t) Line 4292 + 0x18 bytes              C#
System.Data.dll!System.Data.SqlClient.SqlDataReader.InvokeRetryable<bool>(System.Func<System.Threading.Tasks.Task,System.Threading.Tasks.Task<bool>> moreFunc, System.Threading.Tasks.TaskCompletionSource<bool> source, System.IDisposable objectToDispose) Line 4625 + 0x9 bytes              C#
System.Data.dll!System.Data.SqlClient.SqlDataReader.ReadAsync(System.Threading.CancellationToken cancellationToken) Line 4318 + 0x11 bytes           C#
System.Data.dll!System.Data.Common.DbDataReader.ReadAsync() Line 243 + 0x15 bytes              C#

Default value of TdsParserStateObject._syncOverAsync is True. ReadAsync() can be done asynchronously only when the value is set to False :
https://github.com/dotnet/corefx/blob/master/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParserStateObject.cs#L2030-L2036

When SqlDataReader.ReadAsync() is called, TdsParserStateObject._syncOverAsync is set to False for asynchronous operation :
https://github.com/dotnet/corefx/blob/master/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs#L4798

But TdsParserStateObject._syncOverAsync is rolled back to True when the code flow hits TdsParser.TryProcessDone() : https://github.com/dotnet/corefx/blob/master/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs#L2503

Look at the stack trace again:

SNINativeMethodWrapper::SNIReadSyncOverAsync()
TdsParserStateObject.ReadSniSyncOverAsync()
TdsParserStateObject.TryReadNetworkPacket()
TdsParserStateObject.TryPrepareBuffer()
TdsParserStateObject.TryReadByteArray()
TdsParserStateObject.TryReadInt64()
TdsParser.TryProcessDone() <--------------------------------_syncOverAsync is set back to True
TdsParser.TryRun()
SqlDataReader.TryHasMoreRows()
SqlDataReader.TryReadInternal()
SqlDataReader.ReadAsync.AnonymousMethod__0()
SqlDataReader.InvokeRetryable<bool>()
SqlDataReader.ReadAsync() <---------------------------------_syncOverAsync is set to False
System.Data.Common.DbDataReader.ReadAsync()

As result, TdsParserStateObject.ReadSniSyncOverAsync() is executed instead of TdsParserStateObject.ReadSni(). And ReadSniSyncOverAsync() always proceed operation synchronously if the protocol is TCP.

saurabh500 · 2018-01-26T02:27:41Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/ReadAsyncTest.cs

+                using (SqlCommand command = connection.CreateCommand())
+                {
+                    command.CommandText = commandText;
+                    using (SqlDataReader reader = command.ExecuteReader())


You could use the async equivalent of ExecuteReader to make this method async. The same applies to connection.Open()

stephentoub · 2018-01-26T18:03:45Z

Why does this _syncOverAsync thing exist at all? Why was it added in the first place? Can we entirely delete it?

saurabh500 · 2018-01-26T22:05:21Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTest.cs

@@ -36,7 +37,7 @@ public static void ExecuteTest()
            con.Close();
        }

-        [CheckConnStrSetupFact]
+        //[CheckConnStrSetupFact]


You may want to clean this method and the one above. Looks like they are not used and the [Fact] attribute has been removed

saurabh500 · 2018-01-26T22:05:59Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTest.cs

+            CompareReadSyncAndReadAsync();
+        }
+
+        private static async void CompareReadSyncAndReadAsync()


This method doesn't need to be async

saurabh500 · 2018-01-26T22:06:27Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTest.cs

+                            + "   DROP TABLE #y"
+                            + " END"
+                            + " SELECT 'b'";
+            double elapsedAsync = await RunReadAsync(sql);


It would be better to wait on the task returned by RunReadAsync(sql);

saurabh500 · 2018-01-26T22:07:43Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTest.cs

+                            + " SELECT 'b'";
+            double elapsedAsync = await RunReadAsync(sql);
+            double elapsedSync = RunReadSync(sql);
+            Assert.True(elapsedAsync < (elapsedSync / 2.0d));


Do you plan to improve this assert in future commits?

saurabh500 · 2018-01-27T02:14:26Z

@stephentoub It seems like when the networking layer of SqlClient was changed in the framework (long ago), it was decided that Async APIs following the Begin and End pattern would use IOCP at the networking layer to make the calls so that the calls are not blocking. This behavior was put behind a flag called Async=true/false
At the same time the Sync calls were ported to be Sync over these Async network calls.
I found this blog https://blogs.msdn.microsoft.com/angelsb/2004/09/02/ado-net-2-0-asynchronous-command-execution-async-faq/ which has some answers.

stephentoub · 2018-01-27T02:17:46Z

Thanks. After this fix, do any async paths still hit sync over async paths? And is this a contributor to the issue that made you make long running tasks, and if so, can we undo that now?

geleems · 2018-01-30T08:09:11Z

@stephentoub
The spot I removed was the only place that _syncOverAsync variable is consumed for synchronous processing. So..no.. there is no other path. :)

saurabh500 · 2018-01-30T22:58:59Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTest.cs

        [CheckConnStrSetupFact]
-        public static void ExecuteTest()
+        public static void TestReadAsync()


Can this be changed to TestReadAsyncTimeConsumed

saurabh500 · 2018-01-30T22:59:08Z

src/System.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTest.cs

+            double elapsedSync = RunReadSync(sql);
+            t.Wait();
+            double elapsedAsync = t.Result;
+            Console.WriteLine("Asynchronous Operation: " + elapsedAsync + "ms");


Remove Console statements.

geleems · 2018-01-31T04:26:31Z

@saurabh500 Manual tests were also passed.

Commit migrated from dotnet/corefx@da8a105

fixed ReadAsync blocking issue

8e124cb

geleems added the area-System.Data.SqlClient label Jan 26, 2018

geleems self-assigned this Jan 26, 2018

geleems requested review from saurabh500 and corivera January 26, 2018 01:08

corivera reviewed Jan 26, 2018

View reviewed changes

saurabh500 reviewed Jan 26, 2018

View reviewed changes

geleems requested a review from stephentoub January 26, 2018 02:01

saurabh500 reviewed Jan 26, 2018

View reviewed changes

comment fix

ee9ab84

saurabh500 reviewed Jan 26, 2018

View reviewed changes

comment fix

980e8ce

comment fix

828be6c

saurabh500 reviewed Jan 30, 2018

View reviewed changes

saurabh500 approved these changes Jan 30, 2018

View reviewed changes

comment fix

2d12ba6

geleems merged commit da8a105 into dotnet:master Jan 31, 2018

saurabh500 added this to the 2.1.0 milestone Feb 3, 2018

geleems deleted the async branch February 16, 2018 00:15

David-Engel mentioned this pull request Mar 24, 2020

The MARS TDS header contained errors using ASP.NET Core and EF Core connecting to Azure SQL Server dotnet/SqlClient#85

Closed

David-Engel mentioned this pull request Mar 25, 2020

Address MARS TDS header contained errors dotnet/SqlClient#490

Merged

cheenamalhotra mentioned this pull request Apr 30, 2020

Revert change that made SqlDataReader.ReadAsync() non-blocking dotnet/SqlClient#547

Merged

picenka21 pushed a commit to picenka21/runtime that referenced this pull request Feb 18, 2022

Fixed ReadAsync blocking issue (dotnet/corefx#26595)

6e48424

Commit migrated from dotnet/corefx@da8a105

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fixed ReadAsync blocking issue #26595

Fixed ReadAsync blocking issue #26595

geleems commented Jan 26, 2018

corivera Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

geleems Jan 30, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

geleems Jan 26, 2018

geleems Jan 26, 2018 •

edited

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

geleems commented Jan 26, 2018 •

edited

saurabh500 Jan 26, 2018

stephentoub commented Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 Jan 26, 2018

saurabh500 commented Jan 27, 2018

stephentoub commented Jan 27, 2018

geleems commented Jan 30, 2018

saurabh500 Jan 30, 2018

saurabh500 Jan 30, 2018

geleems commented Jan 31, 2018

		@@ -0,0 +1,107 @@
		// Licensed to the .NET Foundation under one or more agreements.
		// The .NET Foundation licenses this file to you under the MIT license.

Fixed ReadAsync blocking issue #26595

Fixed ReadAsync blocking issue #26595

Conversation

geleems commented Jan 26, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

geleems Jan 26, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

geleems commented Jan 26, 2018 • edited

What causes this issue?

Choose a reason for hiding this comment

stephentoub commented Jan 26, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

saurabh500 commented Jan 27, 2018

stephentoub commented Jan 27, 2018

geleems commented Jan 30, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

geleems commented Jan 31, 2018

geleems Jan 26, 2018 •

edited

geleems commented Jan 26, 2018 •

edited