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