在MVC或WEBAPI中记录每个Action的执行时间和记录下层方法调用时间

刚才在博客园看了篇文章，http://www.cnblogs.com/cmt/p/csharp_regex_timeout.html  突然联想到以前遇到的问题，w3wp进程吃光CPU都挂起IIS进程，即使网站或者服务出现了问题，导致CPU百分之百，但是有时候我们根本不知道具体哪里出了问题！公司曾经一个项目组遇到过WCF服务端莫名其妙就CPU占用百分之百的情况，但是具体有查不到原因。我总结了下，查不到原因是因为没有合理的方法，根本不知道从何开始查。如果当时对客户端或者服务端方法调用都加上日志，估计很快就查到了是哪个方法出了问题。

如果在在MVC或者WEBAPI中，记录每个action的执行时间，后期用来做一些分析，我们会发现哪些调用是执行耗时是比较久的，下面分享下我们在项目中是如何做的。

记录每个action的执行时间，这个需要点技巧。记录下层调用的时间也需要一些技巧的，最开始我想用动态代理来实现，后来发现这个东西不是那么的友好，后来换了种思路去实现。

首先介绍MVC和WEBAPI如何记录action的执行时间

MVC的实现

using System.Diagnostics;
using System.Globalization;
using System.Web.Mvc;

namespace WebSeat.Web.Core
{
    public class TimingActionFilter : IActionFilter
    {
        private const string Key = "__action_duration__";

        public void OnActionExecuting(ActionExecutingContext filterContext)
        {
            var stopWatch = new Stopwatch();
            stopWatch.Start();
            //filterContext.HttpContext.Request.Params[Key] = stopWatch;
            filterContext.HttpContext.Items[Key] = stopWatch;
        }

        public void OnActionExecuted(ActionExecutedContext filterContext)
        {
            var items = filterContext.HttpContext.Items;
            if (!items.Contains(Key))
            {
                return;
            }
            var stopWatch = items[Key] as Stopwatch;
            if (stopWatch == null)
            {
                return;
            }
            stopWatch.Stop();
            var actionName = filterContext.ActionDescriptor.ActionName;
            var controllerName = filterContext.ActionDescriptor.ControllerDescriptor.ControllerName;
#if  DEBUG
            Debug.WriteLine("Execute {0}- {1} took {2}.]", controllerName, actionName, stopWatch.ElapsedMilliseconds);
#endif

            var response = filterContext.HttpContext.Response;
            if (response != null)
            {
                response.AddHeader("TotalSpendTimes",
                    stopWatch.ElapsedMilliseconds.ToString(CultureInfo.InvariantCulture));
            }
        }
    }
}

最后在Application_Start中注册一下

 FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);

public class FilterConfig
    {
        public static void RegisterGlobalFilters(GlobalFilterCollection filters)
        {
            filters.Add(new HandleErrorAttribute());
            filters.Add(new TimingActionFilter());
        }
    }

WEBAPI中的实现 

using System.Diagnostics;
using System.Globalization;
using System.Web.Http.Controllers;
using System.Web.Http.Filters;

namespace WebSeat.FlipCourse.WebApi.Resolver.Filter
{
    public class TimingActionFilter : ActionFilterAttribute
    {
        private const string Key = "__action_duration__";
        public override void OnActionExecuting(HttpActionContext actionContext)
        {
            var stopWatch = new Stopwatch();
            actionContext.Request.Properties[Key] = stopWatch;
            stopWatch.Start();
        }

        public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
        {
            if (!actionExecutedContext.Request.Properties.ContainsKey(Key))
            {
                return;
            }
            var stopWatch = actionExecutedContext.Request.Properties[Key] as Stopwatch;
            if (stopWatch == null)
            {
                return;
            }
            stopWatch.Stop();
            var actionDescriptor = actionExecutedContext.ActionContext.ActionDescriptor;
            var actionName = actionDescriptor.ActionName;
            var controllerName = actionDescriptor.ControllerDescriptor.ControllerName;
#if  DEBUG
            Debug.WriteLine("Execute {0}- {1} took {2}.]", controllerName, actionName, stopWatch.ElapsedMilliseconds);
            //可直接记录到日志中
#endif
            if (actionExecutedContext.Response != null)
            {
                actionExecutedContext.Response.Content.Headers.Add("TotalSpendTimes", stopWatch.ElapsedMilliseconds.ToString(CultureInfo.InvariantCulture));
            }
        }
    }
}

上面记录Controller里面action的执行时间，action其实调用了底层方法，其实也就记录了整个调用过程的耗时。但是如果我们的程序没有被MVC或者WEBAPI呢？比如我们只是用WCF来提供服务，此时没有了Filter，这就麻烦了。但由于我们项目一直采用分层架构，上层肯定会调用下层，下层返回相应的数据，并且返回相关的调用状态。

底层我们统一返回InvokeResult<T>泛型对象，里面包含返回的数据以及此次操作的其他信息。

　　/// <summary>
    ///     操作状结果处理--有返回值
    /// </summary>
    /// <typeparam name="T"></typeparam>
    public class HandleResult<T>
    {
        public HandleResult()
        {
            Success = true;
            InvokCode = InvokeCode.Success;
        }

        public T Result { get; set; }
        public string Message{ get; set; }
        public InvokeCode InvokCode { get; set; }
        public bool Success { get; set; }
    }

上层调用下层并向客户端返回ClientResult<T>泛型对象

/// <summary>
    ///     操作状结果处理--有返回值
    /// </summary>
    /// <typeparam name="T"></typeparam>
    public class ClientResult<T>
    {

        public T Result { get; set; }

        public string Message { get; set; }

        public bool Success { get; set; }
    }

为什么要统一返回一种类型呢，这个我不多说，用过的人自然之道他的好处。现在就要做一个转换，把下层返回的HandleResult<T>转换为ClientResult<T>。如果在项目中只用HandleResult<T>进行传输，那么就不需要转换。我们的项目需要转换也是有特殊的需求。不管转不转换，反正就是调用下层，下层返回一个HandleResult<T>对象，抓住这个特点，我们可以做很多事情。我们可以定义一个类，类里面Invoke有这个方法

//不需要转换的操作

　　　　　/// <summary>
        /// 调用方法  返回ClientResult<TResult/> 但是没有对Result进行映射转换
        /// </summary>
        /// <typeparam name="TResult"></typeparam>
        /// <param name="fun"></param>
        /// <returns></returns>
        public static ClientResult<TResult> Invoke<TResult>(Func<HandleResult<TResult>> fun)
        {
            var result = new ClientResult<TResult> { Success = true };
            var stopWatch = new Stopwatch();
            stopWatch.Start();
            try
            {
                HandleResult<TResult> data = fun();
                result.Success = data.Success;
                result.Message = data.Message;
                result.Result = data.Result;
            }
            catch (WebSeatException ex)
            {
                result.Success = false;
                result.Message = string.Format("{0}({1})", ex.Code.ToMessage(), ex.Description);
            }
            catch (Exception ex)
            {
                result.Success = false;
                result.Message = ex.GetMessage();
                LogHelper.Error(ex);
            }
            finally
            {
                stopWatch.Stop();
                var time = stopWatch.ElapsedMilliseconds;
                if (time > 3000)
                {
#if DEBUG
                    LogHelper.Error(new Exception(),
                        string.Format("调用方法:{0}.{1},  执行时间：{2}毫秒", fun.Method.DeclaringType, fun.Method.Name, time));
#endif
                }
                else
                {
                    LogHelper.Log(string.Format("调用方法:{0}.{1},  执行时间：{2}毫秒", fun.Method.DeclaringType, fun.Method.Name, time));
                }
            }
            return result;
        }

//需要转换的  如果有需要用Mapper做数据映射，可以给这个方法加个重载，代码如下，具体实现和上面差不多。

 /// <summary>
        /// 调用方法读取数据 并且 把 HandleResult<TGResult/>转换成 ClientResult<TResult/>
        /// </summary>
        /// <typeparam name="TGResult"></typeparam>
        /// <typeparam name="TResult"></typeparam>
        /// <param name="fun"></param>
        /// <returns></returns>
        public static ClientResult<TResult> Invoke<TGResult, TResult>(Func<HandleResult<TGResult>> fun)
        {
            var result = new ClientResult<TResult> { Success = true };
            var stopWatch = new Stopwatch();
            stopWatch.Start();
            try
            {
                HandleResult<TGResult> data = fun();
                result.Success = data.Success;
                result.Message = data.Message;
                result.Result = Mapper.Map<TGResult, TResult>(data.Result);
            }
            catch (WebSeatException ex)
            {
                result.Success = false;
                result.Message = string.Format("{0}({1})", ex.Code.ToMessage(), ex.Description);
            }
            catch (Exception ex)
            {
                result.Success = false;
                result.Message = ex.GetMessage();
                LogHelper.Error(ex);
            }
            finally
            {
                stopWatch.Stop();
                var time = stopWatch.ElapsedMilliseconds;
                if (time > 3000)
                {
#if DEBUG
                    LogHelper.Error(new Exception(),
                        string.Format("调用方法:{0}.{1},  执行时间：{2}毫秒", fun.Method.DeclaringType, fun.Method.Name, time));
#endif
                }
                else
                {
                    LogHelper.Log(string.Format("调用方法:{0}.{1},  执行时间：{2}毫秒", fun.Method.DeclaringType, fun.Method.Name, time));
                }
            }
            return result;
        }

我们可以看到，在上面的方法中，我们对调用过程做了包装，并做了一些转换，上层调用下层我们规定必须使用Invoke这个方法，相当于他是上层调用下层唯一的通道，所有的调用都要从此进过，这样设计我们就能够对所有的调用相关的记录。

上层调用下层的分几种情况，如果是WCF做服务端，使用和以下一样，我这里还是用的Controller里面的action做示例，示例代码如下：

 　　　　
　　　　public JsonResult GetGradeList()
        {
            return Json(WebExtension.Invoke(() => GradeService.GetGradeList()));
        }

        public JsonResult GetGradeBySchoolIdAndSchoolStageId(int schoolId = 0, int schoolStageId = 0)
        {
            return Json(WebExtension.Invoke(() => GradeService.GetGradeBySchoolIdAndSchoolStageId(schoolId, schoolStageId)));
        }

　　　　　public JsonResult GetAccountById(int id = 0)
        {
            return Json(WebExtension.Invoke<AccountDTO, AccountModel>(() => AccountDetailService.GetAccountById(id)), JsonRequestBehavior.AllowGet);
        }

        public JsonResult GetOneSchool()
        {
            return Json(WebExtension.Invoke<SchoolDTO, SchoolViewModel>(() => SchoolService.GetOneSchool()));
        }

 记录的日志如下，一般的调试信息记录在debug中，错误信息记录在error中，如果单个方法调用超过3秒直接记录到错误日志中。