2014年1月6日 星期一

觀察 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

image

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

image

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

image

加入 ADO.NET 實體資料模型

SNAGHTMLba20431

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

image

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

image

image

建立 PersonController.cs 與程式內容

image

完成 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>

執行結果

image

這邊執行每一個分頁的時間都很短,並沒有任何緩慢的情況發生,既使將 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 的使用,

image

我們是透過 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>

 

第一次執行的紀錄(PageSize 為 100)

image

image

執行第 100 頁的紀錄

image

image

可以看到當頁數越大的時候執行時間就會拉長,如果我們把 PageSize 修改為 20 後再來看看,

PageSize 修改為 20 後的第一頁執行紀錄

image

第 100 頁

image

 


因為之前介紹過得 MiniProfiler 與 Clutch.Diagnostics.EntityFramework 還沒有支援 EF6,所以使用 EF6 的專案就可以使用內建的 Intercepting 功能並搭配 NLog 來做紀錄與觀察。

造成效能緩慢的原因有很多,由上面的操作示範可以知道 PagedList.Mvc 並不是主因,就如同我一開始所說的,就要開發人員自己一個一個去找原因了,畢竟造成效能緩慢的可能性實在太多了,不可能只憑幾行程式就能診斷出來。

 

延伸閱讀:

初探 Entity Framework 6 - Logging

初探 Entity Framework 6 - Intercepting Part.1

初探 Entity Framework 6 - Intercepting Part.2

ASP.NET MVC + NLog + Clutch.Diagnostics.EntityFramework 追蹤 EF 執行的 SQL Command

mrkt 的程式學習筆記 – MiniProfiler

 

以上

沒有留言:

張貼留言

提醒

千萬不要使用 Google Talk (Hangouts) 或 Facebook 及時通訊與我聯繫、提問,因為會掉訊息甚至我是過了好幾天之後才發現到你曾經傳給我訊息過,請多多使用「詢問與建議」(在左邊,就在左邊),另外比較深入的問題討論,或是有牽涉到你實作程式碼的內容,不適合在留言板裡留言討論,請務必使用「詢問與建議」功能(可以夾帶檔案),謝謝。