Troubleshooting slow unit test runs

[ThomasSchmidt]

Hi,

Hoping the community can help here.

We are using NUnit (3.13.3) and NUnit3TestAdapter (4.5.0) in all our test projects, we have roughly 5 test projects with around 10.000+ tests in them, of them around 9.000 is located in one of the projects, our core project. All tests are pure unit tests, no integration tests in these projects. We are using NSubstitute primarly, but a few legacy tests is using Moq. A small part of the tests use [SetUp] or [SetUpFixture] but we are trying to get away from that. All projects are .net 6.

Currently our tests take around 6m 30s to run on the fastest dev machines and around 10m on our build agents, so we are looking to increase performance and one of the things we are looking into is running tests in parallel with assembly level attribute like [assembly: Parallelizable(scope: ParallelScope.Fixtures)] or even ParallelScope.Children.

This for some reason doesn't speed up our test runs, it actually made them a little bit slower, which we do not understand. We have tried making example projects with a couple of hundred tests in them, purely with just Thread.Sleep(..) in them, and they ran as fast as expected. We then started logging the tests results to a trx file, importing said file in excel so we could see the duration of each test. This was an eye opener, some of the tests took 30+ seconds to run, but if you run them individually or even as part of a test fixture with a lot of tests in them they run instant (< 1ms effectively). It makes no difference if we run the tests on commandline with dotnet test or we run them inside visual studio. We also logged tests runs after we discovered this without using ParallelScope attributes of any sort, and it is the same thing, still seeing these 30+ seconds duration tests when we run the entire test suite, but run them individually or just as part of a fixture and they are near instant.

We did notice that there is some overhead in creating mocks with NSubstitute for example Substitute.For() takes around 60-70ms for most cases, but that is caused by Castle.Core creating proxies, and using ParallelScope.Children seem to run everything in new threads so it cannot re-use its internal caches, hence why we are using ParallelScope.Fixtures, but this doesn't even remote explain the 30+second test durations we are seeing.

Is there any way to troubleshoot this? Or does anyone have any good ideas around this? I think I have read all documentation there is around NUnit for logging things or whatever, but no hints yet.

Want to thank the developers for making NUnit, what an amazing piece of work.

[OsirisTerje]

Assembly parallelization is handled by the testhost, not by nunit. If you add a runsettings file (you can install the template using https://marketplace.visualstudio.com/items?itemName=OsirisTerje.Runsettings-19151) , select the parallell template, and you have the correct settings. There is a blog (a bit old now, but still correct, some links seems dead) https://devblogs.microsoft.com/devops/parallel-and-context-sensitive-test-execution-with-visual-studio-2015-update-1/ .

The setting you're looking for is

You can also just drop these few lines into your own .runsettings file though to check it out.

PS: The template also ensures you don't activate code coverage, which will slow down everything. See https://devblogs.microsoft.com/devops/parallel-and-context-sensitive-test-execution-with-visual-studio-2015-update-1/#why-dont-we-include-code-coverage

[OsirisTerje]

You activate the dumps in a runsettings file, see https://docs.nunit.org/articles/vs-test-adapter/Tips-And-Tricks.html#dumpxmltestdiscovery-and-dumpxmltestresults
The files are in a folder named Dump under your test projects binary output folder.

The tests in the NUnit.TestPrograms are very short and simple, so activating/deactivating threads probably takes longer time than the tests themselves. In a real testprogram with slower tests it would make a more positive result, but one should not overdo attempts at parallelisms, considering the number of cores you have to create threads.

The delays you see at 30secs however, must be something else going on.

[ThomasSchmidt]

I tried activating dumps in a runsettings file and I am seeing quite a few examples like this:

<test-case id='0-2286' name='SomeTestNAme' fullname='SomeTest' methodname='SomeTestMethodName' classname='SomeNamespace.SomeTest' runstate='Runnable' seed='1032018474' result='Passed' start-time='2023-09-15T14:32:58.5966830Z' end-time='2023-09-15T14:34:38.2075943Z' duration='99.609258' asserts='3' parentId='0-2283' />

This line appears multiple times in the file, and it says duration 99.60s and if I run it on its own or with maybe a handful other tests, either from visual studio or from command line, it executes in <100ms. The tests doesn't have any shared state or anything, just a simple create a few mocks, execute SUT and and assert.

Quite strange..

[ThomasSchmidt]

Just posting an update here as this is beyond weird to me, it seems that if the number of tests run around higher than roughly 2000 tests from an assembly, things will slow down immensely. We are using feature folders for our code, so my examples are around that.

I have run tests like this:
dotnet test --no-build --filter "Features.H|Features.I|Features.L|Features.M"
This is 1927 test that gets hit with this filter and it runs in 16 seconds, then I run the following filter
dotnet test --no-build --filter "Features.H|Features.I|Features.L|Features.M|Features.N"
Now we hit 2124 tests and it takes 4 minutes and 42 seconds to run. The only difference is I include a filter "Features.N" that takes it from 1927 tests to 2124 tests. I can also run with a filter of just "Features.N" and the 200 tests there execute in around 3 seconds.

I can do any combination of unit tests, and it appears that as soon as we cross the roughly 2000+ count of tests, everything slows down dramatically.

[OsirisTerje]

If the number of tests are >2000 you're hitting the default setting AssemblySelectLimit, which is at 2000. See https://docs.nunit.org/articles/vs-test-adapter/Tips-And-Tricks.html#assemblyselectlimit which also explains the side effects of this setting, which is that the category setting is skipped (in VS).
I suggest you raise this limit in your case.
Another tip: Set the NUnit.Verborsity to 5. You will then see all the settings for the adapter listed, including the ASL, and others that might be interesting.

[lahma]

I wonder if the limit was created because due to overhead of transferring the information or due to to matching being slow. The OR matching was already improved in #3786, #3787 and #4034 . So this limit might be too low or even unnecessary?

[ThomasSchmidt]

I have tried with:
dotnet test --no-build --settings nunit.runsettings

and the following is in the nunit.runsettings file

<RunSettings>
	<RunConfiguration>
		<MaxCpuCount>0</MaxCpuCount>
	</RunConfiguration>
	<NUnit>
		<Verbosity>5</Verbosity>
		<AssemblySelectLimit>10000</AssemblySelectLimit>
	</NUnit>
</RunSettings>

And I am not seeing any changes, still slow unfortunately :(

What is very strange though is that I asked 10 devs on our teams to run the tests with and without runsettings file, and for 8 of them we are seeing the exact same results as I am here, below 2000 tests filtered then the runs are as fast as expected but more than that it is slow, roughly 6m 30s for our entire suite of almost 10.000 tests. But for 2 devs with one of them having a standard intel i7 setup like the rest of us and one with a intel i9 laptop, are seeing completely different numbers, the i7 dev can run the entire suite in less than 40 seconds and the i9 dev can run the entire suite in less than 25 seconds. Running with or without runsettings doesn't make a difference for anyone.

[OsirisTerje]

@lahma It was the overhead of transferring every tests by name in a list. With 10000 tests it went way up the megabytes area.
Without the limit, the transfer is done without any list of test cases, so it should still be the fastest way to transfer the request to the framework/engine. That doesn't mean the tests will be faster though, since many more tests will be run.

@ThomasSchmidt If you look in the dump files, you can see how the request to the engine looks. (Hitting the limit at 2000 is strangely close to the default assemblyselectlimit, so it being something else there is weird.) Without knowing anything more about your tests, it is hard to figure this out. You say you have tried with a repro solution that doesn't repro the behavior you see. There must then be something in your tests that differs significantly.

[manfred-brands]

@ThomasSchmidt Do these machines that run the tests fine have more memory?