Coverage
External Method Calls
To make the profiler even more useful, the latest experimental builds now show external calls. External in the case of the profile really means anything not in your solution.
This approach lets you focus on your code, and see at least one more level into referenced libraries as well as the .NET BCL. It keeps performance high by not deeply tracing into assemblies that are part of the framework that you can’t really modify. This is a performance boosting compromise with the goal of letting you pinpoint parts of your code to tune, without cluttering up your view with a lot of .NET framework internal call stacks.
External methods have a little arrow over the icon, and are grayed out indicating they aren’t in your solution … 
Remember to get tracing, you’ll need to enable coverage (TestMatrix | Collect Coverage Data)
You can get this feature from the (Experimental) updates starting… now!
| Permalink | Comments[0] |
Profiling and Tracing
We’ve been working on our profiling and tracing system rather a lot in this release. The main innovation being a system of instrumentation that doesn’t require and C++, or COM, or even a profiler DLL. One of the benefits of this new approach is sheer speed at runtime and the ability to collect some really clever data during the test runs.
The most exciting thing is the Call Trace. When you are running with coverage enabled (TestMatrix | Collect Coverage Data), this call trace is populated along with the line level code coverage.
Think of this as showing you the Call Stack that you see while debugging, but after your tests are finished. This lets you review what was called, which can often be surprising to see just how many methods are involved in a test case.
This also lest you see the time and percentages of time in a method, separating out the actual clock time (Time in Method) from the CPU elapsed time (CPU in Method). Gaps in those two numbers indicate some kind of block or wait, such as I/O, Sleep, or a database call.
One thing to keep in mind, in order to be very fast, and to focus on code you can really do something about, the trace only collects data from your classes and methods, not from the base class library. Very specifically, the times for calls nested ‘under’ another call don’t sum up when you call out to the framework as those methods just aren’t in the call trace shown.
Coming soon on the online updates, we’re planning on enhancing this feature with some additional data:
- Calls out the framework from your methods, one level deep so it stays fast but so that the times ‘add up’
- Allocations of your solution’s objects, count and size - but not cluttering up the data with huge numbers of allocations of string, which is the usual problem with memory profiling.
- File, Network, and Registry I/O similar to procmon/filemon/regmon, but inline in the call trace
- Exceptional Exits - marking on the call trace when a method exited via a a thrown exception rather than returning normally
| Permalink | Comments[0] |
Tracking Exceptions while Testing
Tracking exceptions up the Call Trace lets you see where a test failure starts and to visually see how far an exception ‘leaks’ up your call stack before being handled.
The little 
indicates which calls exited via an exception, as opposed to exiting normally out the bottom of the function, or through a return.
You can double click on any call in the Trace and navigate there in the editor. And — you’ll see the error fingers in the gutter if this exception exited all the way out of your test case.
You can right click on the fingers and navigate up and down the exception stack trace. This feature is available even without profiling being on, as it intercepts exceptions coming out of the test engines and saves that metadata along with the test. Very handy for tracking down why a test failed.
| Permalink | Comments[0] |
Punishing Test Coverage
Looking around for something complicated to test that folks actually use, I decided to pick on Lucene.NET. My idea was to make sure the code coverage works well on what is a complex piece of software with some really complex tests – and that it isn’t so painfully slow that nobody would ever actually use it.
I ran the tests in Lucene 1.9rc1. After a little bit of setup, and changing the NUnit references to 2.4 using the Fix NUnit References Option in the Test Explorer I ran the entire solution’s Lucene Test solution’s test using the TestExplorer. 301 tests with coverage ran in 3 minutes 9 seconds. There were a few failures in there – looks like the Lucene test run at least a few web connections that I didn’t set up my local IIS to respond:
As a comparison, I ran again with coverage disabled, I just hit the toggle button in the Test Explorer. 2 minutes 8 seconds.
Coverage does have some overhead since it computes activity on each individual line, but not an overwhelming overhead. I’ve had profiler/coverage experiences in the past that have 400% to 800% overhead – this one is just 50%.
| Permalink | Comments[0] |
