Time to log method execution using dynamic proxy

In large systems, we often need to monitor the performance of our systems, and when performance problems arise, we need to be able to quickly find where the bottlenecks are. At the level of the program, it takes a long time to see which method is being executed.

Using dynamic proxies makes it easy to record how long a method executes, such as the screenshot below, which is a fragment of the ESBasic.Emit.Aop.Interceptors.MethodTimeInterceptor Interceptor record:

2009-4-17　 18:50:12:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗 时:390ms
2009-4-17　18:50:16:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时 :106ms
2009-4-17　18:50:23:TY.Web.MemberInterface.IMemberBL.GetOne方法耗 时:105ms
2009-4-17　18:50:23:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时 :105ms
2009-4-17　 18:50:24:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗 时:386ms
2009-4-17　 18:50:30:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗 时:387ms
2009-4-17　 18:50:35:TY.Web.AgentInterface.IGameRecordDetailBL.GetPaginationData方法耗 时:377ms
2009-4-17　18:50:43:TY.Web.MemberInterface.IMemberBL.GetOne方法耗时 :105ms
2009-4-17　 18:51:14:TY.Web.MemberInterface.IGameBenefitBL.GetMemberBenefitData方法耗 时:714ms

In our common three-tier architecture, we may need to record the time that each method of the UI layer invokes the BL layer, so we can do so. Suppose BL provides UI access to the interface as IBL (there may be multiple, such as IBL1,IBL2, IBL3,...... , BL publishes its services in a remoting way.

//BL层给UI层调用的接口
public　interface　IBL
{
}
//BL的实现
public　class　BLObject　:　IBL
{
}

So, we let BL not directly publish objects that implement the IBL interface (Blobject), but instead publish a dynamic proxy that intercepts the object, like this:

IMethodTimeLogger　logger　=　new　MethodTimeLogger(new　 FileAgileLogger("TimeLogger.txt")　,100);
IBL　blObject　=　...; //BLObject　的实例
IBL　blObjectProxy　=　 DynamicProxyFactory.CreateAopProxy<IBL>(blObject,　null,　new　 MethodTimeInterceptor(logger));

Blobjectproxy is the dynamic proxy that intercepts the Blobject call, implements the Ibl interface like Blobject, and sends all calls to Blobject, and records blobject the time each method executes. We can publish the Blobjectproxy object as a remoting so that we can record the execution time for each of the BL methods.

In the example above, the Imethodtimelogger interface is the logger interface for recording time, and we can log the time to the logs, and of course, to the database or other places, and you can just implement the Imethodtimelogger interface. Here we log the time to the TimeLogger.txt file, noting that Methodtimelogger's second argument, 100, records only those method calls that execute longer than 100ms, because if all the method calls are to be logged, In large systems, logs can become very large in a very short period of time, which is detrimental to log viewing.

Back to the log fragment above, we see that the log records the BL interface specific methods of the call time, the execution of the length of time, so that we can easily find the bottleneck of the performance of the method is generated on the call.

The classes used in the above examples are located in ESBasic.dll, and you can download them for testing. Esbasic Dynamic Agent technology is based on emit implementation, you can use reflector to view the implementation of the principle.

Annex to this article