使用动态代理记录方法执行的时间

在大型系统中，我们经常需要监视我们系统执行的性能状况，当出现性能问题时，我们要能够迅速地找到瓶颈在什么地方。在程序的层面上来说，就是看哪个方法执行所消耗的时间很长。

使用动态代理可以非常方便的记录方法执行的时间，比如，下面的截图，就是ESBasic.Emit.Aop.Interceptors.MethodTimeInterceptor截获器记录的片段：

<!--<br /><br />Code highlighting produced by Actipro CodeHighlighter (freeware)<br />http://www.CodeHighlighter.com/<br /><br />-->2009-4-1718:50:12:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗时:390ms
2009-4-1718:50:16:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时:106ms
2009-4-1718:50:23:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时:105ms
2009-4-1718:50:23:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时:105ms
2009-4-1718:50:24:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗时:386ms
2009-4-1718:50:30:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗时:387ms
2009-4-1718:50:35:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗时:377ms
2009-4-1718:50:43:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时:105ms
2009-4-1718:51:14:TY.Web.MemberInterface.IGameBenefitBL.GetMemberBenefitData方法耗时:714ms

在我们常见的三层架构中，我们可能需要记录UI层调用BL层的每个方法所执行的时间，那我们可以这样做。假设BL提供给UI访问的接口为IBL（可能有多个，如IBL1，IBL2，IBL3,......），BL通过Remoting的方式发布它的服务。

<!--<br /><br />Code highlighting produced by Actipro CodeHighlighter (freeware)<br />http://www.CodeHighlighter.com/<br /><br />-->//BL层给UI层调用的接口
publicinterfaceIBL
{
}
//BL的实现
publicclassBLObject:IBL
{
}

那么，我们让BL不直接发布实现了IBL接口的对象（BLObject），而是发布拦截了这个对象的动态代理，就像这样：

<!--<br /><br />Code highlighting produced by Actipro CodeHighlighter (freeware)<br />http://www.CodeHighlighter.com/<br /><br />-->IMethodTimeLoggerlogger=newMethodTimeLogger(newFileAgileLogger("TimeLogger.txt"),100);
IBLblObject=...; //BLObject的实例
IBLblObjectProxy=DynamicProxyFactory.CreateAopProxy<IBL>(blObject,null,newMethodTimeInterceptor(logger));

blObjectProxy即是拦截了blObject调用的动态代理，它和BLObject一样实现了IBL接口，并且将所有的调用转发给blObject，而且记录了blObject每个方法执行的时间。我们可以将blObjectProxy对象发布为Remoting，这样就可以记录下BL每个方法的执行时间了。

在上面的例子中，IMethodTimeLogger接口是用于记录时间的记录器接口，我们可以将时间记录到日志文件，当然也可以记录到数据库或其他地方，你只要实现IMethodTimeLogger接口就可以了。这里我们将时间记录到TimeLogger.txt文件，注意，MethodTimeLogger的第二个参数100，表示只记录那些执行时间超过100ms的方法调用，因为如果要记录所有的方法调用的话，在大型系统中日志可能会在很短的时间内就变得非常的庞大，这样反而不利于日志查看。

再回到上面的日志片段，我们看到，日志记录了BL接口中具体方法的调用时间，执行所消耗的时长，这样我们就可以很方便的找到性能的瓶颈是在那个方法的调用上产生的了。

上述例子中所用到的类都位于ESBasic.dll中，你可以从这里下载进行试验。ESBasic中的动态代理技术是基于Emit实现的，有兴趣的话你可以使用Reflector来查看其实现原理。

关于ESBasic中动态代理实现的更多介绍，可以参考我的这两篇文章：动态代理DynamicProxy 介绍 和 使用动态代理，提高工作效率