Since SDK 2.2.300 test performance is magnitudes slower

[davidruhmann]

Description

Tests take a long time to run on detached hosts build servers (CircleCI)

Similar issue was closed, but the issue still happens. #2078

Steps to reproduce

Repo which can reproduce the issue https://github.com/davidruhmann/vstest2080

Expected behavior

Tests to complete < 1s

Actual behavior

Tests take over > 20s

Each line of Test run in progress. output takes several seconds while the test takes < 2 ms.

Diagnostic logs

https://circleci.com/gh/davidruhmann/vstest2080/3

Environment

.NET Core SDK (reflecting any global.json):
 Version:   2.2.401
 Commit:    729b316c13

Runtime Environment:
 OS Name:     debian
 OS Version:  9
 OS Platform: Linux
 RID:         debian.9-x64
 Base Path:   /usr/share/dotnet/sdk/2.2.401/

Host (useful for support):
  Version: 2.2.6
  Commit:  7dac9b1b51

.NET Core SDKs installed:
  2.2.401 [/usr/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.2.6 [/usr/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.2.6 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.2.6 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

[ShreyasRmsft]

@davidruhmann does this repro on your local devbox as well?

[JSkimming]

@davidruhmann Try separating the package restore and build from the test steps. you're doing all three in a single step that takes 27 seconds; I usually do something like the following:

dotnet restore
dotnet build --no-restore
dotnet test --no-restore --no-build

If you do this in distinct CirlceCI steps it will give you a more accurate reflection of where the time is being taken.

[davidruhmann]

@JSkimming separated steps as requested to show that dotnet test is super slow by itself.

https://circleci.com/gh/davidruhmann/vstest2080/7

Note, this is just a repro of the issue, this is affecting production builds at the company I work with. Running hundreds of tests that should take seconds, take 5+ minutes on those projects. And only on versions of the SDK since 2.2.300.

[davidruhmann]

@ShreyasRmsft Yes, I can reproduce the issue locally with running tests in docker (with the TTY flag -t). Added a dockerfile to the repo and README instructions.

https://github.com/davidruhmann/vstest2080

[JSkimming]

@davidruhmann I've created a PR (davidruhmann/vstest2080#3) to test against previous SDK releases, and I'm finding no real difference, certainly not on a different magnitude.

[davidruhmann]

@JSkimming Thank you for taking a look!

I do see a difference both using docker and on CircleCI when using 2.2.204 vs 2.2.401.

branch 2.2.204 vs master

Docker
using 2.2.204 it takes 4s
using 2.2.401/latest it takes 26s

CircleCI
using 2.2.204 it takes 3s to run the test step
https://circleci.com/gh/davidruhmann/vstest2080/11
using 2.2.401/latest it takes 24s
https://circleci.com/gh/davidruhmann/vstest2080/10

I will work on capture some screen recordings to show the issue visually.

[davidruhmann]

For some more context, here are more reports of this issue on CircleCI's board.
https://discuss.circleci.com/t/dotnet-core-testing-randomly-times-out/30492

[JSkimming]

@davidruhmann This looks a lot like the issue I had originally in CircleCI. Looking at the output, the step that takes 24 seconds reports to only take 1.5117 seconds.

Starting test execution, please wait...
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.1 (64-bit .NET Core 4.6.27817.03)
Test run in progress.[xUnit.net 00:00:00.47]   Discovering: Example.Library.Tests
Test run in progress.[xUnit.net 00:00:00.53]   Discovered:  Example.Library.Tests
Test run in progress.[xUnit.net 00:00:00.54]   Starting:    Example.Library.Tests
Test run in progress.[xUnit.net 00:00:00.69]   Finished:    Example.Library.Tests
Test run in progress.  √ Example.Library.Tests.UnitTest1.Test2 [7ms]
Test run in progress.  √ Example.Library.Tests.UnitTest1.Test5 [1ms]
Test run in progress.  √ Example.Library.Tests.UnitTest1.Test3 [1ms]
Test run in progress.  √ Example.Library.Tests.UnitTest1.Test4 [1ms]
Test run in progress.  √ Example.Library.Tests.UnitTest1.Test1 [1ms]
Test run in progress.
Test Run Successful.
Total tests: 5
     Passed: 5
 Total time: 1.5117 Seconds
     1>Done Building Project "/root/workspace/vstest2080.sln" (VSTest target(s)).

The discrepancy when running in docker is strange, as I don't get that at all.

What happens if you don't use -v n, as verbose logging was the issue I originally received and added a fix with PR #2024.

[JSkimming]

@davidruhmann a further enhancement I was thinking about to #2024 was not to show the progress indicator if the environment variable CI had any value. Several CI systems use that convention.

Maybe you could investigate that as an option.

[davidruhmann]

@JSkimming Correct, if I do not use -v n on 2.2.401 then it is fast as 2.2.204.
https://circleci.com/gh/davidruhmann/vstest2080/14

However, I would not categorize that as a resolution.

[davidruhmann]

So you think, not showing a progress indicator might fix the issue?

[JSkimming]

However, I would not categorize that as a resolution.

Agreed, but it narrows down the potential causes, and I suspect the progress indicator is the culprit.

So you think, not showing a progress indicator might fix the issue?

Yup, but I don't think it can be disabled using cli options.

[davidruhmann]

@JSkimming Thank you for the quick replies! Let me know if I can help diagnose it further.

[JSkimming]

@davidruhmann I think you should consider submitting a PR as I did 😃

[davidruhmann]

Just found this PR while looking through the source that adds a noprogess parameter
#2117
and associated issue
#2106

Will look at creating a PR that sets DisableProgress to true when environment variable CI=true.

[JSkimming]

Just a suggestion, but a check for the environment variable being anything other than empty or "false" (case insensitive) would be more robust.

[davidruhmann]

That is an interesting thought. What constitutes the default.

Normal Environment no CI defined.
CI Environment assume CI defined. what values should be accepted? truthy? 0/1/true/false? any?

• AppVeyor uses True https://www.appveyor.com/docs/environment-variables/
• TravisCI uses true https://docs.travis-ci.com/user/environment-variables/#default-environment-variables
• CircleCI uses true https://circleci.com/docs/2.0/env-vars/#built-in-environment-variables
• GitHub Actions unknown, not documented, untested https://developer.github.com/actions/creating-github-actions/accessing-the-runtime-environment/#environment-variables
• Jenkins not defined https://issues.jenkins-ci.org/browse/JENKINS-36707
• CodeShip unkonwn, not documented, untested https://documentation.codeship.com/pro/builds-and-configuration/environment-variables/#default-environment-variables

[davidruhmann]

Personally I lean towards having invalid boolean value ignored. CI can be 0|1|true|false/i

[JSkimming]

I was thinking that the convention of setting CI environment variable may not be followed well, say CI=NameOfCIService though it's an edge case.

[ShreyasRmsft]

@JSkimming it is indeed strange that the progress indicator is causing slowness. Could it be that IO is bottlenecked? Just a thought. We will look into this.

Thanks a lot for diagnosing the issue.

[martincostello]

This has regressed as per #2078 in the .NET Core 3.0 SDK since preview 7 as well. A test run in Travis CI that writes to the log that it takes 3 seconds to run the tests for takes about 15 minutes to complete.

Again it appears that lots of time is being wasted writing Test run in progress. to the console.

Examples below using 3.0.100-preview9-013994:

• https://travis-ci.com/martincostello/sqllocaldb/jobs/227942006
• https://travis-ci.com/martincostello/sqllocaldb/jobs/227942005
• https://travis-ci.org/martincostello/sqllocaldb/jobs/576211137
• https://travis-ci.org/martincostello/sqllocaldb/jobs/576211136

Contrast with the same commit built in Azure DevOps and AppVeyor:

• https://martincostello.visualstudio.com/sqllocaldb/_build/results?buildId=2311
• https://ci.appveyor.com/project/martincostello/sqllocaldb/builds/26932620

[martincostello]

Can workaround the issue by specifying the following parameter to dotnet test:

'--logger:Console;noprogress=true'

[nohwnd]

There is no progress indicator anymore.