搞搞就懂

前言

---

先前介紹過 JMeter 可針對 Web API 進行負載測試，並透過統計數據了解各 Web API 回應的時間，但若想精準了解 Web API 內各處理項目的執行時間，可以透過 NanoProfiler 幫我們記錄下這些資訊，這些都是在推敲效能瓶頸過程中不可或缺的重要資訊，特別是在操作 DB 所耗費的時間，透過 NanoProfiler 更是可不費吹灰之力的自動逐條詳列，並可重現當下呼叫 SP 所傳入的參數值，真的是非常方便，以下介紹。

 

先看效果

---

效能調教最重要的事情就是找出效能瓶頸，當在有安裝 NanoProfiler 的環境下，面對這類問題不囉嗦就是直接開啟 NanoProfiler 資訊頁面，找尋回應時間最長的 Web API 並點選開啟細項，此時效能瓶頸清清楚楚一覽無遺；接著只要針對回應最久的那隻  Stored Procedure 進行調教即可，省去不少繁瑣地分析過程及時間。

下圖為真實案例，當時就是透過 NanoProfiler 獲得許多重要資訊，方便筆者釐清問題並有足夠資訊進行後續效能調教事宜。

1. 在此 Web API 耗費在資料庫查詢的時間就花了 5136 ms (資料庫回應過久)
2. 其中執行 usp_EHR_MENU_GET_FREQUENCY 就花 4610 ms (瓶頸所在)
3. 點選 data 後可顯示當下傳入 Stored Procedure 之參數 (重現問題)

 

安裝說明

---

直接在 ASP.NET Web API 專案中透過 Nuget 安裝以下套件：

• NanoProfiler
• NanoProfiler.Web
• NanoProfiler.Data
• NanoProfiler.Storages.Json

接著若依照官方資訊來設定 web.config 會報錯，因此在參考 使用 NanoProfiler 對 ASP.NET Web API 進行性能監控 文章後修改 web.config 如下就可以順利使用了。

<configuration>
  
  ...

  <!--for using nanoprofiler-->
  <configSections>
    <section name="slf4net" type="slf4net.Configuration.SlfConfigurationSection, slf4net" />
    <section name="nanoprofiler" type="EF.Diagnostics.Profiling.Configuration.NanoProfilerConfigurationSection, NanoProfiler" />
  </configSections>
  <nanoprofiler circularBufferSize="500" storage="EF.Diagnostics.Profiling.Storages.Json.JsonProfilingStorage, NanoProfiler.Storages.Json">
    <filters>
      <add key="_tools" value="_tools/" type="Contain" />
      <!--<add key="exts" value="ico,jpg,js,css" type="FileExt" />-->
      <add key="exts" value="ico,jpg,js,css" type="EF.Diagnostics.Profiling.Web.ProfilingFilters.FileExtensionProfilingFilter, NanoProfiler.Web" />
      <add key="ViewProfilingLogsHandler" value="ViewProfilingLogsHandler.*" type="regex" />
    </filters>
  </nanoprofiler>

  ...

</configuration>

 

顯示紀錄

---

只要在站台位置後面加上 nanoprofiler/view ，即可開啟 NanoProfiler 資訊頁，其中紀錄資料的筆數會依照 web.config 中 circularBufferSize="500" 設定值而定，可依本身需求調整該數值，保留最近 N 筆紀錄在記憶體中供開發人員查閱。

 

紀錄【DB 回應】時間

---

為什麼 NanoProfiler 可以紀錄所有應用程式向 DB 發出請求及回應時間，想當然爾必然是從 DB Connection 下手啦！因此需要在 DB Connection 外包裝 ProfiledDbConnection 物件來使用，如此 NanoProfiler 就有能力取得應用程式對於 DB 的所有操作行為及回應數據，請參考以下做法。

public static IDbConnection Connection
{
    get
    {
        var dbConnection = new SqlConnection("your connection string");
      
        // wrap connection by ProfiledDbConnection 
        var dbProfiler = new DbProfiler(ProfilingSession.Current.Profiler);    
        return new ProfiledDbConnection(dbConnection, dbProfiler);
    }
}

接著任何程式都不需調整，只要使用 ProfiledDbConnection 對 DB 的任何請求都會被詳實的紀載下來。

可以點選 data 超連結顯示該 stored procedure 實際傳入的參數值

 

紀錄【邏輯運算】時間

---

不知道大家有沒有覺得以下的圖怪怪的，怎麼在呼叫 SP 前後有一段空白的時間？這支 API 總共耗時 1131 ms，但是在 DB 的花費只有 175 ms，所以推測在呼叫 SP 前後都有 C# 邏輯運算的時間消耗。

此時若想要精細了解各邏輯運算所耗費的時間，可以使用 ProfilingSession.Current.Step 來處理，藉此獲得特定行為所執行的時間；其中若有相關使用參數需要被記載下來，可以透過 step.AddTag 或 step.AddField 告知 NanoProfiler 一併顯示該資訊於結果頁面，示意代碼如下所示。

public IHttpActionResult PostCheckToken(UspSsoBaseTokenDto uspSsoBaseDto)
{
    using (var step = ProfilingSession.Current.Step("step - pre action"))
    {

        step.AddTag(this.deviceId);
        step.AddField("clientIP", this.clientIP);

        // do something here
        // ...
    }

    var result = service.CheckToken(uspSsoBaseDto);

    using (var step = ProfilingSession.Current.Step("step - post action "))
    {
        // do something here
        // ...
    }

}

可從結果看出執行 SP 前後執行特定邏輯運算所耗費的時間。

點選 data 後則可以看到我們寫入 tag / field 的資訊。

 

篩選追蹤資料

---

當測試資料過多時，可以使用程式來篩選所需要記錄的特定資料；例如我們只希望列出時間消耗過久的 Web API ，因此可以在 Application_Start() 中加入以下代碼，表示僅記錄回應時間超過 1500 ms 的項目，讓開發人員一眼就看出效能低落的項目。

protected void Application_Start()
{
    GlobalConfiguration.Configure(WebApiConfig.Register);


    // 若在 web.config 中有啟用 NanoProfiler 時套用新規則
    if (ProfilingSession.CircularBuffer != null)
    {
        // 1. 資料上限為 200 筆
        // 2. 排除回應時間小於 1500 ms 的項目
        ProfilingSession.CircularBuffer =
            new CircularBuffer<ITimingSession>(200, session => session.DurationMilliseconds < 1500);
    }

               
}

 

上線前準備

---

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

 

接著即使 circularBufferSize 設定為 0，若仍使用 ProfiledDbConnection 作為 DB 連線，感覺還是會有多走一層的效能疑慮；因此筆者發現當 web.config 中 circularBufferSize = 0 時 ProfilingSession.CircularBuffer 會為 Null，所以可使用此邏輯來判斷是否需使用 ProfiledDbConnection 來追蹤 DB 效能。取得連線方式修改如下。

public static IDbConnection Connection
{
    get
    {
        var dbConnection = new SqlConnection("your connection string");
        if (ProfilingSession.CircularBuffer == null)
        {
            // return pure connection if profiling is disable
            return dbConnection;
        }

        // wrap connection by ProfiledDbConnection 
        var dbProfiler = new DbProfiler(ProfilingSession.Current.Profiler);
        return new ProfiledDbConnection(dbConnection, dbProfiler);
    }
}

 

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

 

---

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

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