Aspects for Monitoring

Monitoring applications to detect and respond to problems is a common systems requirement. Monitoring is important in all phases of an application lifecycle: development and testing (principally with logging and tracing), and load testing and production (logging, performance monitoring, exception monitoring).

Conventional programming techniques have two problems when coping with monitoring:

  1. Implementation of monitoring typically requires modifications of hundreds, possibly thousands, of classes and methods. It results in repetitive code, which is a source of defects during development and a maintenance issue later in the application lifecycle.
  2. Monitoring requirements are often different during development and testing than during production. Extensive logging may be necessary for debugging purposes, but would have a prohibitive performance cost in production. Therefore, logging code must be disabled in release builds. Although this may be easy in simplest cases (for instance by the use of the Conditional custom attribute), more complex requirements result in unreadable code, for instance if logging involves the use of try- catch-finally clauses.

In this section:

PostSharp Partners for Monitoring

Don't reinvent the wheel. Our partners deliver state-of-the-art monitoring solutions with off-the-shelf PostSharp integration. Check their offering.

Gibraltar

Gibraltar is an end-to-end solution for monitoring .NET software to improve software quality, streamline customer support and enhance user experience. A built-in PostSharp aspect library makes it easy to trace execution, profile performance and track feature usage. Gibraltar also automatically captures a wealth of additional data such as unhandled exceptions, application and assembly versions, and system performance metrics. read more

Author: Gibraltar Software. License: Commercial.

SmartInspect

The SmartInspect aspect library for PostSharp helps you instrument your code with SmartInspect log statements. SmartInspect is an advanced .NET, Java and Delphi logging tool for debugging and monitoring software applications. It helps you identify bugs, find solutions to user-reported issues and gives you a precise picture of how your software performs in different environments. read more

Author: Gurock Software. License: Commercial.

Non-Invasive Tracing & Logging

Because logging is so ubiquitous and is addressed so elegantly by aspect-oriented programming (AOP), it has become to AOP what 'Hello, World' is to procedural programming.

Getting Started

Basically, logging is nothing more than writing some text whenever a method enters or exits. In PostSharp, this can be achieved by the following piece of code:

/// <summary>
/// Aspect that, when applied on a method, emits a trace message before and
/// after the method execution.
/// </summary>
[Serializable]
public class TraceAttribute : OnMethodBoundaryAspect
{
    /// <summary>
    /// Method invoked before the execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Information about the method being executed.</param>
    public override void OnEntry( MethodExecutionArgs args )
    {
        Trace.TraceInformation( "{0}.{1}: Enter",
                                args.Method.DeclaringType.FullName, args.Method.Name );
        Trace.Indent();
    }

    /// <summary>
    /// Method invoked after successfull execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Information about the method being executed.</param>
    public override void OnSuccess( MethodExecutionArgs args )
    {
        Trace.Unindent();
        Trace.TraceInformation( "{0}.{1}: Success",
                                args.Method.DeclaringType.FullName, args.Method.Name );
    }

    /// <summary>
    /// Method invoked after failure of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Information about the method being executed.</param>
    public override void OnException( MethodExecutionArgs args )
    {
        Trace.Unindent();
        Trace.TraceInformation( "{0}.{1}: Exception {2}",
                                args.Method.DeclaringType.FullName, args.Method.Name,
                                args.Exception.Message );
    }
}

The class TraceAttribute is a custom attribute that can be used to annotate every method requiring tracing. However, in many situations, we do not want to touch the source code of target methods.

Aspects allow you to target multiple methods using a single piece of code. For instance, the following snippet applies TraceAttribute to all public methods of public types in the namespace MyNamespace:

#if DEBUG
[assembly: Trace( AttributeTargetTypes = "MyNamespace.*",
    AttributeTargetTypeAttributes = MulticastAttributes.Public,
    AttributeTargetMemberAttributes = MulticastAttributes.Public )]
#endif

Improving Runtime Performance

The preceding code was a good pedagogical example, but don't use it in production: it is inefficient. Indeed, it makes use of System.Reflection at runtime to build the method name. The following version of the aspect computes the method name at build time and stores it in a field. At runtime, the field just has to be read, and reflection is not necessary any more. 

/// <summary>
/// Aspect that, when applied on a method, emits a trace message before and
/// after the method execution.
/// </summary>
[Serializable]
public class TraceAttribute : OnMethodBoundaryAspect
{
    private string methodName;

    /// <summary>
    /// Method executed at build time. Initializes the aspect instance. After the execution
    /// of <see cref="CompileTimeInitialize"/>, the aspect is serialized as a managed 
    /// resource inside the transformed assembly, and deserialized at runtime.
    /// </summary>
    /// <param name="method">Method to which the current aspect instance 
    /// has been applied.</param>
    /// <param name="aspectInfo">Unused.</param>
    public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
    {
        this.methodName = method.DeclaringType.FullName + "." + method.Name;
    }

    /// <summary>
    /// Method invoked before the execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnEntry(MethodExecutionArgs args)
    {
        Trace.TraceInformation("{0}: Enter", this.methodName);
        Trace.Indent();
    }

    /// <summary>
    /// Method invoked after successfull execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnSuccess(MethodExecutionArgs args)
    {
        Trace.Unindent();
        Trace.TraceInformation("{0}: Success", this.methodName);
    }

    /// <summary>
    /// Method invoked after failure of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnException(MethodExecutionArgs args)
    {
        Trace.Unindent();
        Trace.TraceInformation("{0}: Exception {1}", this.methodName);
    }
}

Printing Parameter Values

You know the situation: a bug happens in production, you cannot reproduce it in development environment, and logs are useless because they don't contain the value of parameters of methods in the exception call stack. A solution may be to log the parameter values whenever an exception happens. Although this is daunting using conventional programming techniques, aspects makes it much easier.

[Serializable]
public class VerboseTraceAttribute : OnMethodBoundaryAspect
{
    private string methodName;

    /// <summary>
    /// Method executed at build time. Initializes the aspect instance. After the execution
    /// of <see cref="CompileTimeInitialize"/>, the aspect is serialized as a managed 
    /// resource inside the transformed assembly, and deserialized at runtime.
    /// </summary>
    /// <param name="method">Method to which the current aspect instance 
    /// has been applied.</param>
    /// <param name="aspectInfo">Unused.</param>
    public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
    {
        this.methodName = method.DeclaringType.FullName + "." + method.Name;
    }

    /// <summary>
    /// Method invoked before the execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnEntry(MethodExecutionArgs args)
    {
        Trace.TraceInformation("{0}: Enter", this.methodName);
        Trace.Indent();
    }

    /// <summary>
    /// Method invoked after successfull execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnSuccess(MethodExecutionArgs args)
    {
        Trace.Unindent();
        Trace.TraceInformation("{0}: Success", this.methodName);
    }

    /// <summary>
    /// Method invoked after failure of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnException(MethodExecutionArgs args)
    {
        Trace.Unindent();
    
        StringBuilder stringBuilder = new StringBuilder(1024);

        // Write the exit message.
        stringBuilder.Append(this.methodName);
        stringBuilder.Append('(');

        // Write the current instance object, unless the method
        // is static.
        object instance = args.Instance;
        if (instance != null)
        {
            stringBuilder.Append("this=");
            stringBuilder.Append(instance);
            if (args.Arguments.Count > 0)
                stringBuilder.Append("; ");
        }

        // Write the list of all arguments.
        for (int i = 0; i < args.Arguments.Count; i++)
        {
            if (i > 0)
                stringBuilder.Append(", ");
            stringBuilder.Append(args.Arguments.GetArgument(i) ?? "null");
        }

        // Write the exception message.
        stringBuilder.AppendFormat("): Exception ");
        stringBuilder.Append(args.Exception.GetType().Name);
        stringBuilder.Append(": ");
        stringBuilder.Append(args.Exception.Message);

        // Finally emit the error.
        Trace.TraceError(stringBuilder.ToString());
    }
}

Performance Counters

Instrumentation makes it possible to diagnose performance problems, which typically occur during load tests or on production where profiling utilities are not available. As a .NET developer, you can use Windows performance counters (see System.Diagnostics.PerformanceCounter) to instrument your application.

In some situations, integrating performance counters into your application can be a menial task. Suppose that you have hundreds of methods for which you have to instrument the call count and average execution time. With conventional object-oriented programming, this can easily become a nightmare. An aspect makes it much easier.

We will consider the following design: we develop a base class PerformanceCounterAttribute taking care of the initialization of the performance counter at runtime, and two concrete uses: IncrementPerformanceCounterAttribute (counts method invocations) and TimePerformanceCounterAttribute (measure the method execution time). Let's start with the abstract aspect: 

/// <summary>
/// Base class for all performance counter aspects.
/// </summary>
/// <remarks>This class takes care of the identification and initialization of the
/// performance counter. Derived class may access the performance counter at runtime 
/// on the <see cref="PerformanceCounter"/> property.</remarks>
[Serializable]
public abstract class PerformanceCounterAttribute : OnMethodBoundaryAspect
{
    // Serialized fields: set at build time, used at run time.
    private readonly string categoryName;
    private readonly string counterName;
    private string instanceName;

    // Not serialized because used at rutime only.
    [NonSerialized]
    private PerformanceCounter performanceCounter;

    // Not serialized because used at build time only.
    [NonSerialized]
    private bool includeInstanceName;

    protected PerformanceCounterAttribute(string categoryName, string counterName)
    {
        this.categoryName = categoryName;
        this.counterName = counterName;
    }

    /// <summary>
    /// Gets the performance counter (can be invoked at runtime).
    /// </summary>
    protected PerformanceCounter PerformanceCounter
    {
        get { return this.performanceCounter; }
    }

    /// <summary>
    /// Determines whether the performance counter must include an instance name.
    /// If <c>true</c>, the instance name is set to the full method name.
    /// </summary>
    public bool UseInstanceName
    {
        get { return this.includeInstanceName; }
        set { this.includeInstanceName = value; }
    }

    /// <summary>
    /// Method executed at build time. Initializes the aspect instance. After the execution
    /// of <see cref="CompileTimeInitialize"/>, the aspect is serialized as a managed 
    /// resource inside the transformed assembly, and deserialized at runtime.
    /// </summary>
    /// <param name="method">Method to which the current aspect instance 
    /// has been applied.</param>
    /// <param name="aspectInfo">Unused.</param>
    public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
    {
        if (this.includeInstanceName)
        {
            this.instanceName = method.DeclaringType.FullName + "." + method.Name;
        }
    }

    /// <summary>
    /// Method executed at run time just after the aspect is deserialized.
    /// </summary>
    /// <param name="method">>Method to which the current aspect instance 
    /// has been applied.</param>
    public override void RuntimeInitialize(MethodBase method)
    {
        this.performanceCounter = new PerformanceCounter(
            this.categoryName, this.counterName, this.instanceName, false);
    }
}

It is now easy to develop an aspect that counts the number of executions of a method:

/// <summary>
/// Aspect that, when applied on a method, increments a performance counter
/// before each execution of this method.
/// </summary>
[Serializable]
public class IncrementPerformanceCounterAttribute : PerformanceCounterAttribute
{
    private long increment = 1;

    public IncrementPerformanceCounterAttribute(string categoryName, string counterName)
        : base(categoryName, counterName)
    {
    }

    /// <summary>
    /// Gets or sets the value of which the performance counter is incremented
    /// before each execution of target method. The default value is 1.
    /// </summary>
    public long Increment
    {
        get { return this.increment; }
        set { this.increment = value; }
    }

    /// <summary>
    /// Method invoked before the execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnEntry(MethodExecutionArgs args)
    {
        this.PerformanceCounter.IncrementBy(this.increment);
        base.OnEntry(args);
    }

}

For the time-measuring aspect, we use a global Stopwatch and use the property MethodExecutionArgs.MethodExecutionTag to store the initial timer value between OnEntry and OnExit.

/// <summary>
/// Aspect that, when applied on a method, increments a performance counter
/// by the time elapsed during the execution of this method.
/// </summary>
public class TimePerformanceCounterAttribute : PerformanceCounterAttribute
{
    static readonly Stopwatch stopwatch = new Stopwatch();

    static TimePerformanceCounterAttribute()
    {
        stopwatch.Start();
    }

    public TimePerformanceCounterAttribute(string categoryName, string counterName)
        : base(categoryName, counterName)
    {
    }

    /// <summary>
    /// Method invoked before the execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnEntry(MethodExecutionArgs args)
    {
        args.MethodExecutionTag = stopwatch.ElapsedTicks;
        base.OnEntry(args);
    }

    /// <summary>
    /// Method invoked after the execution of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Unused.</param>
    public override void OnExit(MethodExecutionArgs args)
    {
        long time = stopwatch.ElapsedTicks - (long) args.MethodExecutionTag;
        this.PerformanceCounter.IncrementBy( time );
        base.OnExit(args);
    }
}

Exception Monitoring

Exception monitoring is a special case of logging. Typically, unhandled exceptions must be caught before they are allowed to crash the application or get passed to the caller. Very often, exceptions need to be wrapped before they cross the application boundary, because the exception may contain details that may unveil security leaks, making life easier for potential attackers. Therefore, exception monitoring is often part of a larger exception handling policy.

The following example illustrates an easy exception handling policy: we log the exception (to record all details) and to wrap it into an InternalException.

/// <summary>
/// Aspect that, when applied on a method, catches all its exceptions,
/// assign them a GUID, log them, and replace them by an <see cref="InternalException"/>.
/// </summary>
[Serializable]
public class ExceptionPolicyAttribute : OnExceptionAspect
{
    /// <summary>
    /// Method invoked upon failure of the method to which the current
    /// aspect is applied.
    /// </summary>
    /// <param name="args">Information about the method being executed.</param>
  public override void OnException(MethodExecutionArgs args)
    {
        Guid guid = Guid.NewGuid();

        Trace.TraceError("Exception {0} handled by ExceptionPolicyAttribute: {1}",
            guid, args.Exception.ToString());

        throw new InternalException(
            string.Format("An internal exception has occurred. Use the id {0} " +
            "for further reference to this issue.", guid));
    }
}

Summary

Monitoring provides many opportunities to use aspect-oriented programming. Indeed, tracing has been the poster child of this technology, and is often the first thing people blog about when they learn AOP. For good reasons: monitoring typically crosscuts all business functions of an application and requires menial, costly, and unmaintainable code replication. Additionally, it is often required to disable some debugging monitoring features in the release build; with aspects, this is almost trivial.