-
I created an IDisposable object that log the execution time on Dispose.
-
Then, I created a RealProxy that uses this object to log the time of any method call of my business class
-
My business class uses async methods, which then leave the using statement before completion of the task, and then log wrong execution time.
Here's my code:
/// <summary>
/// Logging proxy with stopwatch
/// </summary>
/// <typeparam name="T"></typeparam>
public sealed class LoggingProxy<T> : RealProxy// where T : MarshalByRefObject
{
private ILog _logger;
private readonly T _instance;
private LoggingProxy(T instance, ILog logger)
: base(typeof(T))
{
_logger = logger;
_instance = instance;
}
/// <summary>
/// Create the Transparent proy for T
/// </summary>
/// <param name="type">An implementation type of T</param>
/// <retus>T instance</retus>
public static T Create(ILog logger)
{
logger.DebugFormat("[{0}] Instantiate {1}", "LoggingProxy", typeof(T).Name);
var instance = (T)Activator.CreateInstance(typeof(T), logger);
//retu the proxy with execution timing if debug enable in logger
if (logger.IsDebugEnabled)
retu (T)new LoggingProxy<T>(instance, logger).GetTransparentProxy();
else
retu instance;
}
/// <summary>
/// Invoke the logging method using Stopwatch to log execution time
/// </summary>
/// <param name="msg"></param>
/// <retus></retus>
public override IMessage Invoke(IMessage msg)
{
var methodCall = (IMethodCallMessage)msg;
var method = (MethodInfo)methodCall.MethodBase;
string methodName = method.Name;
string className = method.DeclaringType.Name;
//retu directly methods inherited from Object
if (method.DeclaringType.Name.Equals("Object"))
{
var result = method.Invoke(_instance, methodCall.Args);
retu new RetuMessage(result, null, 0, methodCall.LogicalCallContext, methodCall);
}
using (var logContext = _logger.DebugTiming("[{0}] Execution time for {1}", className, methodName))
{
_logger.DebugFormat("[{0}] Call method {1}", className, methodName);
//execute the method
//var result = method.Invoke(_instance, methodCall.Args);
object[] arg = methodCall.Args.Clone() as object[];
var result = method.Invoke(_instance, arg);
//wait the task ends before log the timing
if (result is Task)
(result as Task).Wait();
retu new RetuMessage(result, arg, 0, methodCall.LogicalCallContext, methodCall);
}
}
The _logger.DebugTiming method start a stopwatch tand log it on Dispose. The only way I found to make it work with async methods, is to use that line:
//wait the task ends before log the timing
if (result is Task)
(result as Task).Wait();
But I just have the feeling that I break all the benefits of async methods by doing that.
-> If you have a suggestion about how to make a proper implementation
-> Any idea of the real impact of calling wait() on the proxy ?
Cheers
