Tests involving lots of parallelism take a long time to run with code coverage

[stephentoub]

At https://github.com/dotnet/corefx, there are several libraries that are are focused on parallelism (e.g. PLINQ, Parallel.For, etc.), and thus the tests for these involve lots of parallelism. Without code coverage, the tests for PLINQ take ~15-30seconds to run. With code coverage enabled, these same tests take anywhere from 15-30 minutes to run. This is a much larger increase than we see for tests not involving parallelism. It'd be great if there's a way to reduce these overheads.

[sawilde]

We'd have to see the tests and see how the OpenCover interaction is causing the increased time.

Can you point me to the tests that are badly affected?

[stephentoub]

Thanks, Shaun!

Easiest way is probably to clone the corefx repo at https://github.com/dotnet/corefx, and then from the root do "build /p:Coverage=true". That'll build everything and run all of the tests using OpenCover. One of the most interesting ones is the PLINQ suite, which is at https://github.com/dotnet/corefx/tree/master/src/System.Linq.Parallel/tests.

You can see the latest code coverage run in the lab at:
http://dotnet-ci.cloudapp.net/job/dotnet_corefx_coverage_windows/38/consoleFull
If you search for System.Linq.Parallel.Tests, you'll see that it took ~27 minutes (1672.183s). In contrast, if you just look at a recent build without code coverage, e.g.
http://dotnet-ci.cloudapp.net/job/dotnet_corefx_windows_debug/76/console
and do a similar search, you'll see that it took ~18 seconds.

Please let me know if there's anything I can do to help with analysis. And thanks for making OpenCover available; very nice tool.

[sawilde]

I see that the visit count is very high e.g. in ProducerComparerInt I see a visit count of 4422310 but only 1 of the 2 branches is tested.

You could therefore try adding the -threshold option, e.g -threshold:100, this stops OpenCover from recording visits for a seq/branch point once it has been reached this in turn reduces the flood of information into the host from the profiler. This is useful if you care about a visit but not how many times - it doesn't play well with the -coverbytest feature because of the reduced recording but you may find it helps with the overall performance.

It was added in response to a similar issue but the original reporter then determined the perf problem was actually elsewhere.

[stephentoub]

Thanks, Shaun; will try that shortly and get back to you.

[stephentoub]

That made a huge difference. It's still 5x slower with code coverage than without, but that's a lot better than 90x slower ;)

If all one cares about is whether a seq/branch point is hit and not how many times, any reason not to set threshold to 1 instead of 100?

[sawilde]

That's good

If all one cares about is whether a seq/branch point is hit and not how many times, any reason not to set threshold to 1 instead of 100?

no none at all but I don't think it's going to get much better - the problem is loops are tight and quick so they are hitting the same sequence points over and over again and each hit causes a call into the profiler to record a hit; only in the profiler does it determine that the hit is not to be recorded.

This happens here

https://github.com/OpenCover/opencover/blob/master/main/OpenCover.Profiler/ProfilerCommunication.cpp#L106

so there is probably two things that we may be able to do

1. increase buffer size (currently 65K)
2. improve the performance when locking the buffer to record a hit - any advice?

[stephentoub]

Thanks,Shaun.

Have you considered a per-thread buffer? Then the thread adding to its own buffer wouldn't need to do any synchronization in order to add to it (this could also help with single-threaded performance), and presumably threads would only need to synchronize when they wanted to send their visit points, if the mechanism through which they send requires serialization. Or if you wanted a fixed number of buffers rather than one per thread, you could create N of them and then have each thread access the threadId%N buffer... you'd need to synchronize still, but there should be less contention as a result.

(As an aside, it looks like the usage of m_thresholds in that same function could potentially suffer from data loss due to races if multiple threads tried to increase the same value concurrently. Maybe the threshold is really just meant as an approximation so such races don't particularly matter?)

[sawilde]

Have you considered a per-thread buffer?

I have but I am wary of too many buffers being created and the chance of data loss, especially when the runtime just stops and does not tell the attached profiler that it is shutting down. This is why we write to the shared memory area, that way the host can always get the last bits of data written when this happens

A small pool of buffers might work

m_thresholds in that same function could potentially suffer from data loss due to races

yes - I worked on the idea that if we didn't care about an accurate count then what is one or two extra reports of a sequence point going to matter.

[stephentoub]

I am wary of too many buffers being created and the chance of data loss

That's fair. I was thinking you could do something like this:

• Maintain a small buffer per thread, maybe enough for a few hundred or potentially a few thousand events (you could dial this up or down based on experimentation). The primary goal here is to avoid taking the lock on every point being traced.
• When the per-thread buffer is filled, then take the lock and dump the per-thread data into the overall buffer, proceeding with your logic as you currently have it. Effectively you're amortizing the cost of taking the lock across the size of the per-thread buffer, and avoiding unnecessary contention / serialization when multiple threads are all trying to access the main buffer at the same time... they only need to serialize with each other when dumping their tiny buffer into the bigger one.
• When a new thread attaches, set up its buffer, and keep a pointer to it in a list of buffers; when a thread detaches, remove it from the tracking list and dump its buffer into the main buffer, if there's any data still in the per-thread buffer. At the end of a run, the profiler can enumerate the buffers it's still tracking, see if any have data in them, and if any do, dump their data into the main buffer, which can then be flushed as you do at the end of a run today.

[sawilde]

I see where you are going - it would mess the track by test feature as that would no longer be able to track beyond the main thread (unless a test method exit became a dump visited points trigger)

[stephentoub]

it would mess the track by test feature as that would no longer be able to track beyond the main thread

Even if that's true and there's no workaround, that feature is opt-in, right? So by default threads could do their own buffering to avoid the locking costs (which I expect could help with performance a bit even in the single-threaded case), and if someone opted in to track-by-test, then it could skip the per-thread buffer (or logically set the size of the per-thread buffer to 1 so that it's effectively a write-through), making it more pay-for-play. Would that be feasible? Then it would be a separate issue to determine whether the better perf could be enabled for the track-by-test feature as well.