Poor man's profiler with Windsor

I generally advise to keep the IoC container out of the tests, but sometimes it is a convenient tool to have. Take for example the auto-mocking container concept. It's just too useful so I make an exception to the previous rule sometimes.

Here's another use for a container in a test: a profiler. All IoC containers have some proxying abilities (or rather, they delegate to one of the proxying libraries), which can be leveraged to build a basic profiler. A profiler is especially useful in integration tests where there's something that's taking too much time but you can't put your finger on the culprit simply because there are too many components involved.

A real-world example: an application which uses SolrNet was taking too long when getting lots of documents from Solr. There was nothing weird in Solr's log so it was a client issue. Let's profile it!

Setting up the profiler

We create a ProfilingContainer and add all the components we want to profile:

IWindsorContainer container = new ProfilingContainer(); 
container.AddComponent<ISolrDocumentResponseParser<Document>, SolrDocumentResponseParser<Document>>(); 
container.AddComponent<ISolrResponseParser<Document>, ResultsResponseParser<Document>>("resultsParser"); 
container.AddComponent<IReadOnlyMappingManager, AttributesMappingManager>(); 
container.Register(Component.For<ISolrQueryResultParser<Document>>().ImplementedBy<SolrQueryResultParser<Document>>() 
    .ServiceOverrides(ServiceOverride.ForKey("parsers").Eq(new[] { "resultsParser" }))); 
container.AddComponent<ISolrFieldParser, DefaultFieldParser>(); 
container.AddComponent<ISolrDocumentPropertyVisitor, DefaultDocumentVisitor>();

Adding code to profile

We add the code that exercises the components:

var parser = container.Resolve<ISolrQueryResultParser<Document>>(); 

for (int i = 0; i < 1000; i++) { 
    parser.Parse(responseXMLWithArrays); 
} 

Getting the actual profile data

Finally, we get the profile data:

Node<KeyValuePair<MethodInfo, TimeSpan>> rawProfile = container.GetProfile();

This returns a tree of method calls, each with its logged duration. We just want a list of aggregated durations, so first we flatten the tree:

IEnumerable<KeyValuePair<MethodInfo, TimeSpan>> profile = Flatten(rawProfile);

And now we can query and write the profile:

var q = from n in profile 
        group n.Value by n.Key into x 
        let kv = new { method = x.Key, count = x.Count(), total = x.Sum(t => t.TotalMilliseconds)} 
        orderby kv.total descending 
        select kv; 

foreach (var i in q) 
    Console.WriteLine("{0} {1}: {2} executions, {3}ms", i.method.DeclaringType, i.method, i.count, i.total); 

Which prints something like this (prettified):

Method	Executions	Total own time
AttributesMappingManager.GetFields(Type)	21000	2803.23ms
DefaultDocumentVisitor.Visit(Object, String, XmlNode)	10000	432.19ms
DefaultFieldParser.Parse(XmlNode, Type)	10000	122.77ms
SolrQueryResultParser<Document>.Parse(String)	1000	93.52ms
DefaultFieldParser.CanHandleType(Type)	10000	44.71ms
SolrDocumentResponseParser<Document>.ParseResults(XmlNode)	1000	43.11ms
ResultsResponseParser<Document>.Parse(XmlDocument, SolrQueryResults<Document>)	1000	30.28ms
DefaultFieldParser.CanHandleSolrType(String)	10000	23.78ms

 

Analyzing the profile

Well, it's obvious that AttributesMappingManager.GetFields() is to be blamed here, it's taking a lot of time... which is only logical since it uses a lot of reflection...
But wait a minute, I already thought about that when I wrote that MemoizingMappingManager (which is a memoizer decorator for the AttributesMappingManager)... only I forgot to add it to the container!

Fixing and re-running the profile

After adding the MemoizingMappingManager, the profile comes out like this:

Method	Executions	Total own time
DefaultDocumentVisitor.Visit(Object, String, XmlNode)	10000	358.64ms
SolrQueryResultParser<Document>.Parse(String)	1000	166.64ms
DefaultFieldParser.Parse(XmlNode, Type)	10000	87.13ms
MemoizingMappingManager.GetFields(Type)	21000	50.5ms
DefaultFieldParser.CanHandleType(Type)	10000	42.03ms
SolrDocumentResponseParser<Document>.ParseResults(XmlNode)	1000	34.93ms
ResultsResponseParser<Document>.Parse(XmlDocument, SolrQueryResults<Document>)	1000	30.83ms
DefaultFieldParser.CanHandleSolrType(String)	10000	22.22ms
AttributesMappingManager.GetFields(Type)	1	19.82ms

 

Conclusion

This cheap profiler has a number of caveats:

• Since it works by adding a DynamicProxy interceptor to everything, it can only profile interceptable classes and methods managed by Windsor.
• Times should be taken with a grain of salt. Based on a couple of unscientific tests, it can introduce an error of 10ms (on my machine), rendering a 10ms measured time useless. I'd only use these times for a qualitative comparison. There's a reason why there's a specific .Net profiling API.
• Multithreading: each thread will get its own interceptor, so each thread gets its own profile.
• What I just described is not really a test. There is nothing asserted, it can't pass or fail. The "test" here is just a means to run the profile. It should be [Ignore]d.

All in all, I found this to be quite useful. ProfilingContainer is just a thin wrapper around WindsorContainer that adds a ProfilerFacility, which in turn sets up a ProfilingInterceptor. So you could, for example, add the ProfilingInterceptor to your application container with a per-web-request lifestyle and code a HttpModule to profile an entire http request.

Code is here. Sample profile shown in this post is here.