Lots of warnings logged when filter matches no tests 'cat=BAZ'

[runehalfdan]

(This was found when testing issues in #912, and can be reproduced with test-code provided in #874. Registering as new since I suspect it is unrelated to those issues)

Running this, which matches no tests, generates warnings (or, yellow output, which I assume are warnings):
dotnet test TestProject1.sln -v:q --logger="Console;verbosity=minimal" -- NUnit.Where="cat=BAZ"

There are three logged warning pr test, so get nine warnings of this form:
Test 0-1001 not found in cache

This logging slows things down a LOT, even when verbosity is 'quiet'. A test-run that previously took about 30secs now take more than 5 mins.

We run each test project isolated; a .proj-file runs target 'vstest' in each test-project, passing in filter on command-line

(For background info, we have about 13000 tests in total now, in a codebase going back in time. So we have traditionally used categories to select which tests to run when)

[OsirisTerje]

I'll get this subdued for the release version.

[OsirisTerje]

@runehalfdan Just published 4.2.0-beta.2 with the fix.

Are your tests split over multiple assemblies? Please be aware of the AssemblySelectLimit. If you have more than 2000 tests per assembly, your filters will be turned off, except those explicit and ignored. This applies when called from VS and from command line with a list of tests- If this causes problems, just raise that level way up. This was done to increase performance. If you just use categories, it will not be stopped.

Your mention of test speed is very interesting, would appreciate feedback on that when you check beta.2 .

[runehalfdan]

@OsirisTerje Yes, I don't think any individual assembly has more than 2000 tests. Would it be logged if limit is exceeded?

So, running with at category-filter that only would match ~10 tests out of ~3000 now take over 7 minutes, vs. 30 seconds before with Legacy discoverymode.
Running with a category that match most (but not all) of the ~3000 tests took 3 minutes, and almost same time using Legacy discoverymode.

The specific filters are
cat = DOCS which match about 10 out of ~3000 tests
cat != MANUAL and cat != NIGHTLY and cat != Explicit which match almost all

Could it be that scanned tests not matching filter isn't cached? We make quite heavy use of TestCaseSource, TestFixtureSource and TestFixture(Type foo) for generic tests

The annoying logging of Test 0-1001 not found in cache is gone.

[OsirisTerje]

@runehalfdan Thanks for the info. I'll try to replicate your scenario.

1. AssemblySelectLimit: Yes, it will be logged, but you need to set verbosity to >=5.
2. Those 3000 tests, how many approx would be Explicit?

It might be the size of the filter, a category filter will in this case be replaced with a test list, but to be sure I'll need to replicate this behavior.

[OsirisTerje]

@runehalfdan I tested the different scenarios with the repro code an earlier issue #497, the code is here: https://github.com/nunit/nunit3-vs-adapter.issues/tree/master/Issue497 , and I could not reproduce any slowness here. I tried with both positive and negative filters, and using both the --filter command and the NUnit.Where, and got the same results. Can you verify the repro, and see if there is something else you have that triggers this? You can also add to the same repro if you like, since it generates 20000 tests.

As you can see, we have had this issue earlier, so would not rule out that there is some scenario we haven't found.

[OsirisTerje]

@runehalfdan I have uploaded a new beta, https://www.nuget.org/packages/NUnit3TestAdapter/4.2.0-beta.3 , which contains a bit more logging.
It will produce a bit of noise, so redirect the output to a file, like in the following example:

dotnet test Issue497_Filtering.csproj --filter=TestCategory!=Slow -v:n -l "Console;Verbosity=normal" -- NUnit.Verbosity=5  > log.txt

You can change the filters to NUnit filters if you like, just add it after the Verbosity statement.
When the adapter execute tests it does two things: First it runs a discovery, then based on the results there, it runs the real text execution.
If you look in the start of the log file, you will see a section like:

The section will be around the same place, line 100 or so.
The interesting things are 1. Filter length, 2. Elapsed time (for discovery that is) and 3, if filter length is less than 100, the filter itself.
Also notice there is a time for converting test cases, neglible in my case, on line 111, please check this one too.

The next section is near the bottom of the file:

If you can grab out this information in your case, I would assume it would point to where the issue might be. And then it should be possible to create some sort of repro for it.

The important thing to get out the information is to set the NUnit verbosity to 5, and then the logger setting to make it come out. You can change how you want to filter anyway you like, including using a runsettings file, if you prefer.

[runehalfdan]

@OsirisTerje I updated to Beta 3, set verbosity to 5, and ran logs both with and without legacy discovery mode (I'd rather not upload the logs here, but can shared in mail if you want)
I'm now running only one test-assembly (previously I ran with many, but each invoked individually using msbuild). These are my log finding:

Execution engine discovery time with filter length 32 :Elapsed: 00:00:00.08
Filter: <filter><cat>DOCS</cat></filter>
 NUnit3TestExecutor discovered 0 of 0 NUnit test cases <snip>
Converting test cases  :Elapsed: 00:00:00.00

This is exactly the same with and without legacy discovery mode
Then this comes in non-legacy:

(there are in total 251 entries of not found)
Test 0-1057 not found in cache
Test 0-1057 not found in cache
Test 0-1057 not found in cache
Execution engine run time with filter length 17 :Elapsed: 00:00:35.74
Filter: <filter></filter>

Neither modes report Total Test/Total time (since no tests were executed)

Time Elapsed 00:00:00.99 for legacy mode, vs 00:00:36.70 for 'normal'.

(I'll try to look into the Issue497 tests to see if I can reproduce)

[OsirisTerje]

The second block is the execution part, right? The filter there has been cancelled out, which might mean that the AssemblySelectLimit has been hit, but I am confused that when discovery doesn't hit anyone, then execution should not run at all.

My mail is in my profile, so would be interesting to see .

[runehalfdan]

I've played around with the nunit3-vs-adapter.issues/Issue497_Filtering projects now.
I added [Category("FOO")] to one tests (which don't seem to matter), and while I couldn't see the the major timing diffs as I got with our repo, the time difference is clear.

Running with NUnit.Where=cat == FOO:
Execution engine run time :Elapsed: 00:00:00.04

Running with NUnit.Where=cat == BAZ:
Execution engine run time :Elapsed: 00:00:04.31

This could of course be logging tripping up the timings; there are ~60000 entries with entries 'Test 0-21503 not found in cache'

[runehalfdan]

The second block is the execution part, right? The filter there has been cancelled out, which might mean that the AssemblySelectLimit has been hit, but I am confused that when discovery doesn't hit anyone, then execution should not run at all.

The second block is the execution block.

The test-assembly contains 84 tests (as reported by adding -t to dotnet test), so should be no way near the assembly select limit.

[OsirisTerje]

Do you see a line saying Setting filter to empty due to number of testcases ? That is what I see for the negative filter, cat!=Slow. If you have set assemblyselectlimit above 20002 then, it will be in the execution part the following line: ```Execution engine run time with filter length 711194 ````. This might be what is happening in your case too, and this length may be even higher, and it will take time to transfer.
If I move to legacy, then execution time goes from 8 secs to 7 secs, but the filter is again equal to the discovery filter. So it might be this factor that actually does it.
The reason for changing the filter is to avoid the case where NUnit explicit is more relaxed than the adapter, meaning that NUnit will assume that explicit has been selected, where it actually has not.
So possibly, a way to work this is to allow for the explicit to be more relaxed, to gain speed.

About your results over, I get the same, but for the cat==BAZ I also see no tests being found, as expected, but then the 1) The execution should not run either - there is no point in that, and 2) an empty filter I being used.

I think this actually may be the bug here. I enabled the dumpfile, and there was a ton of tests being run, which is then subsequentially filtered off by the adapter, so it never reaches the testhost. You can see this by adding NUnit.DumpXmlTestResults=true and then look in the Dump folder under the bin\debug\netcore3.1. This is not correct.

Thanks a ton!
But it is actually a different bug than the logging, so I'll move this over to a new issue. Or better if you do that, so it gets your name on it :-)

[runehalfdan]

Good catch. I managed to reproduce by making a tests 'crash' by doing Environment.Exit(1);, , even when said test should have been filtered out

[OsirisTerje]

@runehalfdan Published https://www.nuget.org/packages/NUnit3TestAdapter/4.2.0-beta.4 now. Should fix the latest findings.

[runehalfdan]

@OsirisTerje I have verified that have test-filters that match none is fast again (and don't silently execute them)