I have been investigating a way to include trace statements systematically throughout a very large application in .NET. I was directed to the PostSharp framework by a colleague. It looked interesting, so I did some research.
Performance
Consider the following code:
1: public class Person
2: {
3: [TracingAspect]
4: public void Save()
5: {
6: #if SkipPostSharp
7: WriteEntryMsg("Direct Person.Save");
8: #endif
9: Console.WriteLine("::Save start");
10: Thread.Sleep(2000);
11: Console.WriteLine("::Save end");
12: #if SkipPostSharp
13: WriteExitMsg("Direct Person.Save");
14: #endif
15: }
16:
17: public static void WriteEntryMsg(string source)
18: {
19: string msg = string.Format("OnEntry fired for: {0}", source);
20: writeMsg(msg);
21: }
22:
23: public static void WriteExitMsg(string source)
24: {
25: string msg = string.Format("OnExit fired for: {0}", source);
26: writeMsg(msg);
27: }
28:
29: private static void writeMsg(string msg)
30: {
31: Debug.WriteLine(msg);
32: Trace.WriteLine(msg);
33: Console.WriteLine(msg);
34: }
35: }
36:
37: [Serializable]
38: public class TracingAspect : OnMethodBoundaryAspect
39: {
40: public override void OnEntry(MethodExecutionEventArgs eventArgs)
41: {
42: Person.WriteEntryMsg("Aspect");
43: }
44:
45: public override void OnExit(MethodExecutionEventArgs eventArgs)
46: {
47: Person.WriteEntryMsg("Aspect");
48: }
49: }
50:
51: class Program
52: {
53: static void Main(string[] args)
54: {
55:
56: Stopwatch sw = new Stopwatch();
57: sw.Start();
58: try
59: {
60:
61: AopTester.Person p = new Person();
62: p.Save();
63:
64: }
65: catch (Exception ex)
66: {
67: Console.WriteLine(ex.ToString());
68: }
69: sw.Stop();
70:
71: Console.WriteLine("*~*~*~*~*~*~*~*~*~*~*~*~*~*~");
72: Console.WriteLine("Elapsed milliseconds for Main: {0:n}", sw.ElapsedMilliseconds);
73: Console.WriteLine("*~*~*~*~*~*~*~*~*~*~*~*~*~*~");
74:
75: Console.WriteLine("DONE!");
76: #if DEBUG
77: Console.ReadKey();
78: #endif
79:
80: }
81: }
Using a conditional compilation symbol, the code above either uses aspects to inject the Person.WriteEntryMsg code or calls it directly.
Without PostSharp injection, the following outputs to the screen:
OnEntry fired for: Direct Person.Save
::Save start
::Save end
OnExit fired for: Direct Person.Save
*~*~*~*~*~*~*~*~*~*~*~*~*~*~
Elapsed milliseconds for Main: 2,015.00
*~*~*~*~*~*~*~*~*~*~*~*~*~*~
DONE!
With PostSharp:
OnEntry fired for: Aspect
::Save start
::Save end
OnEntry fired for: Aspect
*~*~*~*~*~*~*~*~*~*~*~*~*~*~
Elapsed milliseconds for Main: 2,027.00
*~*~*~*~*~*~*~*~*~*~*~*~*~*~
DONE!
Results
Considering the above results, it appears that the PostSharp framework adds an additional 12 milliseconds of overhead for the same code to execute.
Injected Code
PostSharp performs IL weaving; injecting tracing and logging code into the assembly at build time. Here is an illustration of the code added by the component using our example above:
Without PostSharp
Here is the disassembled IL as shown in Reflector:
1: public class Person
2: {
3: // Methods
4: [TracingAspect]
5: public void Save()
6: {
7: WriteEntryMsg("Direct Person.Save");
8: Console.WriteLine("::Save start");
9: Thread.Sleep(0x7d0);
10: Console.WriteLine("::Save end");
11: WriteExitMsg("Direct Person.Save");
12: }
13:
14: public static void WriteEntryMsg(string source)
15: {
16: writeMsg(string.Format("OnEntry fired for: {0}", source));
17: }
18:
19: public static void WriteExitMsg(string source)
20: {
21: writeMsg(string.Format("OnExit fired for: {0}", source));
22: }
23:
24: private static void writeMsg(string msg)
25: {
26: Debug.WriteLine(msg);
27: Trace.WriteLine(msg);
28: Console.WriteLine(msg);
29: }
30: }
With PostSharp
Here is the disassembled IL as shown in Reflector:
1: public class Person
2: {
3: // Methods
4: [CompilerGenerated]
5: static Person()
6: {
7: if (!~PostSharp~Laos~Implementation.initialized)
8: {
9: LaosNotInitializedException.Throw();
10: }
11: ~PostSharp~Laos~Implementation.~targetMethod~1 = methodof(Person.Save);
12: ~PostSharp~Laos~Implementation.AopTester.TracingAspect~1.RuntimeInitialize(~PostSharp~Laos~Implementation.~targetMethod~1);
13: }
14:
15: public void Save()
16: {
17: MethodExecutionEventArgs ~laosEventArgs~1;
18: try
19: {
20: ~laosEventArgs~1 = new MethodExecutionEventArgs(~PostSharp~Laos~Implementation.~targetMethod~1, this, null);
21: ~PostSharp~Laos~Implementation.AopTester.TracingAspect~1.OnEntry(~laosEventArgs~1);
22: if (~laosEventArgs~1.FlowBehavior != FlowBehavior.Return)
23: {
24: Console.WriteLine("::Save start");
25: Thread.Sleep(0x7d0);
26: Console.WriteLine("::Save end");
27: ~PostSharp~Laos~Implementation.AopTester.TracingAspect~1.OnSuccess(~laosEventArgs~1);
28: }
29: }
30: catch (Exception ~exception~0)
31: {
32: ~laosEventArgs~1.Exception = ~exception~0;
33: ~PostSharp~Laos~Implementation.AopTester.TracingAspect~1.OnException(~laosEventArgs~1);
34: switch (~laosEventArgs~1.FlowBehavior)
35: {
36: case FlowBehavior.Continue:
37: case FlowBehavior.Return:
38: return;
39: }
40: throw;
41: }
42: finally
43: {
44: ~PostSharp~Laos~Implementation.AopTester.TracingAspect~1.OnExit(~laosEventArgs~1);
45: }
46: }
47:
48: public static void WriteEntryMsg(string source)
49: {
50: writeMsg(string.Format("OnEntry fired for: {0}", source));
51: }
52:
53: public static void WriteExitMsg(string source)
54: {
55: writeMsg(string.Format("OnExit fired for: {0}", source));
56: }
57:
58: private static void writeMsg(string msg)
59: {
60: Debug.WriteLine(msg);
61: Trace.WriteLine(msg);
62: Console.WriteLine(msg);
63: }
64: }
Results
The PostSharp framework added some nominal code for error handling and call-back methods for the aspect code.
The impact appears to be marginal. Efficiency measures are added to ensure the PostSharp objects are instantiated in a static constructor.
Posted by Brandon P Miller 