Slow read from SqlDataReader

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

Issue Analytics

State:
Created 2 years ago
Comments:7 (4 by maintainers)

Top GitHub Comments

2reactions

JRahnamacommented, Sep 30, 2021

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

I have tested different scenarios.

Sync call with no CommandBehavior
Sync call with CommandBehavior.SequentialAccess
Async call with no CommandBehavior
Async call with no CommandBehavior.SequentialAccess
Async call with CommandBehavior.SequentialAccess and no ConfigureAwait(false)
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?

0reactions

Wraith2commented, Oct 10, 2021

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.