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 的過程當中發生了延遲？這是接下來須要進一步排查的問題。