搞搞就懂

前言

日前在針對 Web API 做非同步機制的調整時，本想透過 NanoProfiler 驗證看看是否有回應時間的改善，但居然沒發揮出非同步執行的優勢；因此就做了個小測試，發現若使用 ProfiledDbConnection 包裝原本 DB 連線後，預期的非同步效果就會消失，感覺似乎都在每筆 DB 查詢後立即 await 獲得資料。以下為實測過程，文末也有提供筆者關閉 NanoProfiler 方式可供參考。(測試版本為 2.0.8.4 )

事前準備

假設目前存在兩隻 Stored Procedure 分別為 usp_async_test_1 及 usp_async_test_2，為模擬處理時間則都在 SP 中等待 1 秒鐘，代碼如下。

-- SP1
CREATE PROCEDURE [dbo].[usp_async_test_1]
AS BEGIN
	SET NOCOUNT ON;
	WAITFOR DELAY '00:00:01'
	SELECT 1
END

-- SP2
CREATE PROCEDURE [dbo].[usp_async_test_2]
AS BEGIN
	SET NOCOUNT ON;
	WAITFOR DELAY '00:00:01'
	SELECT 2
END

建立非同步呼叫 Stored Procedure 的方法如下。

public IDbConnection CreateConnection()
{
    return new SqlConnection(str);
}

private async Task<int> DoSP1Async(IDbConnection cn)
{
    var result = await cn.QueryAsync<int>("usp_async_test_1", commandType: CommandType.StoredProcedure);
    return result.FirstOrDefault();
}

private async Task<int> DoSP2Async(IDbConnection cn)
{
    var result = await cn.QueryAsync<int>("usp_async_test_2", commandType: CommandType.StoredProcedure);
    return result.FirstOrDefault();
}

預期的非同步作業

使用非同步方式執行 SP 的 Web API 代碼如下

public async Task<IHttpActionResult> Get()
{

    // 非同步執行呼叫 SP1
    var sp1Task = DoSP1Async(CreateConnection());

    // 非同步執行呼叫 SP2
    var sp2Task = DoSP2Async(CreateConnection());


    // ....


    // 在此等待 sp1 結果回傳 (約花費 1 秒等待時間)
    var sp1Result = await sp1Task;

    // 在此等待 sp2 結果回傳 (在等待 sp1 處理的時間，sp2 也已經完成了，無產生等待時間)
    var sp2Result = await sp2Task;


    return Ok();
}

透過 JMeter 計算執行時間如下，結果如預期僅花費 1012 ms，也就是在等待 DoSP1 的同時間， DoSP2 也正在執行中，而此情境兩者花費的時間相同，因此當 DoSP1 處理完畢時， DoSP2 也完成作業了。

加入 NanoProfiler 造成非同步作業失效

筆者原本想要使用 NanoProfiler 來呈現非同步機制下 DB 回應時間線圖，但突然發現會造成非同步作業的優勢完全失效，測試如下。調整使用 ProfiledDbConnection 將原本使用的 SqlConnection 包裝起來，讓 NanoProfiler 監看 DB 所有操作的回應時間。

透過 JMeter 計算執行時間如下，結果讓筆者整個大傻眼居然花費 2009 ms，根本沒有非同步的效果。

我想應該跟 NanoProfiler 在追蹤 DB 作業的機制有關吧！所以在「系統上線」或「負載測試」時，切記不要使用 ProfiledDbConnection 包裝後的連線來對 DB 進行操作，一來是因為 NanoProfiler 在追蹤 DB 作業時會提供許多敏感資訊，當然不可被攤在陽光下，另外同時也會造成非同步機制的失效，影響系統運作效能。

如何關閉 NanoProfiler 追蹤

由於 NanoProfiler 內含許多敏感性資料，因此上線前切記移除此頁面，而移除方式很簡單就把 web.config 中 circularBufferSize 設定為 0 筆即可 。

此時再度訪問時，該結果頁面就已經不存在了。

接著即使 circularBufferSize 設定為 0，若仍使用 ProfiledDbConnection 作為 DB 連線，還是會有非同步失效問題發生，因此我們需要來解決一下 DB 連線問題；筆者發現當 web.config 中 circularBufferSize = 0 時 ProfilingSession.CircularBuffer 會為 Null，所以可使用此邏輯來判斷是否需使用 ProfiledDbConnection 來追蹤 DB 效能。取得連線方式修改如下。

public IDbConnection CreateConnection()
{

    if (ProfilingSession.CircularBuffer == null)
    {
        return new SqlConnection(str);
    }
    else
    {
        // 使用 NanoProfiler 監看 DB 回應時間
        var sqlConnection = new SqlConnection(str);
        var dbProfiler = new DbProfiler(ProfilingSession.Current.Profiler);
        return new ProfiledDbConnection(sqlConnection, dbProfiler);
    }

}

如此我們就可以透過 web.config 中 circularBufferSize 數值作為是否啟用 NanoProfiler 追蹤效能的開關，平常可以依照需求調整需監看最近 N 筆紀錄；當上線前或進行負載測試時，只要記得將 circularBufferSize 設定為 0 即可，避免 NanoProfiler 對系統效能造成負面的影響。

總結

NanoProfiler 可以幫助開發人員釐清效能瓶頸位置，但切記在「上線」或「負載測試」時須完整地關閉它，除設定 circularBufferSize = 0 不記錄任何資料外，也需要將 DB Connection 切換不使用 ProfiledDbConnection 來操作 DB ，否則非同步效果就消失，對於系統效能將會有所衝擊，所以記得一定要完整的關閉唷！

更新資訊 (2017-09-10)

針對使用 NanoProfiler 造成非同步操作 DB 效果失效的問題，在熱心友人幫忙提報 issue 給 NanoProfiler 作者後得到善意的回應如下：

佛心作者也很迅速地發布 v2.1 版本，經筆者測試後果然改善了這個問題；以本篇文章的測試情境結果，完美地呈現出非同步執行所帶來的效益，大家又可以精準的掌握非同步狀況下實質的效能反饋啦！

希望此篇文章可以幫助到需要的人

若內容有誤或有其他建議請不吝留言給筆者喔 !