使用Filter跟踪Asp.net MVC页面加载时间

浏览数：79 / 时间：2015年06月09日

最近，客户一直反馈系统使用慢，有时候能够指出具体是哪个页面，有时候又只是笼统地反馈慢。这种问题就像是幽灵一样，非常不好处理。因为导致这种问题的因素非常之多，而且在开发工程中，很难模拟出实际运行是的环境。理论上，对于所有的页面做压力测试是个解决方案，但是这种方式的成本太高，又没有办法很快地定位和解决客户的问题。

最后，考虑通过创建Filter来在访问Action之前记录一个时间，在页面Render完成之后，再记录一下时间。通过比较这2个时间的差值来跟踪每个页面的加载性能。如果对于MVC中的Filter还不太熟悉，可以看这里Asp.net MVC使用Filter解除Session, Cookie等依赖，文章有对于Filter的介绍和使用。

言归正传，直接上代码。通过继承ActionFilterAttribute, 分别重写OnActionExecuting和OnResultExecuted方法。

public class TrackPageLoadPerformanceAttribute : ActionFilterAttribute
   {

      //这里使用log4net来打印出结果
       private static readonly ILog Log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);

      //创建字典来记录开始时间，key是访问的线程Id.
       private readonly Dictionary<int, DateTime> _start = new Dictionary<int, DateTime>();

      //创建字典来记录当前访问的页面Url.
       private readonly Dictionary<int, string > _url = new Dictionary<int, string>();

       public override void OnActionExecuting(ActionExecutingContext filterContext)
       {
           //过滤掉ChildAction, 因为ChildAction实际上不是一个单独的页面
           if(filterContext.IsChildAction) return;

           var currentThreadId = System.Threading.Thread.CurrentThread.ManagedThreadId;

           try
           {
               _start.Add(currentThreadId, DateTime.Now);
               _url.Add(currentThreadId, filterContext.HttpContext.Request.Url == null
                   ? string.Empty
                   : filterContext.HttpContext.Request.Url.AbsoluteUri);
           }
           catch (Exception ex)
           {
               Log.Error(ex.ToString());
           }
       }

       public override void OnResultExecuted(ResultExecutedContext filterContext)
       {
           var currentThreadId = System.Threading.Thread.CurrentThread.ManagedThreadId;
           if (!_start.ContainsKey(currentThreadId)) return;

           try
           {

                //计算出当前页面访问耗时
               var costSeconds = (DateTime.Now - _start[currentThreadId]).TotalSeconds;
               if (costSeconds > 2)//如果耗时超过2秒，就是用log4net打印出，具体是哪个页面访问超过了2秒，具体使用了多长时间。
               {
                   Log.Info(string.Format("Access the action more than 2 seconds. cost seconds {1}.  URL: {0}", _url[currentThreadId], costSeconds));
               }
           }
           catch (Exception ex)
           {
               Log.Error(ex.ToString());
           }
           finally
           {
               _start.Remove(currentThreadId);
               _url.Remove(currentThreadId);
           }
       }
   }