在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秒直接记录到错误日志中。