mrkt 的程式學習筆記: 觀察 PagedList.Mvc + ASP.NET MVC 5 + EF 6 的執行效能

這陣子有網友詢問為何使用 PagedList.Mvc 所執行的效能為何會相當緩慢，而在看過程式碼後並未發現到有做任何特殊的處理或複雜的操作，就只是從 DbContext 將資料取出後再使用 ToPagedList() 方法取得分頁資料，另外我也曾建議他可以使用 LINQPad 去做單純的 EF 取得資料的觀察，這麼做是要將資料存取的環境給單純化，排除 ASP.NET MVC 環境的影響，而這位朋友回報說在 LINQPad 執行 EF 的取得資料處理是很快的，因為這位網友只給我看 Controller 裡 Action 方法的程式內容而已，我無從了解前端 View 是否有做其他的處理，所以我也不知道造成執行效能緩慢的原因為何。

無論使用 MvcPaging 或是 PagedList.Mvc，在取得分頁資料的操作處理上我並沒有遇到這樣的狀況，這些分頁套件並不是造成效能緩慢的主因，因為在我所處理過上萬筆甚至上百萬筆資料的分頁操作都不曾發生這樣的事情，其實造成效能緩慢的原因有很多可能，所以就必須一個一個去找尋原因，例如說將 PagedList.Mvc 從網站裡移除，然後觀察一次取得所有資料是否緩慢、使用 Skip Take 方法取得部份資料是否緩慢、不使用 EF 而直接使用 ADO.NET 執行 SQL Command、調整資料庫的設計或加上索引等，藉由這些的方式將原因給找出，而不是直接懷疑或認定 PagedList.Mvc 就是兇手。

這一篇簡單說明在 ASP.NET MVC 5 使用 EF 6 的 Intercepting 功能來觀察 PagedList.Mvc 的處理與執行的時間。

有關 EF6 的 Logging 與 Intercepting 功能，在之前的文章也有介紹過，還沒有接觸過的朋友可以先前往了解。

初探 Entity Framework 6 - Logging

初探 Entity Framework 6 - Intercepting Part.1

初探 Entity Framework 6 - Intercepting Part.2

因為有人反應過為何每次的文章範例都要使用 Northwind 而不是使用對應版本的範例資料庫呢？這是因為已經習慣使用 Northwind 了，我並不是主要關注 SQL Server 的開發人員，所以範例資料庫是否對應資料庫的版本對於我來說並不是重點，我知道每一個 SQL Server 版本都會有對應的 AdventureWorks 範例資料庫，但是這些範例資料庫可能對於主要從事資料庫開發與維護的 DBA 比較有直接關係，相對於我只是一個單純的網頁程式開發人員來說，我只要能夠透過 EF 或 ADO.NET 去取得資料庫裡的資料然後做處理與顯示就可以了，所以範例資料庫是不是用 Northwind 或是使用 SQL Server 2008R2 就得要用 AdventureWorks2008R2 範例資料庫，這都不是重點。

說了一堆，這次就來使用 AdventureWorks2012 範例資料庫來作為這篇文章的資料來源，各個版本的範例資料庫可以從以下的網站裡取得。

http://msftdbprodsamples.codeplex.com/

http://msftdbprodsamples.codeplex.com/releases/view/93587

這邊我使用的是「AdventureWorks2012_Database.zip」，壓縮檔裡是「AdventureWorks2012_Data.mdf 與 AdventureWorks2012_Data.ldf」，我這邊所使用的是 MS SQL Server Express 2012，使用附加功能將 AdventureWorks2012 範例資料庫加入到 SQL Server Express 裡，

再來使用 VS2013 建立一個 ASP.NET MVC 5 網站，並且使用 Entity Framework 6

加入 ADO.NET 實體資料模型

這裡我將會使用 Person 來做分頁的操作，因為 Person 裡面的資料蠻多的（有 19972 筆資料），而且關聯也不少，

接著透過 NuGet 安裝 PagedList.Mvc 與 NLog，

建立 PersonController.cs 與程式內容

完成 View 的內容

@using PagedList@using PagedList.Mvc@model IPagedList<BlogSample.Models.Person> @{    ViewBag.Title = "Index";}@section styles{    <link href="~/Content/PagedList.css" rel="stylesheet" />}@{    var itemSliceAndTotalItem = string.Format("顯示項目：{0} ~ {1}, 共 {2} 項",        Model.FirstItemOnPage, Model.LastItemOnPage, Model.TotalItemCount);} <h2>AdventureWorks - Person</h2> <div class="row">    <div class="col-sm-12">        @Html.PagedListPager(Model, page => Url.Action("Index", new { page }),            PagedListRenderOptions.ClassicPlusFirstAndLast)    </div></div><div class="row">    <div class="col-sm-12 pagination-sm">        共 @Model.PageCount 頁 , @itemSliceAndTotalItem    </div></div><br /><table class="table">    <tr>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().PersonType)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().NameStyle)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().Title)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().FirstName)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().MiddleName)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().LastName)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().Suffix)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().EmailPromotion)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().EmailAddresses)        </th>        <th>            @Html.DisplayNameFor(model => model.FirstOrDefault().PersonPhones)        </th>    </tr>     @foreach (var item in Model)    {        <tr>            <td>                @Html.DisplayFor(modelItem => item.PersonType)            </td>            <td>                @Html.DisplayFor(modelItem => item.NameStyle)            </td>            <td>                @Html.DisplayFor(modelItem => item.Title)            </td>            <td>                @Html.DisplayFor(modelItem => item.FirstName)            </td>            <td>                @Html.DisplayFor(modelItem => item.MiddleName)            </td>            <td>                @Html.DisplayFor(modelItem => item.LastName)            </td>            <td>                @Html.DisplayFor(modelItem => item.Suffix)            </td>            <td>                @Html.DisplayFor(modelItem => item.EmailPromotion)            </td>            <td>                @Html.DisplayFor(modelItem => item.EmailAddresses.FirstOrDefault().EmailAddress1)            </td>               <td>                @Html.DisplayFor(modelItem => item.PersonPhones.FirstOrDefault().PhoneNumber)            </td>        </tr>    } </table>

執行結果

這邊執行每一個分頁的時間都很短，並沒有任何緩慢的情況發生，既使將 PageSize 調整為 100 也是沒有發生效能緩慢的情況，口說無憑，所以這邊就使用 EF6 的 Intercepting 功能來觀察每次分頁的執行內容與時間。

先在 ASP.NET MVC 網站裡建立 Infrastructure 資料夾，在 Infrastructure 資料夾裡再建立 Interceptor 資料夾，然後建立 NLogCommandInterceptor.cs，完整內容如下：

using System;using System.Collections.Generic;using System.Data;using System.Data.Common;using System.Data.Entity.Infrastructure.Interception;using System.Diagnostics;using System.Linq;using System.Text;using System.Web;using NLog; namespace WebApplication1.Infrastructure.Interceptor{    class NLogCommandInterceptor : IDbCommandInterceptor    {        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();         private readonly Stopwatch _stopwatch = new Stopwatch();         protected internal Stopwatch Stopwatch        {            get { return _stopwatch; }        }          public void NonQueryExecuting(            DbCommand command, DbCommandInterceptionContext<int> interceptionContext)        {            LogIfNonAsync(command, interceptionContext);            Stopwatch.Restart();        }         public void NonQueryExecuted(            DbCommand command, DbCommandInterceptionContext<int> interceptionContext)        {            Stopwatch.Stop();            LogNonQueryCommand(command, interceptionContext);        }         public void ReaderExecuting(            DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)        {            //LogIfNonAsync(command, interceptionContext);            Stopwatch.Restart();        }         public void ReaderExecuted(            DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)        {            if (interceptionContext.Exception != null)            {                LogIfError(command, interceptionContext);            }            else            {                Stopwatch.Stop();                string logContent = LogCommand(command, interceptionContext);                Logger.Trace(logContent);            }        }         public void ScalarExecuting(            DbCommand command, DbCommandInterceptionContext<object> interceptionContext)        {            //LogIfNonAsync(command, interceptionContext);            Stopwatch.Restart();        }         public void ScalarExecuted(            DbCommand command, DbCommandInterceptionContext<object> interceptionContext)        {            if (interceptionContext.Exception != null)            {                LogIfError(command, interceptionContext);            }            else            {                Stopwatch.Stop();                string logContent = LogCommand(command, interceptionContext);                Logger.Trace(logContent);            }        }         //=========================================================================================         private void LogIfNonAsync<TResult>(            DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)        {            if (!interceptionContext.IsAsync)            {                Logger.Trace("Non-async command used: {0}", command.CommandText);            }        }         private void LogIfError<TResult>(            DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)        {            if (interceptionContext.Exception != null)            {                Logger.Error("Command {0} failed with exception {1}",                    command.CommandText, interceptionContext.Exception);            }        }         private void LogNonQueryCommand<TResult>(            DbCommand command,            DbCommandInterceptionContext<TResult> interceptionContext)        {            if (command == null)            {                throw new ArgumentNullException("command");            }            if (interceptionContext == null)            {                throw new ArgumentNullException("interceptionContext");            }             if (interceptionContext.Exception != null)            {                LogIfError(command, interceptionContext);            }            else            {                //只有針對不是非同步處理                if (!interceptionContext.IsAsync)                {                    string logContent = LogCommand(command, interceptionContext);                    Logger.Trace(logContent);                }            }        }         /// <summary>        /// Logs the command.        /// </summary>        /// <typeparam name="TResult">The type of the result.</typeparam>        /// <param name="command">The command.</param>        /// <param name="interceptionContext">The interception context.</param>        /// <returns></returns>        /// <exception cref="System.ArgumentNullException">        /// command        /// or        /// interceptionContext        /// </exception>        private string LogCommand<TResult>(            DbCommand command,            DbCommandInterceptionContext<TResult> interceptionContext)        {            if (command == null)            {                throw new ArgumentNullException("command");            }            if (interceptionContext == null)            {                throw new ArgumentNullException("interceptionContext");            }             var commandText = command.CommandText ?? "<null>";             if (!commandText.EndsWith(Environment.NewLine, StringComparison.Ordinal))            {                commandText = string.Concat(commandText, Environment.NewLine);            }             commandText = string.Concat(                commandText, Environment.NewLine,                "Parameters: ", Environment.NewLine);             foreach (var parameter in command.Parameters.OfType<DbParameter>())            {                commandText = string.Concat(                    commandText,                    LogParameter(command, interceptionContext, parameter));            }             //執行開始時間            commandText = string.Concat(commandText, Environment.NewLine,                "-- Executing at ", DateTimeOffset.Now.ToLocalTime());             //取得目前執行個體所測量的已耗用時間總和，以毫秒為單位             long z = 10000 * Stopwatch.ElapsedTicks;            decimal timesTen = (int)(z / Stopwatch.Frequency);            var elapsedMilliseconds = timesTen / 10;             commandText = string.Concat(commandText, Environment.NewLine,                "-- Completed in ", elapsedMilliseconds, " ms");             return commandText;        }         private string LogParameter<TResult>(            DbCommand command,            DbCommandInterceptionContext<TResult> interceptionContext,            DbParameter parameter)        {            if (command == null)            {                throw new ArgumentNullException("command");            }            if (interceptionContext == null)            {                throw new ArgumentNullException("interceptionContext");            }            if (parameter == null)            {                throw new ArgumentNullException("parameter");            }             // -- Name: [Value] (Type = {}, Direction = {}, IsNullable = {}, Size = {}, Precision = {} Scale = {})            var builder = new StringBuilder();            builder.Append("-- ")                .Append(parameter.ParameterName)                .Append(": '")                .Append((parameter.Value == null || parameter.Value == DBNull.Value) ? "null" : parameter.Value)                .Append("' (Type = ")                .Append(parameter.DbType);             if (parameter.Direction != ParameterDirection.Input)            {                builder.Append(", Direction = ").Append(parameter.Direction);            }            if (!parameter.IsNullable)            {                builder.Append(", IsNullable = false");            }            if (parameter.Size != 0)            {                builder.Append(", Size = ").Append(parameter.Size);            }            if (((IDbDataParameter)parameter).Precision != 0)            {                builder.Append(", Precision = ").Append(((IDbDataParameter)parameter).Precision);            }            if (((IDbDataParameter)parameter).Scale != 0)            {                builder.Append(", Scale = ").Append(((IDbDataParameter)parameter).Scale);            }             builder.Append(")").Append(Environment.NewLine);             return builder.ToString();        }     }}

其中取得執行時間的部份並非使用 Stopwatch.ElapsedMilliseconds() 方法，但是這邊所取得的值並非相當精確，所以使用 ElapsedTicks 屬性的值，另外需要考量到每個執行開發環境的不同，所以使用 Stopwatch.Frequency 取得系統計時器的頻率為基礎，最後所算出來的時間就會比較精確。

MSDN - Stopwatch.ElapsedTicks 屬性 (System.Diagnostics)

MSDN - Stopwatch.Frequency 欄位 (System.Diagnostics)

MSDN - Stopwatch.ElapsedMilliseconds 屬性 (System.Diagnostics)

接著到 Global.asax 的 Application_Start() 裡加入 NLogCommandInterceptor 的使用，

我們是透過 NLog 將 SQL Command 的內容與執行時間給紀錄起來，然後顯示到 Visual Studio 的 Output 視窗中，NLog.Config target 與 rule 設定如下：

<?xml version="1.0" encoding="utf-8" ?><nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">     <!--   See http://nlog-project.org/wiki/Configuration_file   for information on customizing logging rules and outputs.   -->    <targets>        <!-- add your targets here -->         <target name="debugger" xsi:type="Debugger"                layout="=========================================================================${newline}DateTime：${longdate} ${newline}Level：${level:uppercase=true} ${newline}Logger：${logger} ${newline}Source：${callsite:className=true} ${newline}Message：${message} ${newline}=========================================================================${newline}        "/>    </targets>     <rules>        <!-- add your logging rules here -->        <logger name="*" minlevel="Trace" writeTo="debugger" />    </rules></nlog>