Azure DevOps Server: Why does a Visual Studio Test step take so long to run unit tests?

Question

In an Azure DevOps Server build system installed on premises, I have a Build Pipeline with a Visual Studio Test step. The step is configured to discover and run XUnit unit tests in a DLL.

The step is defined via the GUI. Here are its properties:

Version: 2.*
Select tests using: Test assemblies
Test files:
    **\*test*.dll
    !**\*TestAdapter.dll
    !**\obj\**
Search folder: $(System.DefaultWorkingDirectory)
Select test platform using: Version
Test platform version: Latest

The step runs and passes successfully, identifying 18 tests. However, it's taking an unreasonable time to do so: ~51 seconds.

The run logs show that it's spending about 40 seconds right before launching vstest.console.exe, seemingly doing nothing. Please see this line in the full log, below:

2019-09-23T07:11:35.7961563Z ========================================================

My Question - Why does the Visual Studio Test step spend so much time idling? What can I do to make it waste less time?

UPDATE 1: As an experiment, I created a new git repo that only contains the (~100) DLLs that my solutions build. I created a new pipeline that only pulls these DLLs and runs the unit tests. When I ran this, it ran much faster. Specifically the two lines in the log that originally took 40 seconds now took less than a second.

UPDATE 2: I tried to speed things up by specifying the full path to the tests DLL and removing all ** patterns from the 'Test files' property. The step still runs slow as before.

---

2019-09-23T07:11:32.4121152Z ##[section]Starting: run unit tests
2019-09-23T07:11:32.4135871Z ==============================================================================
2019-09-23T07:11:32.4136477Z Task         : Visual Studio Test
2019-09-23T07:11:32.4136755Z Description  : Run unit and functional tests (Selenium, Appium, Coded UI test, etc.) using the Visual Studio Test (VsTest) runner. Test frameworks that have a Visual Studio test adapter such as MsTest, xUnit, NUnit, Chutzpah (for JavaScript tests using QUnit, Mocha and Jasmine), etc. can be run. Tests can be distributed on multiple agents using this task (version 2).
2019-09-23T07:11:32.4137066Z Version      : 2.143.8
2019-09-23T07:11:32.4137295Z Author       : Microsoft Corporation
2019-09-23T07:11:32.4137526Z Help         : [More information](https://go.microsoft.com/fwlink/?LinkId=835764)
2019-09-23T07:11:32.4138042Z ==============================================================================
2019-09-23T07:11:35.0894195Z SystemVssConnection exists true
2019-09-23T07:11:35.0937440Z SystemVssConnection exists true
2019-09-23T07:11:35.2406351Z Running tests using vstest.console.exe runner.
2019-09-23T07:11:35.2407337Z ======================================================
2019-09-23T07:11:35.2408408Z Test selector : Test assemblies
2019-09-23T07:11:35.2409125Z Test filter criteria : null
2019-09-23T07:11:35.2409694Z Search folder : C:\pool\_work\238\s
2019-09-23T07:11:35.2412135Z VisualStudio version selected for test execution : latest
2019-09-23T07:11:35.2758339Z Run in parallel : false
2019-09-23T07:11:35.2810059Z Run in isolation : false
2019-09-23T07:11:35.2813902Z Path to custom adapters : null
2019-09-23T07:11:35.2831140Z Other console options : null
2019-09-23T07:11:35.2883526Z Code coverage enabled : false
2019-09-23T07:11:35.2884892Z Diagnostics enabled : false
2019-09-23T07:11:35.2937817Z SystemVssConnection exists true
2019-09-23T07:11:35.3039161Z Run the tests locally using vstest.console.exe
2019-09-23T07:11:35.3040102Z ========================================================
2019-09-23T07:11:35.3075806Z Test selector : Test assemblies
2019-09-23T07:11:35.3094635Z Test assemblies : **\*test*.dll,!**\*TestAdapter.dll,!**\obj\**
2019-09-23T07:11:35.3095999Z Test filter criteria : null
2019-09-23T07:11:35.3114780Z Search folder : C:\pool\_work\238\s
2019-09-23T07:11:35.3125782Z Run settings file : C:\pool\_work\238\s
2019-09-23T07:11:35.3144368Z Run in parallel : false
2019-09-23T07:11:35.3158394Z Run in isolation : false
2019-09-23T07:11:35.3243577Z Path to custom adapters : null
2019-09-23T07:11:35.3244967Z Other console options : null
2019-09-23T07:11:35.3269743Z Code coverage enabled : false
2019-09-23T07:11:35.3273300Z Diagnostics enabled : false
2019-09-23T07:11:35.3286973Z Rerun failed tests: false
2019-09-23T07:11:35.3308152Z VisualStudio version selected for test execution : latest
2019-09-23T07:11:35.7961563Z ========================================================
2019-09-23T07:11:50.3641983Z ======================================================
2019-09-23T07:12:16.2956956Z [command]"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe" @C:\pool\_work\_temp\60ff2cb1-ddd1-11e9-a3ed-db0a48eb3ef5.txt
2019-09-23T07:12:16.9940929Z Microsoft (R) Test Execution Command Line Tool Version 15.9.0
2019-09-23T07:12:16.9941829Z Copyright (c) Microsoft Corporation.  All rights reserved.
2019-09-23T07:12:16.9942101Z 
2019-09-23T07:12:16.9942399Z vstest.console.exe 
2019-09-23T07:12:16.9942679Z "C:\pool\_work\238\s\REDACTED\bin\Release\REDACTED.Tests.dll"
2019-09-23T07:12:16.9942954Z /logger:"trx"
2019-09-23T07:12:16.9943238Z /TestAdapterPath:"C:\pool\_work\238\s"
2019-09-23T07:12:17.6998070Z Starting test execution, please wait...
2019-09-23T07:12:20.5147395Z [xUnit.net 00:00:00.6296658]   Discovering: REDACTED.Tests
2019-09-23T07:12:20.6880418Z [xUnit.net 00:00:00.8113825]   Discovered:  REDACTED.Tests
2019-09-23T07:12:20.6955571Z [xUnit.net 00:00:00.8192449]   Starting:    REDACTED.Tests
2019-09-23T07:12:21.9022641Z Passed   REDACTED 1
2019-09-23T07:12:21.9024375Z Passed   REDACTED 2
2019-09-23T07:12:21.9024811Z Passed   REDACTED 3
2019-09-23T07:12:21.9025086Z Passed   REDACTED 4
2019-09-23T07:12:21.9025460Z Passed   REDACTED 5
2019-09-23T07:12:21.9026429Z Passed   REDACTED 6
2019-09-23T07:12:21.9027211Z Passed   REDACTED 7
2019-09-23T07:12:21.9027581Z Passed   REDACTED 8
2019-09-23T07:12:21.9027938Z Passed   REDACTED 9
2019-09-23T07:12:21.9028266Z [xUnit.net 00:00:01.9910390]   Finished:    REDACTED.Tests
2019-09-23T07:12:22.3918748Z Passed   REDACTED 10
2019-09-23T07:12:22.3920336Z Passed   REDACTED 11
2019-09-23T07:12:22.3920912Z Passed   REDACTED 12
2019-09-23T07:12:22.3922185Z Passed   REDACTED 13
2019-09-23T07:12:22.3923090Z Passed   REDACTED 14
2019-09-23T07:12:22.3925098Z Passed   REDACTED 15
2019-09-23T07:12:22.3926473Z Passed   REDACTED 16
2019-09-23T07:12:22.3928334Z Passed   REDACTED 17
2019-09-23T07:12:22.3930288Z Passed   REDACTED 18
2019-09-23T07:12:22.4707999Z Results File: C:\pool\_work\238\s\TestResults\REDACTED_2019-09-23_10_12_21.trx
2019-09-23T07:12:22.4743977Z 
2019-09-23T07:12:22.4746692Z Total tests: 18. Passed: 18. Failed: 0. Skipped: 0.
2019-09-23T07:12:22.4748446Z Test Run Successful.
2019-09-23T07:12:22.4764305Z Test execution time: 2.7962 Seconds
2019-09-23T07:12:23.0702219Z ##[section]Async Command Start: Publish test results
2019-09-23T07:12:23.3336706Z Publishing test results to test run '432'
2019-09-23T07:12:23.3338983Z Test results remaining: 18. Test run id: 432
2019-09-23T07:12:24.1461381Z Published Test Run : http://REDACTED/Runs#runId=432&_a=runCharts
2019-09-23T07:12:24.1474239Z ##[section]Async Command End: Publish test results
2019-09-23T07:12:24.1476508Z ##[section]Finishing: run unit tests

Answer 1

The root cause turned out to be that there were over 100,000 files for the Visual Studio Step to scan for tests, in the Search folder.

To resolve, I pointed the search folder to a more specific bin folder down the folder tree. This reduced the number of files scanned and dramatically shortened the overall run time for the step.