Answers: <p>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 <code>Search folder</code>.</p>
  
  <p>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.</p>
  
Answers: CC BY-SA 4.0
Answers: 2019-10-03T12:33:51.483Z
Answers: 2019-10-03T12:33:51.483Z
Answers: urig
Body: <p>In an <a href="https://azure.microsoft.com/en-in/services/devops/server/" rel="nofollow noreferrer">Azure DevOps Server</a> build system installed on premises, I have a Build Pipeline with a <a href="https://docs.microsoft.com/en-us/azure/devops/pipelines/tasks/test/vstest?view=azure-devops" rel="nofollow noreferrer">Visual Studio Test step</a>. The step is configured to discover and run <a href="https://xunit.org/" rel="nofollow noreferrer">XUnit</a> unit tests in a DLL.</p>
  
  <p>The step is defined via the GUI. Here are its properties:</p>
  
  <pre><code>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
  </code></pre>
  
  <p>The step runs and passes successfully, identifying 18 tests. However, it's taking an unreasonable time to do so: ~51 seconds.</p>
  
  <p>The run logs show that it's spending about 40 seconds right before launching <code>vstest.console.exe</code>, seemingly doing nothing. Please see this line in the full log, below:</p>
  
  <pre><code>2019-09-23T07:11:35.7961563Z ========================================================
  </code></pre>
  
  <p><strong>My Question</strong> - Why does the Visual Studio Test step spend so much time idling? What can I do to make it waste less time?</p>
  
  <hr>
  
  <pre><code>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&amp;_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
  </code></pre>
  
Comments: CC BY-SA 4.0
Comments: 2019-09-23T13:34:22.963Z
Comments: My guess would be that it is provisioning resources for the unit test step. Do subsequent runs of the step take less time than the initial run?
Comments: Preston Martin
Comments: CC BY-SA 4.0
Comments: 2019-09-23T13:37:31.763Z
Comments: @PrestonM thanks. No, subsequent runs yield near identical run times.
Comments: urig
Comments: CC BY-SA 4.0
Comments: 2019-09-23T13:41:13.417Z
Comments: Can you add your pipeline file to the question?
Comments: Preston Martin
Comments: CC BY-SA 4.0
Comments: 2019-09-23T14:07:30.770Z
Comments: @PrestonM it's defined in GUI so I did the next thing and listed the GUI property values
Comments: urig
Tags: <azure-devops><testing><unit-testing>
Title: Azure DevOps Server: Why does a Visual Studio Test step take so long to run unit tests?
UserDisplayName: urig
ThreadText: # Azure DevOps Server: Why does a Visual Studio Test step take so long to run unit tests?
  
  (Asked by: username_0 on 2019-09-23)
  
  In an [Azure DevOps Server](https://azure.microsoft.com/en-in/services/devops/server/) build system installed on premises, I have a Build Pipeline with a [Visual Studio Test step](https://docs.microsoft.com/en-us/azure/devops/pipelines/tasks/test/vstest?view=azure-devops). The step is configured to discover and run [XUnit](https://xunit.org/) 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?
  
  ---
  
  ```
  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
  
  ```
  
  **Tags:** azure-devops, testing, unit-testing
  
  > **Comments:**
  > **username_1**: My guess would be that it is provisioning resources for the unit test step. Do subsequent runs of the step take less time than the initial run?  
  > **username_0**: @PrestonM thanks. No, subsequent runs yield near identical run times.  
  > **username_1**: Can you add your pipeline file to the question?  
  > **username_0**: @PrestonM it's defined in GUI so I did the next thing and listed the GUI property values  
  
  ---
  
  ## 1 answers
  
  ### Answer by username_0 on 2019-10-03. Score: 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.
  
  
  ---
  
  