Diagnosing slow coverage reports

[ffMathy]

I'm having a test run that seems to go on forever.

Here's my log so far, although the tests are still running:

       AltCoverGenerateCoverageResult:
         ... C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.BusinessLogic.Tests\coverage.xml.tmp.pruner.0.acv (195.852b)
         5.211.327 visits recorded in 00:10:02.9396466 (8.643 visits/sec)
         ... C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.BusinessLogic.Tests\coverage.xml.tmp.pruner.1.acv (196.055b)
         5.218.369 visits recorded in 00:09:50.0547794 (8.844 visits/sec)
         ... C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.BusinessLogic.Tests\coverage.xml.tmp.pruner.2.acv (196.154b)

I tried opening these .acv files, but I can't seem to read them.

Is there any way that I can get more information on why such a large amount of calls is being recorded, and why it never ends?

Also, it's super nice that it seems to produce the X visits recorded in Y message once in a while, chunking things up. However, as you can see, the message didn't appear until after 10 minutes (so I thought my build was frozen). Can it perhaps chunk up based on size AND time, so that feedback is given no matter what, once in a while?

[ffMathy]

Alright, the coverage completed, after about 50 minutes.

The coverage file contains 126 anonymous type references. Can I tell AltCover to not instrument anonymous types somehow?

And is there anything else I should look for in the file, to see why it is slow?

[ffMathy]

Emphasis: By "slow" I don't mean AltCover is slow. 10.000 methods tracked per second is quite impressive, considering what it's doing. I am simply referring to the total time, due to the nature of my exact project.

[SteveGilham]

The .acv files are binary versions of the visit data, deflate compressed. Given that the compression is achieving more than 25 visits per byte, that looks like there is a great deal of repetitive looping going on. That, unfortunately, is the absolute worst sort of behaviour for the instrumented code, as it magnifies the instrumentation overhead -- see also issues #51 and #57 for previous examples.

The "x visits in y seconds" message comes from the post-test collection phase, and only considers the unpacking of the recorded data. Time spent executing the tests gets shown by the test runner, like

Passed!  - Failed:     0, Passed:   508, Skipped:     0, Total:   508, Duration: 22 s - AltCover.Expecto.Tests.dll (net5.0)

"Anonymous types" are just types, that happen to have names containing angle brackets, dollar signs or commercial ats, all of which are unutterable as identifier names at the user level. At the IL level, they are treated no differently to any user-named class, as in this example from one of the AltCover self-tests

        <Class>
          <Summary numSequencePoints="1" visitedSequencePoints="1" numBranchPoints="1" visitedBranchPoints="0" sequenceCoverage="100" branchCoverage="0" maxCyclomaticComplexity="1" minCyclomaticComplexity="1" visitedClasses="1" numClasses="1" visitedMethods="1" numMethods="1" minCrapScore="1" maxCrapScore="1" />
          <FullName>AltCover.Recorder.Instance/supervision@97-1</FullName>

[ffMathy]

Interesting.

Will things like /p:AltCoverSingle=true help with performance?

I'll try that, because I'm not really interested in knowing the counts.

[ffMathy]

Ah, I can't do that and still have the call context. That also makes sense.

[ffMathy]

Is there any way that I can easily spot the biggest "sinners" in terms of call counts, to quickly be able to see if there's a fundamental code problem? The given count seems incredibly high, even for the given test-run.

[SteveGilham]

In the completed .xml report, look at the sequence point visit counts, like

<SequencePoint vc="54" ...

In 2 lines of powershell

$x = [xml](Get-content [path to xml report])  
$x.CoverageSession.Modules.Module.Classes.Class.Methods.Method.SequencePoints.SequencePoint | Sort-Object vc -Descending | % { $_.ParentNode.ParentNode.Name }

will list the methods owning each line in descending order of visit count.

[ffMathy]

Great idea! I modified the command slightly, since it sorted naturally (alphabetically) and not numerically:

$x.CoverageSession.Modules.Module.Classes.Class.Methods.Method.SequencePoints.SequencePoint | Sort-Object @{e={$_.vc -as [int]}} -Descending | % { $_.ParentNode.ParentNode.Name, $_.vc, "" }

That identified some obvious flaws in my tests that I can definitely solve.

That being said, is there anything that can be done to further improve performance?

For instance, does every hit cause something to be written to disk? And if so, can we move this into memory? Perhaps with some IPC?

[SteveGilham]

Running under dotnet test everything stays in memory until the data collector TestSessionEnd handler is called, and only then is it flushed to disk. After much experimentation, that turned out to be the approach with least-worst performance and best reliability (in terms of test data getting no longer dropped by having the session abruptly terminated in the middle of the flush).

As for offloading to a separate process via some IPC mechanism, having three years ago now hit the VSTest abrupt finish limitation, but not discovered what it was that was cutting the time available to the ProcessExit handler, nor about the data collector option, that's something that I'd expected to have to do. Alas, the various attempts either ran into platform support issues (e.g. OpenCover style named shared memory mapped files), were slower than the naive approach of simply writing directly to disk at intervals (UDP or TCP sockets), and maybe both (named pipes, IIRC).

[ffMathy]

I see. Thank you so much for keeping up the good work and the detailed explanations.

I just reduced the amount of calls - it was way too extensive. That helped on the test duration, but it still seems like it's the parsing of the temporary acv files into the final file that is slow for me.

Could it be possible to make AltCoverSingle work with Call Context?

That way, the size would be way smaller. It is currently around 27 megabytes per project.

[SteveGilham]

At the inevitable cost of more memory (keeping a set of location + caller visits, rather than just location), it would be possible, same with location+timestamp.

The slow processing is purely the expansion of the few megabytes on disk into the likely actual uncompressed gigabyte-level amount of data thus represented, a price also paid on the way in -- so perhaps the extra processing associated with the extra memory would be offset by removing all that.

[ffMathy]

That sounds like a reasonable tradeoff to make. Dev computers and build servers these days have plenty of RAM to spare, but time is much more important IMO.

[SteveGilham]

Have an experimental build which should allow --single and --callContext together
altcover.7.3.121-github-pre.zip
Does this improve matters?

[ffMathy]

This works, and it does seem a lot faster! I can barely notice the collection time anymore!

[ffMathy]

Alright @SteveGilham, I have been thoroughly using this for about two working days, and there is no problem with it. I think it is shippable! Very nice!

[SteveGilham]

Released as v7.4.807

[ffMathy]

This is great stuff - thank you!