2

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
urig
  • 16,016
  • 26
  • 115
  • 184
  • Did it take about 40s long every time? – Levi Lu-MSFT Sep 24 '19 at 12:53
  • @levi-lu-msft thanks. Yes, it does take the same amount of time on every run. Plus I just added an UPDATE to the question. – urig Sep 25 '19 at 12:42
  • You can turn the `system.debug` on to check the details about what vstest was actually doing, It looked like that searching for the test.dlls against the source filter holds back the execution. You can try to narrow down the search folder to `bin/release` folder or specify the detailed test dll files location to save the time. eg.`$(System.DefaultWorkingDirectory)\**\$(BuildConfiguration)\*Test*.dll` – Levi Lu-MSFT Sep 26 '19 at 11:45
  • @LeviLu-MSFT thanks. Please see my "UPDATE 2". I removed `**` patterns and replaced with exact path to tests DLL. Still runs slow. Will now try to enable debug logs and will report back. – urig Sep 26 '19 at 13:19
  • I see you run these tests on your self-hosted agents,You can try running them on a different agent or microsoft-hosted agents to check if it is cased by your agent's low performance. – Levi Lu-MSFT Sep 27 '19 at 08:28

1 Answers1

2

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.

urig
  • 16,016
  • 26
  • 115
  • 184
  • Nice one, I can verify that being more specific with test assembly paths drastically reduces test execution time in Azure Devops pipelines. – DvS Aug 10 '22 at 16:13