Using AOP and PostSharp to Enhance Your Code: Part B
At the last part we talked a little about post compiling, AOP and how we can use the PostSharp tool to make our code look a lot better. At this part I want to get a little more deep inside the mechanism behind this cool feature, and I'll do this by first showing another example.
The Logging Attribute
Let's say you want to create an attribute that enables you to log a method, including when you entered the method, the arguments it received and it's processing time. Sounds useful, no? Let's see how easy it is to do it with PostSharp.
First we'll create our attribute.
[global::System.AttributeUsage(AttributeTargets.All, Inherited = true, AllowMultiple = false)]
public sealed class LoggingAttribute : OnMethodBoundaryAspect
{
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{ }
public override void OnExit(MethodExecutionEventArgs eventArgs)
{ }
}
For now it does nothing, but you can see we already have some hooks we can use to log the entrance and the exit of the method. Also notice that we marked the attribute as Serilizable. It won't compile otherwise (we'll see why later on). In order to create the headers for our log messages, we'll override a different method: CompileTimeInitialize.
[Serializable]
[global::System.AttributeUsage(AttributeTargets.All, Inherited = true, AllowMultiple = false)]
public sealed class LoggingAttribute : OnMethodBoundaryAspect
{
private string _entranceMessage;
private string _exitMessage;
public override void CompileTimeInitialize(System.Reflection.MethodBase method)
{
base.CompileTimeInitialize(method);
string methodDescription = method.DeclaringType.FullName + ": " + method.Name;
_entranceMessage = "Entering " + methodDescription;
_exitMessage = "Exiting " + methodDescription;
}
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{
}
public override void OnExit(MethodExecutionEventArgs eventArgs)
{
}
}
As you can see, this method gets a MethodBase as a parameter, which supplies us with the name of the method and it's enclosing type. We use this to create both an entrance message and an exit message. As the name suggests, CompileTimeInitialize is called during compile time, so the string concatenations that go on here we'll be called only when we compile method. It hardly matters for this small example, but may hold a sigfinicant performance value for more intense calculations. Anyways, let's move on and see the completed attribute:
[Serializable]
[global::System.AttributeUsage(AttributeTargets.All, Inherited = true, AllowMultiple = false)]
public sealed class LoggingAttribute : OnMethodBoundaryAspect
{
private string _entranceMessage;
private string _exitMessage;
public override void CompileTimeInitialize(System.Reflection.MethodBase method)
{
base.CompileTimeInitialize(method);
string methodDescription = method.DeclaringType.FullName + ": " + method.Name;
_entranceMessage = "Entering " + methodDescription;
_exitMessage = "Exiting " + methodDescription;
}
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{
base.OnEntry(eventArgs);
Console.WriteLine(_entranceMessage);
object[] arguments = eventArgs.GetArguments();
if (arguments != null && arguments.Length > 0)
{
Console.WriteLine("Method arguments: ");
for (int i = 0; i < arguments.Length; i++)
{
if (i != 0) Console.Write(",");
Console.Write(arguments[i]);
}
Console.WriteLine();
}
eventArgs.MethodExecutionTag = DateTime.Now;
}
public override void OnExit(MethodExecutionEventArgs eventArgs)
{
base.OnExit(eventArgs);
Console.WriteLine(_exitMessage);
Console.WriteLine("Return value: " + (eventArgs.ReturnValue ?? "null"));
DateTime startTime = (DateTime) eventArgs.MethodExecutionTag;
TimeSpan processTime = DateTime.Now.Subtract(startTime);
Console.WriteLine("The processing of the method took " + processTime.TotalMilliseconds +
" milliseconds ");
}
}
At entry we are writing to the console (although we could use any other way of logging, of course) our entrance message, and the method arguments, if it has any. Notice that we also save the time we entered the method in the MethodExecutionTag property of the eventArgs, which allows us to save state for the method execution. In OnExit we're using this property to determine how long it took the method to run. We're also printing to screen the return value of the method (making sure that if the return value is null, we'll say so). Nice and easy.
So let's place this on a method:
public class NamesBO
{
[Logging]
public string WhatIsMyName(string firstName, string lastName)
{
Thread.Sleep(1000);
return firstName + lastName;
}
}
And now let's test this...
Great, although as you can see, I forgot to place a space between my first name and my last name. Oh well.
Digging In
Now that we've got our example working, let's see what goes on underneath. Unfortunately, Ludz' Reflector seems to have an issue with methods modified by PostSharp, and is unable to disassemble them. We'll have to brush up on our IL then. Let's look on parts of the WhatIsMyName method, using the IL DASM tool.
1 .method public hidebysig instance string
2 WhatIsMyName(string firstName,
3 string lastName) cil managed
4 {
5 ....
6 System.Reflection.MethodBase::GetMethodFromHandle(valuetype [mscorlib]
7 ...
8 IL_0038: newobj instance void [PostSharp.Laos]PostSharp.Laos.MethodExecutionEventArgs::.ctor(class [mscorlib]System.Reflection.MethodBase,
9 object,
10 object[])
11 ...
12 IL_0041: ldsfld class Common.LoggingAttribute '~PostSharp~Laos~Implementation'::'aspect~2'
13 ...
14 IL_004a: callvirt instance void [PostSharp.Laos]PostSharp.Laos.IOnMethodBoundaryAspect::OnEntry(class [PostSharp.Laos]PostSharp.Laos.MethodExecutionEventArgs)
15
16
Here we can see the parts of the injected code:
- At line 6: A call to get the method data using reflection.
- At line 8: Creation of the MethodExectutionEventArgsObject.
- At line 12: Retrieval of the attribute instance (apparently the attribute object is instanstiated once, and saved in a static field).
- At line 14: Call to the OnEntry method.
Let's continue:
1 .try
2 {
3 .try
4 {...
5 IL_0074: call void [mscorlib]System.Threading.Thread::Sleep(int32)
6 ...
7 IL_007c: call string [mscorlib]System.String::Concat(string,
8 string)
9 ...
10 } // end .try
11 catch [mscorlib]System.Exception
12 {
13 ...
14 IL_0092: ldsfld class Common.LoggingAttribute '~PostSharp~Laos~Implementation'::'aspect~2'
15 ...
16 IL_009b: callvirt instance void [PostSharp.Laos]PostSharp.Laos.IExceptionHandlerAspect::OnException(class [PostSharp.Laos]PostSharp.Laos.MethodExecutionEventArgs)
17 PostSharp.Laos.MethodExecutionEventArgs::get_ReturnValue()
18 ...
19 } // end handler
20 } // end .try
21 finally
22 {
23 ...
24 IL_00ec: callvirt instance void [PostSharp.Laos]PostSharp.Laos.IOnMethodBoundaryAspect::OnExit(class [PostSharp.Laos]PostSharp.Laos.MethodExecutionEventArgs)
25 ...
26 PostSharp.Laos.MethodExecutionEventArgs::get_ReturnValue()
27 IL_00fa: castclass [mscorlib]System.String
28 IL_00ff: stloc V_1
29 IL_0103: endfinally
30 } // end handler
31 ...
32 } // end of method NamesBO::WhatIsMyName
33
Wow, that's a big piece of code there. Well, apparently PostSharps wraps our code with some try-catch-finally blocks. It does this, obviously, in order to be able to handle cases in which the method throws an exception (we still want to log the method in this case, don't we?)
- At lines 5-7: Our string concatenation takes place (first and last name).
- In 11-20: Handling of an exception, and a call to the attribute's OnException method (we didn't use it in our example, but you can guess what it's for).
- in 21-30: We are exiting the method, we call the OnExit method, and make sure we return the ReturnValue that we got from the MethodExectutionEventArgs (which means that, yes, the attribute can change the method's return value if it wants too).
The last thing I want to show you from the IL is a piece of the assembly manifest. There it is:
.mresource private '~PostSharp~Laos~CustomAttributes~'
{
// Offset: 0x00000000 Length: 0x000001E7
}
Interesting, PostSharp appears to embed a resource in our dll. The Reflector is thankfully able to show us what's in that resource:
We can see that among other things, the string "Entering Common.NamesBO: WhatIsMyName" is embedded in the dll. That's one of the strings we saved in our CompileTimeInitialize method. That's the reason we had to mark our attribute as Serializable - so all our fields we'll be serialized in the dll's resource.
Multicasting
Lets say that our NamesBO contains tons of methods, and just now we started to use PostSharp and created our LoggingAttribute. We want to have logging for all the methods, but we really don't want to go over the gazillion methods and add the attribute to them. What shall we do, then? Well, just this:
[assembly: Logging(AttributeTargetTypes="Common.BO.*")]
This magic line will cast our attribute on all the methods in the Common.BO namespace, and we're all set.
But what if we wanted to add logging to methods that are in a dll that we don't have the source for, which we can't post compile. For example, what if we wanted to trace all our calls to the System.Collections.Generic namespace? Well, there is a solution for that too, although it will require us to rewrite our attribute, to inherit from OnInvocationAspect, as we did with the CachedAttribute in Part A. We'll call this attribute LoggingExternal. You'll notice that it's pretty similar to the Logging attribute, with the main change being that we override the OnInvocation method, which actually replaces the call to the original method.
[
[Serializable]
[global::System.AttributeUsage(AttributeTargets.All, Inherited = true, AllowMultiple = false)]
public sealed class LoggingExternalAttribute : OnMethodInvocationAspect
{
private string _entranceMessage;
private string _exitMessage;
public override void CompileTimeInitialize(System.Reflection.MethodBase method)
{
base.CompileTimeInitialize(method);
string methodDescription = method.DeclaringType.FullName + ": " + method.Name;
_entranceMessage = "Entering " + methodDescription;
_exitMessage = "Exiting " + methodDescription;
}
public void LogEntry(MethodInvocationEventArgs eventArgs)
{
Console.WriteLine(_entranceMessage);
object[] arguments = eventArgs.GetArguments();
if (arguments != null && arguments.Length > 0)
{
Console.WriteLine("Method arguments: ");
for (int i = 0; i < arguments.Length; i++)
{
if (i != 0) Console.Write(",");
Console.Write(arguments[i]);
}
Console.WriteLine();
}
}
public void LogExit(MethodInvocationEventArgs eventArgs, DateTime startTime)
{
Console.WriteLine(_exitMessage);
Console.WriteLine("Return value: " + (eventArgs.ReturnValue ?? "null"));
TimeSpan processTime = DateTime.Now.Subtract(startTime);
Console.WriteLine("The processing of the method took " + processTime.TotalMilliseconds +
" milliseconds ");
}
public override void OnInvocation(MethodInvocationEventArgs eventArgs)
{
LogEntry(eventArgs);
DateTime startTime = DateTime.Now;
eventArgs.Delegate.DynamicInvoke(eventArgs.GetArguments());
LogExit(eventArgs, startTime);
}
}
Any call to a method that this attribute is placed upon, will be replaced with a call to a new method that is wrapped with our logging code. That means, that unlike attributes that inherit from OnMethodBoundaryAspect, if you want an attribute that inherits from OnInvocationAspect to work, you have to post-compile the assembly that calls the method, and not the assembly in which the method resides. A common pitfall (well, at least I fell in it) would be to post-compile only the assembly with our BO methods, and then not understand why your OnInvocationAspect-inheriting (such as caching) attributes don't work.
After we create the attribute, we'll apply it attribute as follows:
[assembly: LoggingExternal(AttributeTargetAssemblies = "mscorlib",
AttributeTargetTypes = "System.Collections.Generic.*")]
The only problem with this code is, well, that it doesn't work. It worked for the System.Threading namespace, but it doesn't work for this namespace, and it doesn't even compile for some namespaces I use.
As you can tell, the PostSharp framework is not stable enough at the moment - In one case compiling my code caused my Visual Studio to crash. For now PostSharp is still in its beta stage, so the bugs can be understood.
Conclusion
AOP with post compiling has many advantages: clearer code, allows you to avoid duplication, and easily integrated into existing code. Also, the compile-time weaving of the code ensures pretty good performance. Of course, there are some disadvantages as well: Unexpected behavior might arise in some situations (attributes on attributes? Recursion?) and the attributes should be written very carefully, especially if they're multicasted on classes or assemblies. Also, you have to post-compile your code which makes the compilation stage a bit longer.
Still, I feel the advantages are greater than the disadvantages. Although I believe it's not stable enough at the moment to be integrated into production code, the PostSharp framework is a great one for this purpose, and I suggest that you give it a shot.
I will conclude with a question for you: remember the CachedAttribute from Part A? Well, I can only pass it a constant Cache key, since that's the only kind of parameter I can pass to an attribute. Usually, that's not good enough for cache keys (they tend to depend on the method's arguments). Any idea how can I improve on this behavior? I thought of several solutions, but none of them was solid enough. Your advice will be greatly appreciated :)