Slow read from SqlDataReader

[valentiniliescu]

Describe the bug

We have an issue with an Azure Function that runs a query against a Azure SQL Server. The function uses a SqlDataReader, and the command / query execution is pretty fast, but reading the results is sometimes slow. It does not happen very often, but when it happens, there is a certain pattern, the TDS packets seem to be delayed. For example, this is a log snippet:

8/6/2021, 8:46:55.128 AM    20288 - ScopeEnter - SqlDataReader.ReadAsync | API | Object Id 1
8/6/2021, 8:46:55.128 AM    20288 - ScopeEnter - SqlDataReader.TryReadInternal | API | Object Id 1
8/6/2021, 8:46:55.128 AM    20288 - ScopeLeave - Exit Scope 214540
8/6/2021, 8:46:55.128 AM    20288 - ScopeLeave - Exit Scope 214539
8/6/2021, 8:46:55.128 AM    20288 - ScopeEnter - SqlDataReader.ReadAsync | API | Object Id 1
8/6/2021, 8:46:55.128 AM    20288 - ScopeEnter - SqlDataReader.TryReadInternal | API | Object Id 1
8/6/2021, 8:46:55.128 AM    20288 - ScopeLeave - Exit Scope 214542
8/6/2021, 8:46:55.129 AM    20288 - ScopeLeave - Exit Scope 214541
8/6/2021, 8:46:55.374 AM    20288 - SNITrace - SNITCPHandle.Receive | INFO | Connection Id e8b7430d-7f47-410e-83dc-f7bccbe47f49, Data read from stream synchronously
8/6/2021, 8:46:55.375 AM    20288 - Trace - TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 4, Session Id e8b7430d-7f47-410e-83dc-f7bccbe47f49
8/6/2021, 8:46:55.375 AM    20288 - Trace - TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 4, Session Id e8b7430d-7f47-410e-83dc-f7bccbe47f49, Packet DataLeft 8000
8/6/2021, 8:46:55.375 AM    20288 - ScopeEnter - SqlDataReader.ReadAsync | API | Object Id 1
8/6/2021, 8:46:55.375 AM    20288 - ScopeEnter - SqlDataReader.TryReadInternal | API | Object Id 1
8/6/2021, 8:46:55.375 AM    20288 - ScopeLeave - Exit Scope 214544
8/6/2021, 8:46:55.375 AM    20288 - ScopeLeave - Exit Scope 214543
8/6/2021, 8:46:55.375 AM    20288 - ScopeEnter - SqlDataReader.ReadAsync | API | Object Id 1
8/6/2021, 8:46:55.375 AM    20288 - ScopeEnter - SqlDataReader.TryReadInternal | API | Object Id 1

If I understand the log correctly, there is a ~250ms delay when receiving the TDS packet, and, for this particular query, there are 100 packets which adds up to 20-30 seconds.

This seems to happen sporadically without any clear cause. Also, the SQL server isn't busy at all at this time (<5% CPU and IO usage).

Further technical details

Microsoft.Data.SqlClient version: 3.0.0 .NET target: Core 3.1 SQL Server version: Azure SQL Server Operating system: Azure Function v3 on Windows

[JRahnama]

@valentiniliescu Hi,

Logs are not saying much in this case, What I understood from the log: 1- you are using async calls 2- you are using mangedSNI

Is it possible to make a repro including the connection string (including the options you are using) and the query that you run? Do yo have any concurrent/parallel runs on the app?

[valentiniliescu]

Unfortunately, I cannot create a repro, but this is the sanitized version of the code that we run:

            var connectionString = string.Format("Data Source={0};Initial Catalog={1};Connection Timeout={2}", "server", "database", "240");

            using SqlConnection connection = new SqlConnection(connectionString);
            await connection.OpenAsync().ConfigureAwait(false);

            using SqlCommand command = new SqlCommand("[dbo].[MyStoredProc]", connection);
            command.CommandTimeout = 240;

            command.CommandType = CommandType.StoredProcedure;
            command.Parameters.Add(new SqlParameter("@Param1", SqlDbType.NVarChar) { Value = "value1" });
            command.Parameters.Add(new SqlParameter("@Param1", SqlDbType.Int) { Value = 1 });

            using SqlDataReader reader = await command.ExecuteReaderAsync(CommandBehavior.SequentialAccess).ConfigureAwait(false);
            while (await reader.ReadAsync().ConfigureAwait(false))
            {
                string col1 = await reader.GetTextReader(0).ReadToEndAsync().ConfigureAwait(false);
                double col2 = decimal.ToDouble((decimal)reader.GetValue(1));
            }

I used the managed SNI only for tracing purposes, otherwise I don't see SNI traces in the logs.

Also, this is an Azure Function, so there might be concurrent runs, but, as you can see from the code snippet above, there are no shared objects.

[Wraith2]

Are you reading large strings or binary when the problem occurs?

[valentiniliescu]

No, the strings are pretty small. For example, for this particular query, the result is 12000 rows, with one column NVARCHAR and each value 25-30 characters and one DECIMAL(6,5)

[JRahnama]

@valentiniliescu I made a Benchmark testing for this matter. The sample code could be found in this gist.

I have tested different scenarios.

1. Sync call with no CommandBehavior
2. Sync call with CommandBehavior.SequentialAccess
3. Async call with no CommandBehavior
4. Async call with no CommandBehavior.SequentialAccess
5. Async call with CommandBehavior.SequentialAccess and no ConfigureAwait(false)
6. Async call with no CommandBehavior and no ConfigureAwait(false)

The results are as below:

// Summary

BenchmarkDotNet=v0.13.0, OS=Windows 10.0.19043.1151 (21H1/May2021Update) Intel Core i7-8665U CPU 1.90GHz (Coffee Lake), 1 CPU, 8 logical and 4 physical cores .NET SDK=6.0.100-preview.4.21255.9 [Host] : .NET Core 3.1.17 (CoreCLR 4.700.21.31506, CoreFX 4.700.21.31502), X64 RyuJIT .NET Core 3.1 : .NET Core 3.1.17 (CoreCLR 4.700.21.31506, CoreFX 4.700.21.31502), X64 RyuJIT

Job=.NET Core 3.1 Runtime=.NET Core 3.1

Method	Mean	Error	StdDev	Median
SqlReader_Sync_NoCommandBehavior	7.486 ms	0.4869 ms	1.365 ms	7.283 ms
SqlReader_Sync_CommandBehavior_Sequential	25.178 ms	1.0017 ms	2.759 ms	24.432 ms
SqlReader_Async_NoCommandBehaviorAsync	16.786 ms	0.6272 ms	1.738 ms	16.785 ms
SqlReader_Async_CommandBehavior_Sequential	69.953 ms	1.9987 ms	5.702 ms	68.175 ms
SqlReader_Async_CommandBehavior_Sequential_NoConfigureAwait	67.622 ms	1.3522 ms	2.145 ms	67.639 ms
SqlReader_Async_NoCommandBehavi

It seems reading with Sequential access is causing the delay. Can you test it please?

For those who want to follow:

Run the following script on SSMS and make a database with 12000 rows

DECLARE @RowAmount AS INT = 12000;
WITH InfiniteRows (RowNumber1, RowNumber2) AS (
   SELECT 1 AS RowNumber1, 2 AS RowNumber2
   UNION ALL
   SELECT a.RowNumber1 +1  AS RowNumber1, a.RowNumber2+1  AS RowNumber2
   FROM   InfiniteRows a
   WHERE  a.RowNumber1 < @RowAmount
   )
  SELECT CONVERT(NVARCHAR(255), NEWID()) AS VAL1, RowNumber1/3.3000 *100.00  AS VAL2
  INTO temp
FROM   InfiniteRows
OPTION (MAXRECURSION 0);
GO

to create Stored procedure:

CREATE PROCEDURE MyStoredProc
@Param1 nvarchar (max),
@Param2 decimal (26,8)
AS
BEGIN
    SELECT * from temp
END

Can you also confirm that the stored procedure is something similar to what you have?

[valentiniliescu]

Thank you @JRahnama for your code and benchmark.

For the stored procedure, mine is pretty complicated, but the shape and count of the result is pretty similar. Unfortunately, I tested without sequential access before and it does not make any difference. I tested with sync and async, tested with the newest package (Microsoft.Data.SqlClient 3.0.0) and the original one (System.Data.SqlClient 4.6.0) with no luck. Regarding the benchmark, I would be interested in the outliers more than the mean. In my case, most of the time the code is fast, but sometimes it gets slow to the point the Azure Function times out (after 5 minutes) and it's not the query execution (takes only 10 seconds).

At this point I am going to try a workaround - to reduce the size of the results from the stored procedure, so the random slowness in the TDS packets will not influence that much.

[Wraith2]

I've done some investigation. The difference in speed between sequential and non-sequential reads is caused by the extra overhead of using an SqlSequentialTextReader that can handle forward only uncached reads from the tds data stream. In the default case the entire field can be read as a stream and a standard StringReader returned.

For the case where individual reads are extremely slow there isn't much that can be done without a reproduction.

[MichelZ]

Related to #593