corefx 源码追踪：找到引起 SqlDataReader.ReadAsync 执行延迟的那行代码

最近遇到一个非常诡异的问题，在一个 ASP.NET Core 2.2 项目中，从 SQL Server 数据库查询 100 条数据记录，会出现 16-22s 左右的延迟。延迟出现在执行 SqlDataReader 的 ReadAsync 方法时，在一行一行读取数据时，读取某些行时会出现 2-3s 的延迟。

前两天通过在 corefx 中 System.Data.SqlClient 源码中打点 Console.WriteLine($ " {DateTime.Now} " ) （打点方法见之前的博文），定位到了延迟出现在  SqlDataReader.cs 的 ContinueRetryable 方法下面的代码处。

return completionSource.Task.ContinueWith((retryTask) =>
{
    //...
}

发生延迟时 ContinueWith 中的任务会延迟执行，延迟发生在 completionSource.Task 中，completionSource 的类型是 TaskCompletionSource<object> ，值来自 _stateObj._networkPacketTaskSource ，_stateObj 的类型是 TdsParserStateObject 。

接下来进入 TdsParserStateObject.cs 进行追踪，追踪什么地方进行对 TaskCompletionSource 进行了 SetResult 或者 TrySetResult 操作，ContinueWith 就是在 SetResult/TrySetResult 之后执行的。

通过打点发现是在 ReadAsyncCallback<T>(IntPtr key, T packet, UInt32 error) 方法中进行了 TrySetResult 操作：

if ((processFinallyBlock) && (source != null) && (pendingCallbacks < 2))
{
    if (error == 0)
    {
        if (_executionContext != null)
        {
            ExecutionContext.Run(_executionContext, (state) => source.TrySetResult(null), null);
        }
        else
        {
            source.TrySetResult(null);
        }
    }
    //...
}

同时打点时间戳信息显示 ReadAsyncCallback 方法中没有发生延迟，说明延迟发生在调用 ReadAsyncCallback 方法之前。

经过无数次的打点，终于发现延迟发生在 SNIPacket.cs 的 ReadFromStreamAsync(Stream stream, SNIAsyncCallback callback) 方法中的那行   stream.ReadAsync 代码：

stream.ReadAsync(_data, 0, _capacity, CancellationToken.None).ContinueWith(t =>
{
    //...
}

沿着 ReadFromStreamAsync 继续追踪，弄明白 stream.ReadAsync 延迟为什么会造成 source.TrySetResult 延迟？

stream.ReadAsync 的延迟造成了紧随其后的 ContinueWith 延迟执行，ContinueWith 中执行了下面的 callback

callback(this, error ? TdsEnums.SNI_ERROR : TdsEnums.SNI_SUCCESS);

callback 的值是通过 ReadFromStreamAsync 的方法参数传递进来的，传参操作发生在 SNITcpHandle.cs 中的 ReceiveAsync(ref SNIPacket packet) 方法中

public override uint ReceiveAsync(ref SNIPacket packet)
{
    packet = new SNIPacket(_bufferSize);
    try
    {
        packet.ReadFromStreamAsync(_stream, _receiveCallback);
        return TdsEnums.SNI_SUCCESS_IO_PENDING;
    }
    //...
}

继续追踪

SNITcpHandle.ReceiveAsync() 
  -> SNIProxy.ReadAsync() 
  -> TdsParserStateObjectManaged.ReadAsync() 
  -> TdsParserStateObject.ReadSni() 

来到了 TdsParserStateObject.cs 的 ReadSni() 方法

handle = SessionHandle;
if (handle != null)
{
    IncrementPendingCallbacks();

    readPacket = ReadAsync(out error, ref handle);

    if (!(TdsEnums.SNI_SUCCESS == error || TdsEnums.SNI_SUCCESS_IO_PENDING == error))
    {
        DecrementPendingCallbacks(false); // Failure - we won't receive callback!
    }
}

handle 的值是来自 SessionHandle ，继续追，来到了 TdsParserStateObjectManaged.cs 的 CreatePhysicalSNIHandle 方法

internal override void CreatePhysicalSNIHandle(string serverName, bool ignoreSniOpenTimeout, long timerExpire, out byte[] instanceName, ref byte[] spnBuffer, bool flushCache, bool async, bool parallel, bool isIntegratedSecurity)
{
    _sessionHandle = SNIProxy.Singleton.CreateConnectionHandle(this, serverName, ignoreSniOpenTimeout, timerExpire, out instanceName, ref spnBuffer, flushCache, async, parallel, isIntegratedSecurity);
    if (_sessionHandle == null)
    {
        _parser.ProcessSNIError(this);
    }
    else if (async)
    {
        // Create call backs and allocate to the session handle
        SNIAsyncCallback ReceiveAsyncCallbackDispatcher = new SNIAsyncCallback(ReadAsyncCallback);
        SNIAsyncCallback SendAsyncCallbackDispatcher = new SNIAsyncCallback(WriteAsyncCallback);
        _sessionHandle.SetAsyncCallbacks(ReceiveAsyncCallbackDispatcher, SendAsyncCallbackDispatcher);
    }
}

通过上面的 ReadAsyncCallback 追踪到了前面提到的进行 TrySetResult 操作的 ReadAsyncCallback 方法。

internal void ReadAsyncCallback(SNIPacket packet, UInt32 error) => ReadAsyncCallback(IntPtr.Zero, packet, error);

通过源码追踪也确认了延迟的确是来自 SNIPacket.ReadFromStreamAsync 中的 stream.ReadAsync 操作，而 stream 的值是一个 NetworkStream 的实例（详见 SNITcpHandle 的构造函数）。

为什么读取 NetworkStream 的过程中发生了延迟？这是接下来需要进一步排查的问题。