Unusual coverage in VB.NET

Recently a user posted on StackOverflow on why he was seeing unusual coverage results in VB.NET with MSTEST and Visual Studio. The the question already had answers that helped the questioner but I decided to delve a little deeper and find out why the solution proposed worked.

The issue was that in his code sample the End Try was not being shown as covered even though he had exercised the Try and the Catch parts of his code.

First I broke his sample down into something simpler and I have highlighted the offending line.

 07  Function Method() As String  
 08    Try  
 09      Return ""  
 10    Catch ex As Exception  
 11      Return ""  
 12    End Try
 13  End Function  

In debug we can extract the following sequence points (I am, obviously, using OpenCover for this.)

<SequencePoints>  
  <SequencePoint offset="0" ordinal="0" uspid="261" vc="0" ec="32" el="7" sc="5" sl="7"/>  
  <SequencePoint offset="1" ordinal="1" uspid="262" vc="0" ec="12" el="8" sc="9" sl="8"/>  
  <SequencePoint offset="2" ordinal="2" uspid="263" vc="0" ec="22" el="9" sc="13" sl="9"/>  
  <SequencePoint offset="19" ordinal="3" uspid="264" vc="0" ec="30" el="10" sc="9" sl="10"/>  
  <SequencePoint offset="20" ordinal="4" uspid="265" vc="0" ec="22" el="11" sc="13" sl="11"/>  
  <SequencePoint offset="40" ordinal="5" uspid="266" vc="0" ec="16" el="12" sc="9" sl="12"/>  
  <SequencePoint offset="41" ordinal="6" uspid="267" vc="0" ec="17" el="13" sc="5" sl="13"/>  
</SequencePoints>  

(where sl = start line, el = end line, sc = start column, ec = end column and offset = IL offset in decimal)

However these only make sense when you look at the IL...

.method public static
    string Method () cil managed
{
    // Method begins at RVA 0x272c
    // Code size 43 (0x2b)
    .maxstack 2
    .locals init (
        [0] string Method,
        [1] class [mscorlib]System.Exception ex
    )

    IL_0000: nop
    IL_0001: nop
    .try
    {
        IL_0002: ldstr ""
        IL_0007: stloc.0
        IL_0008: leave.s IL_0029

        IL_000a: leave.s IL_0028
    } // end .try
    catch [mscorlib]System.Exception
    {
        IL_000c: dup
        IL_000d: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::SetProjectError(class [mscorlib]System.Exception)
        IL_0012: stloc.1
        IL_0013: nop
        IL_0014: ldstr ""
        IL_0019: stloc.0
        IL_001a: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::ClearProjectError()
        IL_001f: leave.s IL_0029

        IL_0021: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::ClearProjectError()
        IL_0026: leave.s IL_0028
    } // end handler

    IL_0028: nop

    IL_0029: ldloc.0
    IL_002a: ret
} // end of method Module1::Method

Now as you can see the End Try line that is causing concern would only be marked as hit (assuming they are using similar instrumentation to OpenCover) if the code reached IL instruction at offset 40 (IL_0028) however when one looks at the IL produced it is not possible to see how you would ever reach that instruction due to the odd IL produced (leave.s is a small jump like instruction that is used to exit try/catch/finally blocks) and if you follow the code you see that you will always reach a leave.s that jumps to IL_0029 first.

In release the IL changes to something more like what I was expecting beforehand and it has no unusual extra IL...

.method public static
    string Method () cil managed
{
    // Method begins at RVA 0x2274
    // Code size 30 (0x1e)
    .maxstack 2
    .locals init (
        [0] string Method,
        [1] class [mscorlib]System.Exception ex
    )

    .try
    {
        IL_0000: ldstr ""
        IL_0005: stloc.0
        IL_0006: leave.s IL_001c
    } // end .try
    catch [mscorlib]System.Exception
    {
        IL_0008: dup
        IL_0009: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::SetProjectError(class [mscorlib]System.Exception)
        IL_000e: stloc.1
        IL_000f: ldstr ""
        IL_0014: stloc.0
        IL_0015: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::ClearProjectError()
        IL_001a: leave.s IL_001c
    } // end handler

    IL_001c: ldloc.0
    IL_001d: ret
} // end of method Module1::Method

but so do the sequence points...

<SequencePoints>
  <SequencePoint offset="0" ordinal="0" uspid="33" vc="0" ec="22" el="9" sc="13" sl="9"/>
  <SequencePoint offset="15" ordinal="1" uspid="34" vc="0" ec="22" el="11" sc="13" sl="11"/>
  <SequencePoint offset="28" ordinal="2" uspid="35" vc="0" ec="17" el="13" sc="5" sl="13"/>
</SequencePoints>

So now one will never see your try/catch lines marked covered, so this is not helpful.

So lets try changing your code as suggested and go back to debug (because that is where you will be running coverage from usually.)

15   Function Method2() As String
16        Dim x As String
17        Try
18            x = ""
19        Catch ex As Exception
20            x = ""
21        End Try
22        Return x
23    End Function

Again we look at the sequence points...

<SequencePoints>
  <SequencePoint offset="0" ordinal="0" uspid="268" vc="0" ec="33" el="15" sc="5" sl="15"/>
  <SequencePoint offset="1" ordinal="1" uspid="269" vc="0" ec="12" el="17" sc="9" sl="17"/>
  <SequencePoint offset="2" ordinal="2" uspid="270" vc="0" ec="19" el="18" sc="13" sl="18"/>
  <SequencePoint offset="17" ordinal="3" uspid="271" vc="0" ec="30" el="19" sc="9" sl="19"/>
  <SequencePoint offset="18" ordinal="4" uspid="272" vc="0" ec="19" el="20" sc="13" sl="20"/>
  <SequencePoint offset="31" ordinal="5" uspid="273" vc="0" ec="16" el="21" sc="9" sl="21"/>
  <SequencePoint offset="32" ordinal="6" uspid="274" vc="0" ec="17" el="22" sc="9" sl="22"/>
  <SequencePoint offset="36" ordinal="7" uspid="275" vc="0" ec="17" el="23" sc="5" sl="23"/>
</SequencePoints>

and the IL...

.method public static
    string Method2 () cil managed
{
    // Method begins at RVA 0x282c
    // Code size 38 (0x26)
    .maxstack 2
    .locals init (
        [0] string Method2,
        [1] string x,
        [2] class [mscorlib]System.Exception ex
    )

    IL_0000: nop
    IL_0001: nop
    .try
    {
        IL_0002: ldstr ""
        IL_0007: stloc.1
        IL_0008: leave.s IL_001f
    } // end .try
    catch [mscorlib]System.Exception
    {
        IL_000a: dup
        IL_000b: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::SetProjectError(class [mscorlib]System.Exception)
        IL_0010: stloc.2
        IL_0011: nop
        IL_0012: ldstr ""
        IL_0017: stloc.1
        IL_0018: call void [Microsoft.VisualBasic]Microsoft.VisualBasic.CompilerServices.ProjectData::ClearProjectError()
        IL_001d: leave.s IL_001f
    } // end handler

    IL_001f: nop
    IL_0020: ldloc.1
    IL_0021: stloc.0
    IL_0022: br.s IL_0024

    IL_0024: ldloc.0
    IL_0025: ret
} // end of method Module1::Method2

So for the End Try to be covered we need line 21 to be hit and that is offset 31 (IL_001F) and as it can be seen both leave.s instructions jump to that point so now that line will be marked as covered.

Adding OpenCover to TeamCity

Adding OpenCover to the latest version of TeamCity (6.5) couldn't be easier however if you need help follow these simple steps.

1) Download and install OpenCover
2) Download and install ReportGenerator (actually unzip)
3) Register the OpenCover profiler DLLs using the regsvr32 utility

regsvr32 /s x86\OpenCover.Profiler.dll
regsvr32 /s x64\OpenCover.Profiler.dll


4) Using TeamCity add a new Build Step to your configuration
5) Choose Command Line as the runner type then choose Custom Script for the Run option.
6) Now all is needed is to set up the command to run the profiler against your tests e.g. for OpenCover the working directory is set to main\bin\debug and so we have

"%env.ProgramFiles(x86)%\opencover\opencover.console.exe" "-target:..\..\..\tools\NUnit-2.5.10.11092\bin\net-2.0\nunit-console-x86.exe" -targetargs:"OpenCover.Test.dll /noshadow" -filter:"+[Open*]* -[OpenCover.T*]*" "-output:..\..\..\opencovertests.xml"
"%env.ProgramFiles(x86)%\ReportGenerator\bin\ReportGenerator.exe" ..\..\..\opencovertests.xml ..\..\..\coverage

7) Finally setup the artifacts so that you can view the results in TeamCity e.g.

%teamcity.build.workingDir%\opencovertests.xml
%teamcity.build.workingDir%\coverage\**\*.*


And there you have it, OpenCover running under TeamCity and visual reports provided by ReportGenerator. I am sure you will find ways to improve upon this for your own builds.

The problem with sequence coverage. (part 2)

Previously I mentioned why just relying on sequence coverage is not a good idea as it is possible to have 100% sequence coverage but not 100% code coverage. However I only described a scenario that used a branch that had 2 paths i.e. the most common form of the conditional branches, but there is one other member of the conditional branch family that exists in IL and that is the switch instruction; this instruction can have many paths. This time I am using the code from the Newtonsoft.Json library because a) it has tests and b) it is very well covered at 83% sequence coverage, but only 72% (by my calculations) branch coverage. The subject of this investigation is BsonReader::ReadType(BsonType) this method has a very large switch statement, that actually is defined as a switch statement in IL, with a default and several fall-throughs; a fall-through is where two or more case statements call the same code. The method itself has 98% sequence coverage and 82% branch coverage; the only code that is uncovered is the handler for the default: path.

which is not unexpected as it is a handler for an Enum which should not be set to any value that is not part of the allowed values. Looking at the branch coverage report we have the following results (the switch instruction we are interested in is at IL offset 8.

Now the first path (0) is unvisited, but we knew that, so the next unvisited branch is #14 and the next is #17; luckily for us the enum in question that is used by the switch instruction is well defined.

And as such we can thus deduce that the method is never called during testing with the values Symbol and TimeStamp but the code that they would call is covered; in fact we can see from the code that both these enum values are part of the switch/case statement and are part of fall-throughs. So again we see how branch coverage helps identify 'potential' issues and test candidates.

The problem with sequence coverage.

Sequence coverage is probably the simplest coverage metric, the information is packaged in PDB files and can be read using tools like Mono.Cecil, but just because a method has 100% sequence coverage does not mean you have 100% code coverage.

I'll use an example from OpenCover's own dogfood tests to demonstrate what I mean. Here is a method which shows that it has 100% coverage (sequence point that is).

However I see an issue and that is that on line 101 there is a condition, i.e. a branch, and yet if the visit count is 1 then there is no possibility that both paths for that branch could have been tested. We can therefore infer that even if we had 10000 visits there is no guarantee that every path would be covered even in such a simple method.

Looking at the OpenCover results from which the coverage report was generated. We get

We can see that each sequence point has been visited once, however the branch coverage shows that only one of the paths for the condition we have identified had been visited (in this case it is the true path); which is good as that is what we deduced.

So if you are using code coverage tools do NOT just rely on sequence point coverage alone to determine how well covered your code is. Luckily OpenCover now, as of 25th Aug 2011, supports branch coverage and ReportGenerator 1.2 displays most of the information to help you identify possible coverage mismatches.

OpenCover Performance Impact (part 2)

I think I now have a handle on why I was getting the results I earlier reported i.e. OpenCover and PartCover were not some magical performance boosters that added Go Faster stripes to your code.

After a heads up by leppie and his investigations of using OpenCover on his IronScheme project I realised that I needed to spend some time on optimizing how I get data from the profiler and aggregate it into the report. In case you are wondering IronScheme test that took just shy of 1 minute to run on my machine took over 60mins when running under the profiler, Ouch!

The problem

First of all I should explain what sort of data OpenCover gathers (and why) and then I can describe what I did to improve performance. OpenCover records each visit to a sequence point and stores these visits into shared memory; I did it this way as I am hoping to be able to use the order of visits for some form of path coverage analysis at a later date. After 8000 visits it informs the host process that there is a block ready for processing. The host takes this block, makes a copy, releases the shared memory back to the profiler and then processes the data. After processing the data the hosts then waits for the next message. It was this latter stage that was the bottleneck as the host was spending too much time aggregating the data that the profiler was already ready with the next 8000 points.

An (interim) solution

I say interim solution as I am not finished with performance improvements yet but decided that what I had implemented so far was okay for release.

First I looked at how the results were being aggregated and noticed that a lot of the time was being spent looking up the sequence points so that the visit count could be updated, I switched this to a list and mapped the visit count data to the model at the end of the profiling run. This helped but only by bringing the profiling run down to ~40mins.

I realised that I just had to get the data out of the way quickly and process it at a later date, so I added a processing thread and a ConcurrentQueue. This was an interesting turn of events as the target process now finished in 4 mins but the host took nearly 40 mins to process the data and the memory usage went up to 2.5GB and a backlog of 40K messages. Hmmm....

After some toying, whilst looking for inspiration, I noticed that the marshaling of the structure (2 integers) was where most of the time was spent. I switched this to using BitConvertor, which also meant that I could avoid the memory pinning required by the marshaling. Now the target process still ran in just under 4 mins but the backlog very rarely reached 20 messages and memory usage stayed at a comfortable level (<100MB) and the results were ready virtually as soon as the target process had closed. I also upped the number of visit points per packet to 16000, but this didn't show any noticeable improvement in performance.

I decided this was enough for now and released a version of the profiler.

But what about the earlier results?

Those earlier results though were still are cause for thought. Why should the OpenCover dogfood tests be faster but the ironscheme test be so much slower. Well the IronScheme tests were doing a lot of loops and were running parts of the code many 1000's of times whereas the dogfood tests were unit tests and the code was only being run several times before moving onto the next test fixture and next section of code. I am now thinking that the issue is due to the optimization that is normally performed by the JIT compiler, but is turned off by the profiler i.e. when running the tests (without profiler) the JIT compiler spends time optimizing the code but the time spent is not recovered as the code is not run enough times to get a net gain, compared to when the JIT compiler just compiles the non-optimised modified code that the profiler produces.

So in conclusion you may see some speed improvements if running tests where your code is only visited a few times but if you are doing intensive execution of code then don't be surprised if the performance is degraded.

OpenCover Performance Impact

So how does OpenCover's profiling impact your testing. The best way is to get some figures so that you can judge for yourself.

I decided to use OpenCover's own tests and use the timing value produced by Nunit itself; just like I'd expect any user who is trying to determine impact I suppose. I've also added the results from PartCover for comparison. Before I took any numbers I (warmed) the code by running the code several times beforehand.

	Nunit32	Nunit32 (OpenCover)	Nunit32 (PartCover)	Nunit64	Nunit64 (OpenCover)
	2.643	2.691	2.639	4.544	3.807
	2.629	2.69	2.611	4.426	3.753
	2.642	2.638	2.612	4.46	4.036
Average	2.638	2.673	2.621	4.477	3.865

I don't know how to interpret these results as they don't make much sense, OpenCover seemed to add on average 1.3% to the total time (which I'd expect), whereas PartCover appears to make the code go faster by 0.64%. I can't explain why the results for 64 bit seem to show that OpenCover improves performance by 13.6%.

I tried to come up with a number of reasons for the above but the results I keep getting are reasonably consistent, so I decided to post them anyway and perhaps someone else will be able to tell me what is happening.

Questions about open source and liability in the workplace

Last weekend I attended DDDSydney and one of the most interesting sessions was a panel session about Microsoft and Opensource (Open Source & Microsoft Ecosystem); though as these things go, it went quickly off(ish) topic as expected by the panelists whom I'll refer to as the crazy drupal girl and the 3 stooges (honestly no offence folks, it was highly entertaining).

However it got me thinking about the number of projects where I come have across an unusual bit of open source software that has some use (but has not found a niche or has since been surpassed) and I find that this was introduced by a developer as it was their pet open source project. Now the first question is "what is the liability under this scenario?"

Did the developer ask first as they should before using any open source software on a project? If so then the company accepted the situation but what happens if they did not (or what not made aware) are they still liable or is the developer liable? I assume it would be the company as they should be having some sort of oversight but for small overworked teams where process may not be as strong this may get overlooked.

The other issue is what happens if you introduce your pet open source software project and then you leave, who supports it? How do you separate the open source project needs and the day-job, when they are so intermingled? Does the remaining team support it, do they have the skills? What happens if the parting was acrimonious in nature then they, the team, raised a legitimate issue would you fix it, or leave them to stew?

I don't have answers to the above, I did title this "Questions about...", that can be applied universally the answer to most I suppose is "it depends". Each situation will be different I suspect but I think these type of questions should be asked by any company hoping to use open source software and developers wishing to introduce it, whether that are contributors or not.

Personally I have decided to NOT introduce the open source software I develop into my workplace, yes they could use it and find it useful but they can also afford commercial alternatives. If someone else suggested it, I'd have to make sure there was an agreement should an issue arise that affects them, that if they want it fixed quick then I may have to use 'work' time i.e. no guarantees that it would be done that evening or even that week; after all it is supposed to be fun and not stressful.