Today we're going to revisit the OnMethodBoundaryAspect class by building a profiler aspect to help us identify slow executing methods.
As we saw in Day 2 OnMethodBoundaryAspect has 4 methods for us to access specific points in a methods execution
- OnEntry - Before the execution of the method body
- OnExit - Always called when a method is done executing even if there was an error
- OnSuccess - Called only when a method is done executing and there were no exceptions
- OnException - Called only when a method has stopped executing due to an unhandled exception
Each of these methods provides a MethodExecutionArgs parameter that gives us access to important data.
Method Property
First and most important is the Method property. This is where all of the information about the currently executing method is held. It basically provides all of the information that a System.Reflection.MethodInfo instance would hold. In fact, MethodInfo inherits from MethodBase which can be cast as MethodInfo in case more information is needed (for instance finding the return type).
Instance Property
The Instance property holds a reference to the executing methods object instance and can be reflected to extract the details. Be careful, Instance could be null in certain cases such as when static constructors are executing.
Arguments Property
Since methods usually have arguments, we need to have access to them. MethodExecutionArgs.Arguments provides us with access to those arguments and their values. If you need specific details about the arguments you will need to reflect on them, for instance to display their field values. Otherwise, you can use ToString() to get the value as long as they are value types or types that override the ToString() method.
Exception Property
Exception is nothing more than a standard .NET exception that will contain the current unhandled exception information thrown by the executing method. The Exception property will only be set in the OnException method.
ReturnValue Property
This is self explanatory, really. You can get or set the value that the method is going to return. If you wanted to stop method execution in the OnEntry method, you can set the ReturnValue as needed and then set the FlowBehavior to return. The caller will get back the value specified in ReturnValue.
When inside of the OnExit and OnSuccess methods the ReturnValue will contain the value the method is returning. You can overwrite it or leave it as is.
FlowBehavior Property
There will be times when you need to control what a method does. FlowBehavior is an enum that can be set to control the execution of the method. FlowBehavior not as useful in aspects based on OnMethodBoundaryAspect since it only deals with the start and end of a method. We'll see more of this later when dealing with other aspect types.
As an example, think about our exception aspect we built previously. Policy could demand that a specific exception type should be logged but not rethrown. In this case you should set FlowBehavior to FlowBehavior.Return which would cause the method to return normally to the caller sending back whatever is in ReturnValue.
MethodExecutionTag Property
It can hold anything and is meant to pass state between the advices (for instance between OnEntry and OnSuccess). This is the recommended and preferred way to pass state between the advices. You might be tempted to use an aspect level variable but this approach is not thread safe or reentrant. We’ll look at uses for aspect fields another day.
Building the Profiler Aspect
If you’ve noticed while doing searches, there is a delay before the results are returned. In a small application such as our demo, we could easily eyeball the code to find the offending method. In the real world, we work on complex projects and even projects that we’re not familiar with. Having another tool in our belt can make this type of tasks much simpler to deal with.
Add a new file named ProfilerAspect.cs and add the following code
[Serializable] [ProfilerAspect(AttributeExclude = true)] public class ProfilerAspect : PostSharp.Aspects.OnMethodBoundaryAspect { public override void OnEntry(MethodExecutionArgs args) { args.MethodExecutionTag = Stopwatch.StartNew(); } public override void OnExit(MethodExecutionArgs args) { Stopwatch sw = (Stopwatch)args.MethodExecutionTag; sw.Stop(); string output = string.Format("{0} Executed in {1} seconds", args.Method.Name, sw.ElapsedMilliseconds / 1000); System.Diagnostics.Debug.WriteLine(output); } }
What we've done is set the MethodExecutionTag with a stopwatch object in OnEntry and then in OnExit we extract that same stopwatch instance from the MethodExecutionTag so we can use it to get the elapsed time it took to execute the method. Finally, we write the details of execution to the output window.
Apply the aspect at the assembly level
[assembly: ProfilerAspect()]
When you run the application you will see that every method reports 0 second execution times...until we search that is. GetByName reports 3 second execution time.
InMemoryDataStore.GetAll Executed in 0 seconds
ContactManager.UpdateContactList Executed in 0 seconds
ContactManager.ContactManager_Load Executed in 0 seconds
InMemoryDataStore.GetByName Executed in 3 seconds
ContactManager.UpdateContactList Executed in 3 seconds
ContactManager.btnSearch_Click Executed in 3 seconds
Obviously we have our culprit. We can now investigate. You’ll appreciate this exercise if you’ve ever written stop watch code to profile methods.
Conclusion
PostSharp does a great job of giving us what we need and the OnMethodBoundaryAspect class is a great starting point for implementing many cross-cutting concerns, but it certainly isn't all we have to work with as you'll see as we continue to dive into the features of PostSharp. While running the application you may have noticed that the performance is significantly slower. This is because we have not yet optimized our aspects. Don’t worry; we’ll be covering aspect optimization on another day.