Aspect-Oriented Logging Using PostSharp

Applying the magic of Aspect-Oriented Programming (AOP) for awesome logging and profiling without writing any code

  PostSharp is natural complement to Loupe. It lets you add additional logging to your applications without adding additional source code. PostSharp inserts itself in the build process and post-processes compiled assemblies adding logging code at the MSIL level.

PostSharp is an Aspect-Oriented Programming (AOP) framework that allows crosscutting requirements, such as logging, to be encapsulated in code modules called aspects. This page describes a set of PostSharp aspects we’ve written that integrate Loupe with PostSharp.

With these aspects you can declaratively add Loupe logging to your programs by simply tagging whatever methods, classes or namespaces you wish. This lets you add powerful logging to your applications without the effort, complexity or clutter of writing procedural logging code.

• [GTrace] logs entry and exit from tagged methods including appropriate message indentation.
• [GTraceField] logs every change in value of a tagged field.
• [GException] logs exceptions at the point they are raised. This is a handy safe guard to ensure that both handled and unhandled exceptions are logged by Gibraltar.
• [GTimer] lets you graph method execution time in Gibraltar providing invaluable information to identify bottlenecks and optimize performance.

Just tag your code with attributes

PostSharp weaves aspect code in MSIL form with tagged methods as a post-compile step in the build process. You can tag specific methods or use , classes, namespaces or whole assemblies with these aspects. Even better, PostSharp aspects support multicasting so that, with a single line of code, you can selectively associate an aspect with all methods that match a pattern.

Sample source code input to PostSharp

For example, by simply tagging a few methods like this…

[GTrace]
public void TraceStub()
{
    // Original Logic goes here
}
 
[GException]
public void ExceptionStub()
{
    // Original Logic goes here
}

Effective MSIL after PostSharp

…the actual MSIL code after PostSharp post-processing (simplified for clarity of explanation) is equivalent to this:

public void TraceStub()
{
    try
    {
        GTrace.OnEntry();
        // Original Logic goes here
        GTrace.OnSuccess();
    }
    finally
    {
        GTrace.OnExit();
    }
}
 
public void ExceptionStub()
{
    try
    {
        // Original Logic goes here
    }
    catch(Exception ex)
    {
        GTrace.OnException(ex);
        throw;
    }
}

Multicasting makes it even easier

Here are a few multicasting examples that hint at how easy flexible it is to associate aspects with just the methods you want, excluding those you don’t.

// Log all exceptions thrown for every method in the current assembly
[assembly: GException]
 
#if DEBUG // Only log entry/exit in DEBUG builds 
// Log entry and exit of every method with exceptions listed below
[assembly: GTrace(AttributePriority = -1)]

// Exclude constructors and a few excessively noisy classes & methods
[assembly: GTrace(AttributeTargetTypes = "*VerticalProgressBar", AttributeExclude = true)]
[assembly: GTrace(AttributeTargetMembers = ".ctor", AttributeExclude = true)]
[assembly: GTrace(AttributeTargetMembers = "ToString", AttributeExclude = true)]
[assembly: GTrace(AttributeTargetMembers = "WorkerUI_Resize", AttributeExclude = true)]

#endif 

// Monitor changes to a few specific member variables
[assembly: GTraceField(AttributeTargetTypes = "Gibraltar.TraceMonitorSamples.WorkerUI",
    AttributeTargetMembers = "m_WorkerThreadSpeed")]
 
// Measure timing of all methods with a few exceptions listed below
[assembly: GTimer(AttributePriority = -1)]

// Exclude these long-running methods of no interest
[assembly: GTimer(AttributeTargetTypes = "*MainApp", AttributeTargetMembers = ".ctor",
        AttributeExclude = true)]
    
[assembly: GTimer(AttributeTargetMembers = "regex:(Main|WorkerThread)",
        AttributeExclude = true)]
    
// Exclude everything in this low-level class that's fast and called all the time
[assembly: GTimer(AttributeTargetTypes = "*VerticalProgressBar",
        AttributeExclude = true)]

Go Deeper

To try this out yourself need three things: Loupe, PostSharp and the aspects that link them together (the Loupe Agent for PostSharp)

Follow the instructions below to use Loupe and PostSharp together:

• Download and install Loupe so you can view the log data you’ll capture.
• Add the Loupe Agent for PostSharp from NuGet. This will automatically add PostSharp as well.
• Check out the documentation for more details on how to get the most from this combo!

In a nutshell, you add a few references to your project then just tag the methods and classes you want to log. Loupe and PostSharp do the rest.  In just a few minutes, you’ll have a program that is much easier to debug and maintain.

Learn more about PostSharp

• Learn more about PostSharp
• You can also see our PostSharp Tips and Tricks