A friend of mine pointed me in the direction of a cool library for Aspect Oriented Programming called PostSharp the other day. I'd read about AOP in the past, but always had so much going on that it slipped my mind to look further into it. But, his excitement rubbed off on me and it wasn't long before I thought of a way I could use it. I'd been wanting to set up logging on a site I've been working on so that I could collect data for a while and report on it to see which controller methods are running the slowest. Not a permanent solution, just a way to gather data for a while to analyze it and identify any pain points I may have missed. Using PostSharp I can do it without littering too much logging code throughout the controllers themselves (all they would need is an attribute).

First thing we need to do is create a table to log to. Something like this:

The only interesting thing here is the "ExecutionTime" column. I added this because in this case I am logging to MySQL, and MySQL doesn't store the millisecond portion of Date/Times. Seems it would be easier anyway to just log the time rather than try to connect start and finish entries (you could also do it in a single entry, as shown here). The reason I didn't do this is because I wanted to be able to split the table into 3 (start, finish, and exception entries) to get as good an idea as I could what is happening at any given time.

Another thing to note here is that I added a column for parameter name/value combinations and the method name. log4net has a built-in conversion pattern for determining the method name, but it will not work for me because I plan to wrap log4net in a separate static helper class, in case I ever want to change the logging solution behind the scenes. I also read on log4net's Pattern Layout docs that getting any kind of information about the caller from log4net is very slow, because it generates a call stack to read the information from. That is one hell of a warning, they might as well just put police tape around those methods. So I will take my chances getting this info from PostSharp!

Next is to configure log4net. Added an xml file called log4net.config to the top-level directory in the project. Something like this ought to do:

Nothing really special there, except for the additional parameters we added that I didn't see on most of the vanilla demos. One thing to note is the conversionPattern we used for the custom properties, "%property{PROPERTY_NAME}" as it can be very handy if you want to set custom parameters. There's also a special "ErrorLog" that writes to a flat file without using a buffer, for errors only. This is so that if there is a fatal error in the application, the exceptions leading up to it are not lost. Onward. Next thing we need to do is ensure that log4net is configured when we start up the application. There are two ways to do this:

I first used AssemblyInfo.cs like so:

But found I could also use the Application_start method like this:

I have not yet decided which I like better, but I lean towards the second method because the first just feels a bit dirty. So feel free to pick the one you like best.

Now that this is done, the fun can begin. First thing I did was set up a little helper class, so that I don't have calls to log4net all over the place. Besides returning a log4net.ILog to be used in writing entries, this class will have a few methods to use to Add/Remove parameters from the ThreadContext's Properties and NDC Stack. This class will look like this:

Ok so now we know how we are going to do the logging. Now, time to go through and add calls to this logging code throughout our application right? Not exactly. Lets take a look how post sharp comes in. We'll want to extend the class "OnMethodBoundaryAspect" found in PostSharp.Laos. Use of this class will allow us to weave code into our application at compile time that will execute at various points during method execution (if the class has been tagged with the attribute we are about to create). For this exercise we are concerned with overriding the OnEntry, OnExit, and OnException methods. Their purposes ought to be pretty straight forward. I also added a method to take the method's parameter values and build it into a string like "[param1 = A][param2 = B]". The code for this looks like so:

Pretty simple, considering what it does. Now that we've gone through all this effort to set things up, we can see where the magic happens. It seems like a lot of work, but this is where we get the payoff. Find a controller in your project, such as the default home controller. And just add your attribute to it:

Now, the "[Loggable]" attribute is all that you need to add to any class that you want logging to take place on the three method boundaries that we wrote code for (there may be some limitations, but I'm not aware of them yet). You can add it on a method-by-method basis as well. If you want to stop logging a certain class/method, just remove the attribute. Its' really that easy.

I'm sure I will find some problems with this approach eventually (first try and all), and I will update with those as I find them. Or if anything is immediately apparent, please point it out in the comments!

Sorry this post was so heavy on the code, I just thought it was really cool and wanted to share. Hopefully it gives you your own ideas for ways to use the PostSharp library.

Have fun!