XUnit: Test discovery is taking more than 1 hour #2549
Comments
|
We are seeing a similar issue with our solution. It's nowhere near as bad but it's still considerable: XUnit: 2.4.1 ========== Starting test discovery ========== |
|
We're experiencing issues as well, discovery takes long time, running tests typically completes under a minute. xunit: 2.4.1 Computer: ========== Starting test discovery ========== |
|
Is anybody able to reproduce this outside of Visual Studio? Is anybody able to provide a repro project? |
|
Not sure how you would reproduce this outside of VS? Any pointers? Is there a way to debug? increase logging level? |
|
I tried once with Jetbrains rider and seems to be same issue where it takes longer time to discover. And same I can't share repo as belongs to official. |
|
My guess, since you have no repro, is that you are doing something during discovery that is taking a long time. We have a lot of extensibility points here, but the most likely one is that the actual data discovery is what's taking so long. Try setting |
With |
|
Setting preEnumerateTheories to false appeared to make no appreciable difference. Here's the log from within VS in case it helps: It's difficult to be sure, because the output is very different when running dotnet test from the command line, however it does not appear to exhibit the same behvaior. |
|
How about turning |
|
It's also strange that VS isn't running any of those discoveries in parallel. Even 16 seconds is a long time for discovery (IMO), but if it were running all the discoveries in parallel, you'd be looking at a minute or less instead of 12 minutes. 😞 |
|
Okay, now that I look closer, something is very strange here. They all seem to be long delayed before discovery starts, but discovery itself happens very quickly. Example: Why did VSTest wait 35 seconds before starting discovery? The actual discovery took well under half a second. |
|
I created a new solution and added three new Test Projects based on the xUnit Test Project template. I changed the code inside each of the 'UnitTest1' classes to: As you can see by the logs below the actual test discovery is negligible, however it still took 22 seconds to complete. I enabled both |
We started doing that, and it will ship in the next version of VS (17.3). |
|
I can't repro this, I am using VS 17.2.6 and 2.4.5 runner, and 2.4.1 framework. Net 6, and the tests shown above: For your repro you could enable VSTest (TestPlatform) diagnostic logs in the test menu, and then grab the logs from your
|
|
Log file attached: |
|
@justhoma is that all that was there? Only a single file? The info there is not complete, it only shows the execution up until extensions are loaded, which is happening before discovery even starts. |
|
It was the only file which is odd. |
|
This is the relevant part of the log, there is 5s gap when xunit does something. I don't think this is vstest fault, we try to log everything that is happening, and console just waits for testhost to send some events, and testhost does nothing: I guess the best way to diagnose this would be to start perfview, record the execution, and look at flame graph in the related time slice: Start perfView, select Collect > Collect, add additional event source to capture test platform events
(You can also unclick Merge and Zip to save time). In VS you can do Clean, then Re-build to force test re-discovery. Then you can stop the collection, and it will open the etl file for you. You double click Events, type testPlat on the top, and then use Ctrl to select the adapter discovery start and stop events:
You will probably see more of them, choose a pair of them, and open CPU stacks, select the testhost process for your chosen pair of events, and double click it:
Then copy paste the timestamps of the events to start and end so you see only the relevant time slice, and press enter:
You can then switch to flame graph. Select "Group class entries" and Fold% 1, and you should see something like this:
There you can do File > Save View as > and select Speedscope json format and maybe post that resulting file, and also screen shot of that flamegraph. |
I'm not 100% sure your configuration file is correct, because enabling Since we don't see any additional output here, that also makes me suspect that your |
I realize now digging into the source for the VSTest adapter, we print the banner at a different time than I expected. Oops. 😁 So you're right, it's definitely all in our code. Before you see the "Discovering" banner, we are basically setting up the app domain and loading the assemblies. Here's the banner printing and the parsing of the RunSettings XML (neither should take any time): https://github.com/xunit/visualstudio.xunit/blob/main/src/xunit.runner.visualstudio/VsTestRunner.cs#L86-L109 And then here's the discovery: https://github.com/xunit/visualstudio.xunit/blob/b0b4704a7c4e1bd901cd50f40e7fd4ea36f0deb2/src/xunit.runner.visualstudio/VsTestRunner.cs#L218-L334 We can see the "Test discovery started" message being sent on line 299. So tracing through this, as near as I can tell, it's all about assembly loading. Why does a test assembly and its dependencies take 15 to 60 seconds to load? That I'm not sure about. I'm hoping the internal diagnostic messages (which should include a list of all assembly resolution) might give a direction to look. |
|
Here's what I see when I add the Is this enough or would you like me to try the other solution? |
|
Is this issue related? |
|
@nohwnd When is VS (17.3) expected to be released? This is becoming a fairly big issue and appears to be impacting pretty much all our dotnet solutions. |
Seems like a pretty likely explanation. |
|
Any plans to do anything? |
|
It sounds like we're waiting on a fix from Visual Studio. |
|
Note in the issue mentioned above (if I get time I'll work up a PR), the fix shouldn't require Visual Studio - its inside the visualstudio.xunit project. Ideally there would be some sort of filtering applied (such as In my testing, this was definitely causing a delay prior to the discovery starting that matches the descriptions above. I don't know what percentage of users would usually use custom reporters but I would expect it to be on the lower side. |
|
@justhoma I think it released yesterday? @kiwidev FWIW in vstest we currently use a naming convention e.g. *TestAdapter.dll, and then an assembly level attribute also by convention (we know the shape of it, but the extension author defines it in their extension): When found we inspect only those types for the desired type of extension, rather than inspecting all types. |
|
Closing as a dup of xunit/visualstudio.xunit#317. |
#4568) Addresses xunit/xunit#2549 to reduce our integration test shard execution time from > 1 hour to <= 30 mins. The TL;DR is that xUnit has an extension mechanism that attempts to load every class in every available DLL to see if it extends a given interface. This manifests in a huge delay on startup before any tests begin to run, e.g. 52 mins in this case: https://github.com/dafny-lang/dafny/actions/runs/6241813664/job/16944685069#step:22:146 (make sure you turn on Show Timestamps!) This was steadily getting worse as we added more classes, especially #4438 as it added a bunch of Dafny-generated code. Fortunately xUnit 2.5.1 added a knob to switch off this discovery, which we're definitely not using. <small>By submitting this pull request, I confirm that my contribution is made under the terms of the [MIT license](https://github.com/dafny-lang/dafny/blob/master/LICENSE.txt).</small>
#4568) Addresses xunit/xunit#2549 to reduce our integration test shard execution time from > 1 hour to <= 30 mins. The TL;DR is that xUnit has an extension mechanism that attempts to load every class in every available DLL to see if it extends a given interface. This manifests in a huge delay on startup before any tests begin to run, e.g. 52 mins in this case: https://github.com/dafny-lang/dafny/actions/runs/6241813664/job/16944685069#step:22:146 (make sure you turn on Show Timestamps!) This was steadily getting worse as we added more classes, especially #4438 as it added a bunch of Dafny-generated code. Fortunately xUnit 2.5.1 added a knob to switch off this discovery, which we're definitely not using. <small>By submitting this pull request, I confirm that my contribution is made under the terms of the [MIT license](https://github.com/dafny-lang/dafny/blob/master/LICENSE.txt).</small>
We are using XUnit for API tests and currently we have more than 3k tests but it takes 63 minutes of time to actually discover it and then only its ready to execute.
XUnit: 2.4.1
XUnit.Runner.VisualStudio: 2.4.5
Visual Studio 2019 (Version: 16.11.15)
Visual Studio 2022 (Version: 17.2.3)
I tried in both VS but same results.
========== Test discovery finished: 3515 Tests found in 63 min ==========
The text was updated successfully, but these errors were encountered: