Visual Studio, test explorer is slow to start unit tests

Question

Visual Studio 2019 takes several minutes to START running unit test. This is a big (>300 projects) .NET Framework x86 Solution.

• Tests run immediately when executed from console.
• Tests take a couple of seconds to complete (once VS decides to start executing them).
• vstest.console shows no cpu usage in the task manager.
• Trying to run a single test makes no difference.

It feels like VS is waiting for something, but disconnecting the network adapter doesn't make the testing faster.

Running a Test in an empty project takes ~6s from clicking the Test Explorer play button until it finishes.

This is the detailed test log

[5/10/2021 9:22:45.934 PM] Interrupt: Enqueueing RunSelectedOperation
[5/10/2021 9:22:45.934 PM] Enqueue operation 'RunSelectedOperation', hashcode:11243619 
[5/10/2021 9:22:45.935 PM] Operation left in the the queue: 1
[5/10/2021 9:22:45.935 PM]  'RunSelectedOperation', hashcode:11243619
[5/10/2021 9:22:45.935 PM] 

[5/10/2021 9:22:45.935 PM] Operation Dequeue : 'RunSelectedOperation'
[5/10/2021 9:24:01.053 PM] test container discoverer executor://orderedtestadapter/v1, discovered 1 containers
[5/10/2021 9:24:01.053 PM] Containers from 'Microsoft.VisualStudio.MSTest.TestWindow.OrderedTestContainerDiscoverer' :
[5/10/2021 9:24:01.053 PM]  C:\MySolutionFolder\someOtherProject\unittestproject1\orderedtest1.orderedtest:executor://orderedtestadapter/v1
[5/10/2021 9:24:01.054 PM] Updating containers from Microsoft.VisualStudio.MSTest.TestWindow.GenericTestContainerDiscoverer.
[5/10/2021 9:25:51.309 PM] test container discoverer executor://generictestadapter/v1, discovered 0 containers
[5/10/2021 9:25:51.309 PM] No containers found from 'Microsoft.VisualStudio.MSTest.TestWindow.GenericTestContainerDiscoverer' :
[5/10/2021 9:25:51.310 PM] Updating containers from Microsoft.VisualStudio.MSTest.TestWindow.WebTestContainerDiscoverer.
[5/10/2021 9:27:02.077 PM] Summary TextView dimensions: w=244.046666666667 h=110
[5/10/2021 9:27:02.077 PM] Summary TextView dimensions: w=244.046666666667 h=110
[5/10/2021 9:27:02.082 PM] Summary TextView dimensions: w=244.046666666667 h=110
[5/10/2021 9:27:02.771 PM] Summary TextView dimensions: w=204.546666666667 h=110
[5/10/2021 9:27:02.771 PM] Summary TextView dimensions: w=204.546666666667 h=110
[5/10/2021 9:27:02.775 PM] Summary TextView dimensions: w=204.546666666667 h=110
[5/10/2021 9:27:24.231 PM] test container discoverer executor://webtestadapter/v1, discovered 0 containers
[5/10/2021 9:27:24.231 PM] No containers found from 'Microsoft.VisualStudio.MSTest.TestWindow.WebTestContainerDiscoverer' :
[5/10/2021 9:27:24.231 PM] Completed updating containers.
[5/10/2021 9:27:24.231 PM] Syncing containers with the test store.
[5/10/2021 9:27:24.246 PM] Triggering auto-discovery
[5/10/2021 9:27:24.249 PM] Enqueue operation 'DiscoverAllOperation', hashcode:55311871 
[5/10/2021 9:27:24.249 PM] Operation left in the the queue: 1
[5/10/2021 9:27:24.249 PM]  'DiscoverAllOperation', hashcode:55311871
[5/10/2021 9:27:24.249 PM] 

[5/10/2021 9:27:24.429 PM] Start building 1 containers.
[5/10/2021 9:27:24.429 PM] Triggering build for 1 IProjectBasedTestContainers.
[5/10/2021 9:27:25.301 PM] No IBuildableTestContainers were found.
[5/10/2021 9:27:25.301 PM] Completed building containers.
[5/10/2021 9:27:25.310 PM] Start updating 1 containers.
[5/10/2021 9:27:25.315 PM] Updating container C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll.
[5/10/2021 9:27:25.322 PM] Successfully refreshed container: C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll
[5/10/2021 9:27:25.322 PM] Completed updating containers.
[5/10/2021 9:27:25.323 PM] DiscoveryOperation<RunSelectedOperation> Changed container count is 1
[5/10/2021 9:27:25.328 PM] Discovering the following containers :
[5/10/2021 9:27:25.329 PM]  C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll
[5/10/2021 9:27:25.837 PM] UnitTestExtensionDiscoverer: Found the following Unit Test VSIX extensions: C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\ENTERPRISE\COMMON7\IDE\EXTENSIONS\MICROSOFT\NODEJSTOOLS\TESTADAPTER\Microsoft.NodejsTools.TestAdapter.dll
    C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\ENTERPRISE\COMMON7\IDE\EXTENSIONS\MICROSOFT\PYTHON\CORE\Microsoft.PythonTools.TestAdapter.Executor.dll
    C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\ENTERPRISE\COMMON7\IDE\COMMONEXTENSIONS\MICROSOFT\EBF\TESTEXPLORER\Microsoft.VisualStudio.Workspace.ExternalBuildFramework.TestProvider.dll
[5/10/2021 9:30:47.708 PM] UnitTestExtensionDiscoverer: Found the following Nuget Test Adapter extensions: C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.3\build\net452\xunit.runner.visualstudio.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.3\build\netcoreapp2.1\xunit.runner.visualstudio.dotnetcore.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.3\build\uap10.0.16299\xunit.runner.visualstudio.uwp.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.1\build\netcoreapp1.0\xunit.runner.visualstudio.dotnetcore.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.1\build\uap10.0\xunit.runner.visualstudio.uwp.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.1\build\_common\xunit.runner.visualstudio.testadapter.dll
[5/10/2021 9:30:47.733 PM] Initializing test platform with extensions: C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\ENTERPRISE\COMMON7\IDE\COMMONEXTENSIONS\MICROSOFT\EBF\TESTEXPLORER\Microsoft.VisualStudio.Workspace.ExternalBuildFramework.TestProvider.dll
    C:\PROGRAM FILES (X86)\MICROSOFT VISUAL STUDIO\2019\ENTERPRISE\COMMON7\IDE\EXTENSIONS\MICROSOFT\NODEJSTOOLS\TESTADAPTER\Microsoft.NodejsTools.TestAdapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.1\build\_common\xunit.runner.visualstudio.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.1\build\netcoreapp1.0\xunit.runner.visualstudio.dotnetcore.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.1\build\uap10.0\xunit.runner.visualstudio.uwp.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.3\build\net452\xunit.runner.visualstudio.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.3\build\netcoreapp2.1\xunit.runner.visualstudio.dotnetcore.testadapter.dll
    C:\Users\myUser\.nuget\packages\xunit.runner.visualstudio\2.4.3\build\uap10.0.16299\xunit.runner.visualstudio.uwp.testadapter.dll
[5/10/2021 9:30:47.739 PM] ---------- Starting test discovery for requested test run ----------
[5/10/2021 9:30:47.770 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection 
[5/10/2021 9:30:47.770 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.UserFile value:False
[5/10/2021 9:30:47.770 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.SolutionFile value:False
[5/10/2021 9:30:47.770 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.AutoDetect value:False
[5/10/2021 9:30:47.880 PM] Test assembly C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll references test framework: Xunit2
[5/10/2021 9:30:47.899 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:30:47.899 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:Python Run Settings
[5/10/2021 9:30:47.902 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:30:47.902 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:VSTest Run Configuration
[5/10/2021 9:30:47.903 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:30:47.903 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:Dynamic Code Coverage
[5/10/2021 9:30:47.903 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:30:47.903 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:TestPropertySettingsForBoostAdapter
[5/10/2021 9:30:47.906 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:30:47.906 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:TestPropertySettingsForGoogleAdapter
[5/10/2021 9:30:47.906 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettings 
[5/10/2021 9:30:47.906 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettings key: VS.UnitTest.TestWindow.RunSettings.Services value:5
[5/10/2021 9:30:47.911 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection 
[5/10/2021 9:30:47.912 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.ProjectFileCount value:0
[5/10/2021 9:30:47.912 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.ContainerCount value:1
[5/10/2021 9:30:47.955 PM] Project MyProject.UnitTests references test adapter: xunit.runner.visualstudio, version 2.4.3
[5/10/2021 9:30:47.955 PM] Project MyProject.UnitTests references test adapter: xunit.runner.visualstudio, version 2.4.3
[5/10/2021 9:30:47.955 PM] Project MyProject.UnitTests references test adapter: xunit.runner.visualstudio, version 2.4.3
[5/10/2021 9:30:48.691 PM] Grouped C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll : (AnyCPU, Framework45, net472, )
[5/10/2021 9:30:48.695 PM] Test discovery settings for C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll:
 <RunSettings>
  <Python>
    <TestCases />
  </Python>
  <RunConfiguration>
    <ResultsDirectory>C:\MySolutionFolder\TestResults</ResultsDirectory>
    <SolutionDirectory>C:\MySolutionFolder\</SolutionDirectory>
    <CollectSourceInformation>False</CollectSourceInformation>
  </RunConfiguration>
</RunSettings>.
[5/10/2021 9:30:48.767 PM] Multiple versions of same extension found. Selecting the highest version.
  xunit.runner.visualstudio.testadapter : 2.4.3.1
  xunit.runner.visualstudio.dotnetcore.testadapter : 2.4.3.1
  xunit.runner.visualstudio.uwp.testadapter : 2.4.3.1
[5/10/2021 9:30:49.394 PM] [xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.3+1b45f5407b (32-bit Desktop .NET 4.0.30319.42000)
[5/10/2021 9:30:49.626 PM] [xUnit.net 00:00:00.24]   Discovering: MyProject.UnitTests
[5/10/2021 9:30:49.698 PM] [xUnit.net 00:00:00.31]   Discovered:  MyProject.UnitTests
[5/10/2021 9:30:50.258 PM] Trying to update view -2101946778
[5/10/2021 9:30:50.259 PM] Trying to update view -755572006
[5/10/2021 9:30:50.259 PM] Updating view -755572006
[5/10/2021 9:30:50.261 PM] UpdateSummary Detail Unchanged: SKIPPED
[5/10/2021 9:30:50.636 PM] UpdateSummary Detail Unchanged: SKIPPED
[5/10/2021 9:35:21.125 PM] ---------- Starting test run ----------
[5/10/2021 9:35:21.149 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection 
[5/10/2021 9:35:21.149 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.UserFile value:False
[5/10/2021 9:35:21.149 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.SolutionFile value:False
[5/10/2021 9:35:21.149 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.AutoDetect value:False
[5/10/2021 9:35:21.390 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:35:21.391 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:Python Run Settings
[5/10/2021 9:35:21.391 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:35:21.391 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:VSTest Run Configuration
[5/10/2021 9:35:21.391 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:35:21.391 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:Dynamic Code Coverage
[5/10/2021 9:35:21.391 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:35:21.391 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:TestPropertySettingsForBoostAdapter
[5/10/2021 9:35:21.391 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettingsService 
[5/10/2021 9:35:21.392 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettingsService key: VS.UnitTest.TestWindow.RunSettingsService.Name value:TestPropertySettingsForGoogleAdapter
[5/10/2021 9:35:21.392 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/Ext/RunSettings 
[5/10/2021 9:35:21.392 PM] Event:VS/UnitTest/TestWindow/Ext/RunSettings key: VS.UnitTest.TestWindow.RunSettings.Services value:5
[5/10/2021 9:35:21.392 PM] TelemetrySession: Creating the event: VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection 
[5/10/2021 9:35:21.392 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.ProjectFileCount value:0
[5/10/2021 9:35:21.392 PM] Event:VS/UnitTest/TestWindow/RunSettingsProvider/FileSelection key: VS.UnitTest.TestWindow.RunSettingsProvider.ContainerCount value:1
[5/10/2021 9:35:22.459 PM] Tests run settings for C:\MySolutionFolder\MyProject\test\UnitTests\bin\Debug\MyProject.UnitTests.dll:
 <RunSettings>
  <Python>
    <TestCases />
  </Python>
  <RunConfiguration>
    <ResultsDirectory>C:\MySolutionFolder\TestResults</ResultsDirectory>
    <SolutionDirectory>C:\MySolutionFolder\</SolutionDirectory>
    <CollectSourceInformation>False</CollectSourceInformation>
  </RunConfiguration>
</RunSettings>.
[5/10/2021 9:35:22.572 PM] Multiple versions of same extension found. Selecting the highest version.
  xunit.runner.visualstudio.testadapter : 2.4.3.1
  xunit.runner.visualstudio.dotnetcore.testadapter : 2.4.3.1
  xunit.runner.visualstudio.uwp.testadapter : 2.4.3.1
[5/10/2021 9:35:22.930 PM] Trying to update view -755572006
[5/10/2021 9:35:22.930 PM] Trying to update view -2101946778
[5/10/2021 9:35:22.930 PM] Updating view -755572006
[5/10/2021 9:35:23.156 PM] [xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.3+1b45f5407b (32-bit Desktop .NET 4.0.30319.42000)
[5/10/2021 9:35:23.160 PM] UpdateSummary Detail Unchanged: SKIPPED
[5/10/2021 9:35:23.172 PM] [xUnit.net 00:00:00.36]   Starting:    MyProject.UnitTests
[5/10/2021 9:35:23.198 PM] [xUnit.net 00:00:00.59]   Finished:    MyProject.UnitTests
[5/10/2021 9:35:23.426 PM] UpdateSummary Detail Unchanged: SKIPPED
[5/10/2021 9:35:23.631 PM] Operation Dequeue : 'DiscoverAllOperation'
[5/10/2021 9:35:23.636 PM] Start updating 380 containers.
[5/10/2021 9:35:23.640 PM] Updating containers from Microsoft.VisualStudio.MSTest.TestWindow.OrderedTestContainerDiscoverer.
[5/10/2021 9:35:23.895 PM] Trying to update view -755572006
[5/10/2021 9:35:23.895 PM] Updating view -755572006
[5/10/2021 9:35:23.895 PM] Trying to update view -2101946778
[5/10/2021 9:35:23.898 PM] UpdateSummary Detail Unchanged: SKIPPED

Answer 1

With Test Explorer, there are zero ways to diagnose why something might be taking a long time to start. If VSTest decides that between the time the build is finished, and the test starts should take 10 minutes, it will take 10 minutes, with no indication as to what is going on.