Test Discovery slow for large TestCaseSource and TestCaseAttribute

[cidthecoatrack]

I am currently using version 3.15.1 of the test adapter in VS 2019 Community edition (16.2.5). .NET Standard 4.5.2 for the code.

I have a solution with >80,000 tests. 2 test projects have about ~40,000 each. There are many tests that have several hundred test cases (either from TestCaseAttribute or TestCaseSource and a class building the test cases). When I go to run my tests, the actual test run is only a few minutes - but the discovery phase takes up to 20 minutes to find/build all test cases. While I understand that constructing large TestCaseSource and parsing hundreds of TestCaseAttributes will take some time, but 20 minutes seems excessive.

[9/23/2019 9:13:57.068 AM Informational] NUnit Adapter 3.15.1.0: Test execution started
[9/23/2019 9:13:57.108 AM Informational] Running selected tests in C:\Users\cidth\Documents\GitHub\CreatureGen\CreatureGen.Tests.Integration.Stress\bin\Debug\CreatureGen.Tests.Integration.Stress.dll
[9/23/2019 9:13:57.308 AM Informational] NUnit Adapter 3.15.1.0: Test execution started
[9/23/2019 9:13:57.351 AM Informational] Running selected tests in C:\Users\cidth\Documents\GitHub\CreatureGen\CreatureGen.Tests.Integration.IoC\bin\Debug\CreatureGen.Tests.Integration.IoC.dll
[9/23/2019 9:13:57.528 AM Informational]    NUnit3TestExecutor converted 3 of 3 NUnit test cases
[9/23/2019 9:13:57.863 AM Informational]    NUnit3TestExecutor converted 26 of 26 NUnit test cases
[9/23/2019 9:13:58.347 AM Informational] NUnit Adapter 3.15.1.0: Test execution started
[9/23/2019 9:13:58.404 AM Informational] Running selected tests in C:\Users\cidth\Documents\GitHub\CreatureGen\CreatureGen.Tests.Integration\bin\Debug\CreatureGen.Tests.Integration.dll
[9/23/2019 9:13:58.592 AM Informational] NUnit Adapter 3.15.1.0: Test execution complete
[9/23/2019 9:13:59.374 AM Informational]    NUnit3TestExecutor converted 757 of 757 NUnit test cases
[9/23/2019 9:13:59.589 AM Informational] NUnit Adapter 3.15.1.0: Test execution complete
[9/23/2019 9:14:02.972 AM Informational] NUnit Adapter 3.15.1.0: Test execution started
[9/23/2019 9:14:03.208 AM Informational] Running selected tests in C:\Users\cidth\Documents\GitHub\CreatureGen\CreatureGen.Tests.Unit\bin\Debug\CreatureGen.Tests.Unit.dll
[9/23/2019 9:14:03.758 AM Informational] NUnit Adapter 3.15.1.0: Test execution started
[9/23/2019 9:14:04.043 AM Informational] Running selected tests in C:\Users\cidth\Documents\GitHub\CreatureGen\CreatureGen.Tests.Integration.Tables\bin\Debug\CreatureGen.Tests.Integration.Tables.dll
[9/23/2019 9:14:11.565 AM Informational] NUnit Adapter 3.15.1.0: Test execution complete
[9/23/2019 9:20:06.993 AM Informational]    NUnit3TestExecutor converted 34144 of 34144 NUnit test cases
[9/23/2019 9:25:08.348 AM Informational]    NUnit3TestExecutor converted 45509 of 45509 NUnit test cases
[9/23/2019 9:32:16.820 AM Informational] NUnit Adapter 3.15.1.0: Test execution complete

I did read over in #448 that the adapter scans for things in serial, and twice - which would certainly be a source of the slowdown. If I set the test runner to use parallel runs (as the task suggests), that does help with the speed, but it is still very slow to do a "Run All".

The repo where this occurs can be found here. Simple check out the branch, open the solution, build, and click "Run All". There will be test failures, but the time it takes for test discovery is the concern.

I can run the tests in the console runner, and the test discovery is much faster, which also matches up with #448 .

[OsirisTerje]

I can confirm this. It seems to be very slow during the discovery phase, and it seems that phase is triggered even for Real Time Discovery (excluding the extra discovery during execution). Running the console doesn't trigger discovery, so it makes sense it runs faster then.
@jnm2 It seems to be the parsing of the test attributes that does this. Can you have a look ?

[aolszowka]

This still repos for me; I have created a smaller version of the test here https://github.com/aolszowka/NUnitTestDiscoverySlowIssue660 and I am continuing to dig.

[OsirisTerje]

@aolszowka Thanks! You can also have a look at the Prefilter options, see the docs for the settings. It might help.

[aolszowka]

So I have dug into this; I think at least part of the problem is the filter being passed to this.

Specifically this seems to choke early on in the MasterTestRunner.cs at line 438:

https://github.com/nunit/nunit-console/blob/4ae12183927747e2a35859ad520790f84ebaf5f9/src/NUnitEngine/nunit.engine/Runners/MasterTestRunner.cs#L438

The filter that is being sent to the framework is crazy big (in fact its every single test listed); here's a snippet:

<filter>
<or>
<test>TestLibrary1.TestLibrary1.TestNumber0</test>
<test>TestLibrary1.TestLibrary1.TestNumber1</test>
<test>TestLibrary1.TestLibrary1.TestNumber2</test>
<test>TestLibrary1.TestLibrary1.TestNumber3</test>
...
<test>TestLibrary1.TestLibrary1.TestNumber99998</test>
<test>TestLibrary1.TestLibrary1.TestNumber99999</test>
</or>
</filter>

This was added as part of nunit/nunit-console#625. However even just commenting that out it falls over as soon as it attempts to use a filter (he's just the unlucky first guy to hit it).

Part of the problem is it looks like the logic runs though the entire filter list for every test:

https://github.com/nunit/nunit/blob/b315a692d623f74f5440a811e4dc21b7b6387087/src/NUnitFramework/framework/Internal/Filters/OrFilter.cs#L67-L74

This gets super expensive the larger the filter becomes. This should probably be replaced with some type of Hash structure for O(1) look-ups however that is probably a danger zone considering how core it is. Definitely not something I'd be comfortable hacking a fix on.

Maybe @CharliePoole or @rprouse could chime in? Its unclear who owns this, but this code has been around for a long while.

As for what could be done on the adapter end, I think that is where you were trying to point towards pre-filtering; but that really just hides the problem I think.

[CharliePoole]

@OsirisTerje is the lead for the adapter projects. GitHub unfortunately doesn't show that where you might expect to see it. Maybe we should add it as a comment for each project.

I haven't worked on the adapters for a number of years but I'm familiar with the issue if test filters. NUnit's filtering is very flexible and pretty efficient when a small number of filters are combined, There are two distinct problems with filtering, one when you select tests in the IDE and a differnet problem when you use a VS filter expression in your .runsettings file.

However the OP here was talking about a Run All command, which should not use any filtering at all, so we may be mixing two different problems here.

[aolszowka]

Thanks for Responding @CharliePoole .

The Run All command in Visual Studio is basically equivalent to sending every single test due to a change from Microsoft in Visual Studio 2019 (See #658 (comment)). This is what is creating the large filter file, even with a "Run All" Command.

I still believe the underlying cause though is that as the filters get larger (read 50,000+ Filters or more) a significant amount of time is spent in the various filter phases, which is outside the scope of the Adapter (it is happening in NUnit.Framework.Internal.Filters.OrFilter). This would be in the Framework itself.

Is there a way for me to pass the XML Filter Format (https://github.com/nunit/docs/wiki/Test-Filters) to the console or another runner to remove the nunit3-vs-adapter from the loop?

[OsirisTerje]

You can use NUnit.Console to run your tests, but that is on command line. Removing the adapter from the loop - that's kind of cutting the branch of the tree you're sitting on.

We don't know anymore (after the VS change) if we are being called as "Run All" or "set of tests".

So currently we have no way of knowing if we have all tests or none. Earlier we called without any filter (filter.Empty() for Run All. Since we lack that context now, all the tests are being sent down.

Next, since this is about dynamic tests, the discovery has to run. What could be done is perhaps to send down a different filter IF the testCases from Test Explorer are a subset of the discoveryresults. Then we know we have an ALL tests situation.

[aolszowka]

@OsirisTerje How do I use NUnit Console to read the Filter File? All of the examples seem to indicate that I need to have --where on the command line with the filter string. Is there another overload I can use that I can send an XML Filter File (https://github.com/nunit/docs/wiki/Test-Filters)?

[CharliePoole]

I wasn't aware of that change, which seems rather insane if you know how NUnit works.. The normal way to run all tests in NUnit is to select nothing at all.

The original TestFilter design assumed that filters would be used somewhat judiciously. After all, they were intended for use when users invoke individual tests or categories. If the user has a tree of thousands of tests displayed in a GUI, it's not likely that they will go through and select every test in order to run them all, since not selecting any gets them the same result. To the extent that filters are created (indirectly) by users, there still seems to be no great reason to worry abou the efficiency of extremely large numbers of individual filters.

So my judgement is that this is either a job for Microsoft or for the adapter, which is the piece of software that's supposed to translate between Microsoft and NUnit views of the universe.

It should be fairly simple to reduce filters to only those needed.

• We have a tree of tests that NUnit discovered.
• Working bottom up, if all the children of any node are selected, deselect them and select that node itself.
• Once we get to the assembly node, if it is selected as a whole use an empty filter, otherwise, use a filter that lists either the names or the ids of every node that remains selected.

I'll have to check to see how much effort it would take to get set up to work on the adapter but if it's possible/reasonable I can take a shot. Alternatively, I'll be glad to review somebody else's PR!

[OsirisTerje]

Not sure why you need the filter file? That is a result of the adapter getting all the tests in. If you want to simulate Run All, then just run without the filter for each assembly.
[Edit] As Charle said "select nothing at all"

[OsirisTerje]

@CharliePoole We already have code that does that traversal, implemented for categories/traits last year I think (by @jnm2 ). So, doing another scan up there should be doable. I would however finish the refactoring first, so that all these scannings are simplified.

You can have a look here: https://github.com/nunit/nunit3-vs-adapter/tree/refactorengineadapter , and the discussion here: #658 .

[CharliePoole]

@aolszowka If you want to do this just to run a timing test, then create a text file with the full names of all the tests to run and use the --testlist option. The console will create the same filter that is created by the adapter for those names.

OTOH, if you are doing this for any other reason than as an experiment, I'd suggest using the time to fix the adapter. 😄

[CharliePoole]

@OsirisTerje In that case, I'll wait for your refactoring. Let me know if there's anything I can do to help. BTW does this impact the V2 adapter as well?

@aolszowka IMO fixing the adapter is the best place to focus.

[aolszowka]

Thank you both @CharliePoole and @OsirisTerje for the detailed write ups; as you both have mentioned looking at the refactor seems to be the best place to put the work.

Could this comment:

The original TestFilter design assumed that filters would be used somewhat judiciously. After all, they were intended for use when users invoke individual tests or categories. If the user has a tree of thousands of tests displayed in a GUI, it's not likely that they will go through and select every test in order to run them all, since not selecting any gets them the same result. To the extent that filters are created (indirectly) by users, there still seems to be no great reason to worry abou the efficiency of extremely large numbers of individual filters.

Get added somewhere in the wiki? Maybe off the https://github.com/nunit/docs/wiki/Test-Filters page? It is valuable information about the design goals and history and would ward off those trying to leverage it for extremely complex or large cases.

[OsirisTerje]

@CharliePoole Would be great if you could give a hand here when it gets rough, and it will ;-) I'll keep you posted.

@aolszowka Good suggestion, we'll have a look where it can go.

[cidthecoatrack]

Could we maybe do a sort of "dumb hack"? Maybe just check the number of filters, and if that's equal to the number of tests, say it's everything and remove all filters?

As an update, my test project has now expanded to more than 160K tests, and it takes hours to discover all tests

[CharliePoole]

@cidthecoatrack That would work if you counted only filters using a test name and compared to the number of test cases. However, it would rely on VS never changing how it makes the call in a future release. The more robust approach of collapsing/removing filters bottom up in the test tree would be quite efficient, I think, and pretty easy to do.

@OsirisTerje What's the status of this?

[OsirisTerje]

@cidthecoatrack Have you tried the latest version 4-alpha ? It should have a speedup of at least 50%. Take a look at issue #497
@CharliePoole The 4 version also uses the NUnit filters, #767.

Also, version 4 has a limit for how many tests it will allow in a filter, if exceeded, then the filters are dropped, see https://docs.nunit.org/articles/vs-test-adapter/Tips-And-Tricks.html#assemblyselectlimit

[cidthecoatrack]

With using the 4.0-alpha package, I see a marked improvement when running all tests with large test projects. Discovery used to take over an hour for my biggest projects, but now generally work under 10 minutes (or faster).

[h4kun4m4t4t4]

Hi I previously opened an issue in the NUnit repo -> nunit/nunit#3601
Because lack of time I couldn't spend more time in investigating or contact the Jetbrains team.

Today I updated to the latest Resharper Version and the delay (upto 12 seconds) occurs again until the tests are discovered.
Maybe it correlates to this issue? (if not: sorry and ignore this post)

From Resharper Testrunner - One Test executed (~4 sec delay):
2020.12.04 16:56:52.149 INFO TestRunner: NUnitRunner Discovering tests from ...
2020.12.04 16:56:58.612 VERBOSE TestRunner: NUnitTestReporter Sending discovery results to server...

From Resharper Testrunner - All Tests (~2000) executed (~8 sec delay):
2020.12.04 17:09:19.493 INFO TestRunner: NUnitRunner Discovering tests from ...
2020.12.04 17:09:25.806 VERBOSE TestRunner: NUnitTestReporter Sending discovery results to server...

DefaultTestAssemblyBuilder.GetFixtures()
Resharper Testrunner

The foreach loop's duration is about 8 sec. I guess this will increase even more, when there are 10k or 20k tests?
If there was a delay before the upgrade of Resharper Version, then it was not noticeable.

VS Test Explorer

When using the VS Test Explorer the same assembly test detection takes less than 1 second.

I do not get why it behaves differently between both.

[OsirisTerje]

Retested this now with 4.0.0 and it is significantly better, even without the AssemblySelectLimit set low.

[marcw3]

hi @OsirisTerje and @CharliePoole @cidthecoatrack I know this issue has been discussed at length my issue is due to the fact i'm using VS2022 and using the Test explorer to debug my tests cases. My test cases are using TestCaseSource also. Currently I have 108 test cases and its taking over 9 min for test discovery to happen. I'm stuck on how to debug my test without facing this issue or when its time to run it through devops. I've tried different settings on Nunit tips and trick and haven't found anything viable. I'm currently running Nunit 3.13.3 and Nunit3 test adapter 4.5.0. Any direction would be appreciated