Vstest: dotnet test is significantly slower compared to what was available with project.json.

Created on 18 Jan 2017  路  31Comments  路  Source: microsoft/vstest

Description

I believed to see slow downs in dotnet test before and after csproj conversions. I took the Security repo and decided to measure the differences on a simple test project (~220 tests). Ended up for the test project I tried (didn't try others) there was a 6x increase in execution time after converting to csproj.

Steps to reproduce

  • git clone [email protected]:aspnet/Security.git
  • cd Security
  • ./build initialize
  • cd .\test\Microsoft.AspNetCore.Authentication.Test\
  • dotnet test (this is to ensure everything is warm)
  • measure-command {dotnet test}

You get csproj numbers

  • cd ..\..\
  • git clean -xdff
  • git checkout 7ab28ecdc60a565e467bd911f4cd556d780c92f9 (commit before conversion)
  • ./build initialize
  • cd .\test\Microsoft.AspNetCore.Authentication.Test\
  • dotnet test (this is to ensure everything is warm)
  • measure-command {dotnet test}

You get project.json numbers

Expected behavior

Similar timing results between project.json and csproj.

Actual behavior

Nearly a 6x increase in execution time when dotnet testing in csproj.

Here's a table of timings I did for the security test project mentioned above:

| | project.json | csproj |
| ------------- | ------------- | ------------- |
| net451 | 2.8s | 16.5s |
| netcoreapp1.1 | 3.6s | 16s |
| both | 5.6s | 31.8s |

Environment Project.json

.NET Command Line Tools (1.0.0-preview2-1-003180)

Product Information:
Version: 1.0.0-preview2-1-003180
Commit SHA-1 hash: 5fbbb40658

Runtime Environment:
OS Name: Windows
OS Version: 10.0.14393
OS Platform: Windows
RID: win10-x64

Environment csproj

.NET Command Line Tools (1.0.0-preview4-004233)

Product Information:
Version: 1.0.0-preview4-004233
Commit SHA-1 hash: 8cec61c6f7

Runtime Environment:
OS Name: Windows
OS Version: 10.0.14393
OS Platform: Windows
RID: win10-x64
Base Path: C:UsersnimullenAppData\Local\Microsoft\dotnet\sdk1.0.0-preview4-004233

blocking-partner perf
Source
picture NTaylorMullen
👍2

Most helpful comment

Remove extra appdomain creation for getting source info using DiaSession

This can't be done without breaking VS <= 2015.

Batching to reduce cross-appdomain communication

Can you explain this?

Cost due to conversion of XUnitTestCase to VSTestCase (MarshalByRef object)

The Visual Studio runner (on which dotnet test is based on now in MSBuild-land, but wasn't previously in project.json-land) has always been agonizingly slow compared to every other environment. The multi-process design, with the need to serialize test cases, is just brutal for performance. We have actively steered people away from using it pretty much since we shipped 2.0. The fact that it's at the core of dotnet test is unfortunate in this respect, and it seems unlikely that you're going to be able to fix what is fundamentally a design flaw that dates back to 2012.

Our solution for this is: We intend to write a new dotnet command (dotnet xunit), and once that's available, tell people to stop using dotnet test. This will solve not only the poor performance issues, but also the fact that dotnet test is nowhere near as usable or feature rich as our other custom runners (as well as stops forcing people to opt into the Test Explorer integration even if all they cared about is command line test execution).

picture bradwilson on 16 Feb 2017
👍2

All 31 comments

@NTaylorMullen I looked into this a bit and found that it is very likely caused by the SDK's <Target Name="Build" perf. Most of the time spent running test is actually in the build incrementality check...

TheRealPiotrP picture TheRealPiotrP on 19 Jan 2017

How does dotnet test --no-build compare?

natemcmaster picture natemcmaster on 19 Jan 2017

How does dotnet test --no-build compare?

csproj 14.4s
project.json 4.7s

NTaylorMullen picture NTaylorMullen on 20 Jan 2017

We're seeing about a 10x increase in test execution time in Kestrel.

cesarblum picture cesarblum on 4 Feb 2017
😕1

Have you tried using the /Parallel flag to see if it affects performance? I've tried but it doesn't appear to change perf. e.g. dotnet test -- /Parallel.

Side note: I'm not sure this is the right syntax. It shows up in dotnet-vstest help output.

natemcmaster picture natemcmaster on 7 Feb 2017

I took a look with PerfView and noticed a number of problems.

  1. I couldn't actually get the netcoreapp1.1 tests to run. These kept failing for me with "Error: Failed to initialize client proxy: could not connect to test process." I assume there's some bits cobbled on my machine causing this failure, so I didn't spend anytime investigating. Instead, I just passed -f net451 to dotnet test.
  2. As noted by others, build takes a big chunk of the time. Passing --no-build addresses this.
  3. The tests do run slower, and it appears that a lot of this is in the xUnit test adapter itself.

dotnet test --no-build -f net451 = 7.95 seconds

From PerfView, it looked like another chunk of time was being spent in cross-AppDomain communication. Knowing that xUnit will use AppDomains if they're availabe, I added an XML config file next to the test dll named 'Microsoft.AspNetCore.Authentication.Test.dll.config' with the following content.

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <appSettings>
    <add key="xunit.appDomain" value="denied"/>
  </appSettings>
</configuration>

That shaved off a ~1/3 of the time. The difference in the speed of the console output was visually noticable.

dotnet test --no-build -f net451 = 5.25 seconds

That's at least getting closer.

DustinCampbell picture DustinCampbell on 10 Feb 2017
👍1

Hmmm... I came into the office this morning and could not get the netcoreapp1.1 tests to run on a completely fresh machine (no .NET bits prior to install VS 2017 RC4). Same "could not connect to test process" message. Is anyone else seeing this?

DustinCampbell picture DustinCampbell on 10 Feb 2017

@piotrpMSFT: Do you know anything about the problem I'm seeing with running "dotnet test" on the netcoreapp1.1 tests above? I'm wondering if there's a regression here.

DustinCampbell picture DustinCampbell on 10 Feb 2017

I guess that's because of https://github.com/Microsoft/vstest/issues/281.

DustinCampbell picture DustinCampbell on 10 Feb 2017

@DustinCampbell the Failzed to initialize proxy is mostly due to missing shared runtime. Can you try these steps:

  • Run dotnet test -d:log.txt
  • In the log.txt file generated, find the command line of dotnet exe invocation (search for exec or `dotnet)
  • Copy the command line and run it directly in command prompt
  • You will see an error message on which shared runtime version is missing. Install it from https://www.microsoft.com/net/download/core#/runtime
codito picture codito on 11 Feb 2017

@natemcmaster --parallel is at assembly level, it will not help since vstest task only runs one assembly at a time (via msbuild).

It should be possible to disable appdomains with dotnet test -- runconfiguration.disableappdomain=true.

codito picture codito on 11 Feb 2017

I believe @Shyam-Gupta @sbaid are looking at ways to reduce the cross appdomain cost in xunit adapter.

codito picture codito on 11 Feb 2017

@codito: I'm not getting an error about a shared framework being missing at all. At least, if I am, it's so obscured that I'm not able to find it. I only see errors about failing to resolve various assemblies, which look like full framework assemblies instead of .NET Core. Here's the first half of the log where it tries to run the tests under netcoreapp1.1.

TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:11.948, 412457791313, vstest.console.dll, TestPluginCache: Discovering the extensions using extension path.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:37:11.977, 412457847709, vstest.console.dll, AssemblyResolver: Microsoft.VisualStudio.TestPlatform.Extensions.TrxLogger: Resolving assembly.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:37:11.979, 412457851462, vstest.console.dll, AssemblyResolver: Microsoft.VisualStudio.TestPlatform.Extensions.TrxLogger: Resolved assembly. 
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:11.984, 412457863085, vstest.console.dll, TestPluginCache: Discovered the extensions using extension path ''.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:11.985, 412457865887, vstest.console.dll, TestPluginCache: Discoverers are ''.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:11.986, 412457866662, vstest.console.dll, TestPluginCache: Executors are ''.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:11.986, 412457866769, vstest.console.dll, TestPluginCache: Setting providers are ''.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:11.986, 412457866834, vstest.console.dll, TestPluginCache: Loggers are 'logger://Microsoft/TestPlatform/TrxLogger/v2'.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:37:12.011, 412457920473, vstest.console.dll, RunTestsArgumentProcessor:Execute: Test run is starting.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.030, 412457961601, vstest.console.dll, Using effective platform:X86 effective framework:.NETCoreApp,Version=v1.1
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.054, 412458015036, vstest.console.dll, RunTestsArgumentProcessor:Execute: Queuing Test run.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.069, 412458047681, vstest.console.dll, TestEngine: Initializing Parallel Execution as MaxCpuCount is set to: 1
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.087, 412458085547, vstest.console.dll, TestRunRequest.ExecuteAsync: Creating test run request.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.090, 412458092967, vstest.console.dll, TestRunRequest.ExecuteAsync: Starting.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:37:12.091, 412458094858, vstest.console.dll, TestRunRequest.ExecuteAsync: Starting run with settings:TestRunCriteria:
   KeepAlive=False,FrequencyOfRunStatsChangeEvent=10,RunStatsChangeEventTimeout=00:00:01.5000000,TestCaseFilter=,TestExecutorLauncher=
   Settingsxml=<RunSettings>
  <RunConfiguration>
    <ResultsDirectory>C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\TestResults</ResultsDirectory>
    <TargetPlatform>X86</TargetPlatform>
    <TargetFrameworkVersion>.NETCoreApp,Version=v1.1</TargetFrameworkVersion>
  </RunConfiguration>
</RunSettings>

TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.091, 412458094997, vstest.console.dll, TestRunRequest.ExecuteAsync: Wait for the first run request is over.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:37:12.095, 412458103200, vstest.console.dll, TestRunRequest.ExecuteAsync: Started.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:37:12.096, 412458104560, vstest.console.dll, TestRunRequest.WaitForCompletion: Waiting with timeout -1.
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:37:12.097, 412458107661, vstest.console.dll, ProxyParallelExecutionManager: Triggering test run for next source: C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.dll
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.099, 412458112450, vstest.console.dll, ProxyExecutionManager: Test host is non shared. Lazy initialize.
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:37:12.136, 412458192400, vstest.console.dll, Listening on port : 29249
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.151, 412458223082, vstest.console.dll, DotnetTestHostmanager: Full path of dotnet.exe is C:\Program Files\dotnet\dotnet.exe
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.151, 412458223590, vstest.console.dll, DotnetTestHostmanager: Adding  --runtimeconfig "C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.runtimeconfig.json" in args
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.151, 412458223939, vstest.console.dll, DotnetTestHostmanager: Adding  --depsfile "C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.deps.json" in args
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.157, 412458237318, vstest.console.dll, DotnetTestHostmanager: Reading file C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.deps.json to get path of testhost.dll
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.216, 412458365455, vstest.console.dll, DotnetTestHostmanager: Relative path of testhost.dll with respect to package folder is microsoft.testplatform.testhost/15.0.0-preview-20170125-04\lib/netstandard1.5/testhost.dll
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.230, 412458395524, vstest.console.dll, DotnetTestHostmanager: Looking for path microsoft.testplatform.testhost/15.0.0-preview-20170125-04\lib/netstandard1.5/testhost.dll in folder C:\Users\dusti\.nuget\packages
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.231, 412458395998, vstest.console.dll, DotnetTestHostmanager: Full path of testhost.dll is C:\Users\dusti\.nuget\packages\microsoft.testplatform.testhost/15.0.0-preview-20170125-04\lib/netstandard1.5/testhost.dll
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:37:12.232, 412458398739, vstest.console.dll, ProcessHelper: Starting process 'C:\Program Files\dotnet\dotnet.exe' with command line 'exec --runtimeconfig "C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.runtimeconfig.json" --depsfile "C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.deps.json" "C:\Users\dusti\.nuget\packages\microsoft.testplatform.testhost/15.0.0-preview-20170125-04\lib/netstandard1.5/testhost.dll" --port 29249 --parentprocessid 436 --diag log.host.17-02-11_02-37-12_14546_5.txt'
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:38:12.243, 412587798603, vstest.console.dll, AssemblyResolver: Microsoft.TestPlatform.CrossPlatEngine.resources: Resolving assembly.
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:38:12.244, 412587799833, vstest.console.dll, AssemblyResolver: Microsoft.TestPlatform.CrossPlatEngine.resources: Resolving assembly.
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:38:12.245, 412587802050, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:38:12.247, 412587806700, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Information: 0 : 436, 3, 2017/02/11, 02:38:12.249, 412587811806, vstest.console.dll, AssemblyResolver: Microsoft.TestPlatform.CoreUtilities.resources: Resolving assembly.
TpTrace Information: 0 : 436, 3, 2017/02/11, 02:38:12.250, 412587812555, vstest.console.dll, AssemblyResolver: Microsoft.TestPlatform.CoreUtilities.resources: Resolving assembly.
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:38:12.457, 412588258686, vstest.console.dll, AssemblyResolver: System.Core: Resolving assembly.
TpTrace Verbose: 0 : 436, 5, 2017/02/11, 02:38:12.485, 412588318589, vstest.console.dll, TestRunRequest:TestRunComplete: Starting. IsAborted:False IsCanceled:False.
TpTrace Information: 0 : 436, 5, 2017/02/11, 02:38:12.489, 412588328411, vstest.console.dll, TestRunRequest:TestRunComplete: Completed.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:38:12.492, 412588333599, vstest.console.dll, TestRunRequest.Dispose: Starting.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:38:12.492, 412588333837, vstest.console.dll, TestRunRequest.Dispose: Completed.
TpTrace Information: 0 : 436, 1, 2017/02/11, 02:38:12.492, 412588333892, vstest.console.dll, RunTestsArgumentProcessor:Execute: Test run is completed.
TpTrace Verbose: 0 : 436, 1, 2017/02/11, 02:38:12.492, 412588334067, vstest.console.dll, Executor.Execute: Exiting with exit code of 1
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.699, 412588782846, vstest.console.dll, TestPluginCache: Discovering the extensions using extension path.
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.722, 412588830565, vstest.console.dll, AssemblyResolver: Microsoft.VisualStudio.TestPlatform.Extensions.TrxLogger: Resolving assembly.
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.724, 412588834191, vstest.console.dll, AssemblyResolver: Microsoft.VisualStudio.TestPlatform.Extensions.TrxLogger: Resolved assembly. 
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.729, 412588845561, vstest.console.dll, AssemblyResolver: xunit.runner.visualstudio.testadapter: Resolving assembly.
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.730, 412588846856, vstest.console.dll, AssemblyResolver: xunit.runner.visualstudio.testadapter: Resolved assembly. 
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.730, 412588847418, vstest.console.dll, AssemblyResolver: xunit.runner.utility.desktop: Resolving assembly.
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.731, 412588848637, vstest.console.dll, AssemblyResolver: xunit.runner.utility.desktop: Resolved assembly. 
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.732, 412588850741, vstest.console.dll, AssemblyResolver: System.Core: Resolving assembly.
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.733, 412588852784, vstest.console.dll, CurrentDomain_AssemblyResolve: Resolving assembly 'System.Core'.
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.733, 412588853167, vstest.console.dll, AssemblyResolver: System.Core: Resolving assembly.
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.733, 412588853461, vstest.console.dll, CurrentDomain_AssemblyResolve: Resolving assembly 'System.Core'.
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.733, 412588853552, vstest.console.dll, CurrentDomainAssemblyResolve: Failed to resolve assembly 'System.Core'.
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.734, 412588854631, vstest.console.dll, CurrentDomainAssemblyResolve: Failed to resolve assembly 'System.Core'.
TpTrace Information: 0 : 2916, 1, 2017/02/11, 02:38:12.746, 412588881108, vstest.console.dll, AssemblyResolver: System.Core: Resolving assembly.
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.746, 412588881560, vstest.console.dll, CurrentDomain_AssemblyResolve: Resolving assembly 'System.Core'.
TpTrace Verbose: 0 : 2916, 1, 2017/02/11, 02:38:12.746, 412588881644, vstest.console.dll, CurrentDomainAssemblyResolve: Failed to resolve assembly 'System.Core'.
TpTrace Warning: 0 : 2916, 1, 2017/02/11, 02:38:12.756, 412588902498, vstest.console.dll, TestPluginDiscoverer: Failed to get types from assembly 'xunit.runner.visualstudio.testadapter, Version=2.2.0.1225, Culture=neutral, PublicKeyToken=null'.  Skipping test extension scan for this assembly.  Error: System.Reflection.ReflectionTypeLoadException: Unable to load one or more of the requested types. Retrieve the LoaderExceptions property for more information.
   at System.Reflection.RuntimeModule.GetTypes(RuntimeModule module)
   at System.Reflection.Assembly.GetTypes()
   at Microsoft.VisualStudio.TestPlatform.Common.ExtensionFramework.TestPluginDiscoverer.GetTestExtensionsFromAssembly(Assembly assembly, Dictionary`2 testDiscoverers, Dictionary`2 testExecutors, Dictionary`2 testSettingsProviders, Dictionary`2 testLoggers)
TpTrace Warning: 0 : 2916, 1, 2017/02/11, 02:38:12.756, 412588902713, vstest.console.dll, LoaderExceptions: System.TypeLoadException: Could not load type 'System.MarshalByRefObject' from assembly 'mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e'.
TpTrace Warning: 0 : 2916, 1, 2017/02/11, 02:38:12.756, 412588902781, vstest.console.dll, LoaderExceptions: System.TypeLoadException: Could not load type 'System.MarshalByRefObject' from assembly 'mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e'.
TpTrace Warning: 0 : 2916, 1, 2017/02/11, 02:38:12.756, 412588902964, vstest.console.dll, LoaderExceptions: System.IO.FileNotFoundException: Could not load file or assembly 'System.Core, Version=3.5.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089'. The system cannot find the file specified.
File name: 'System.Core, Version=3.5.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089'
TpTrace Warning: 0 : 2916, 1, 2017/02/11, 02:38:12.756, 412588903042, vstest.console.dll, LoaderExceptions: System.TypeLoadException: Could not load type 'System.MarshalByRefObject' from assembly 'mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e'.
DustinCampbell picture DustinCampbell on 11 Feb 2017

If shared runtime is missing, following command should show an error message:

'C:\Program Files\dotnet\dotnet.exe' exec --runtimeconfig "C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.runtimeconfig.json" --depsfile "C:\Projects\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\netcoreapp1.1\Microsoft.AspNetCore.Authentication.Test.deps.json" "C:\Users\dusti\.nuget\packages\microsoft.testplatform.testhost/15.0.0-preview-20170125-04\lib/netstandard1.5/testhost.dll" --port 29249 --parentprocessid 436 --diag log.host.17-02-11_02-37-12_14546_5.txt'

If testhost is launched, log.host.17-02-11_02-37-12_14546_5.txt file will have more verbose logs (from the testhost process which runs the test).

Can you please share the project? I will try to repro this.

codito picture codito on 11 Feb 2017

@codito: The project is in the repro instructions to this issue.

DustinCampbell picture DustinCampbell on 11 Feb 2017

@DustinCampbell using the instructions in repro steps, I could run tests for netcoreapp1.1 (this is on 1.0.0-rc4-004771 dotnet-cli). Will try on a clean machine and update.

codito picture codito on 13 Feb 2017

@codito: I'm confused why this would work for you. Wouldn't it be blocked by https://github.com/Microsoft/vstest/issues/446?

DustinCampbell picture DustinCampbell on 13 Feb 2017

FWIW, I'm also using 1.0.0-rc4-004771. This is a machine that I just rebuilt. It only has VS 2017 RC4 on it.

DustinCampbell picture DustinCampbell on 13 Feb 2017

I was able to repro a similar timing as @NTaylorMullen using vstest.console.exe and xunit.console.exe.

I'm using xunit.runner.visualstudio/2.2.0-rc1-build1247 and I had to manually copy xunit.execution.desktop to the test output folder. After that, the approximate results from measure-command are:

vstest.console.exe - 13.5 sec
xunit.console.exe - 4.9 sec

KevinH-MS picture KevinH-MS on 13 Feb 2017

There is also a surprising functional difference:

D:\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\net451>vstest.console Microsoft.AspNetCore.Authentication.Test.dll
Microsoft (R) Test Execution Command Line Tool Version 15.0.26206.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...

Total tests: 219. Passed: 218. Failed: 0. Skipped: 1.
Test Run Successful.

D:\Security\test\Microsoft.AspNetCore.Authentication.Test\bin\Debug\net451>xunit.console.exe Microsoft.AspNetCore.Authentication.Test.dll
xUnit.net Console Runner (64-bit .NET 4.0.30319.42000)
  Discovering: Microsoft.AspNetCore.Authentication.Test
  Discovered:  Microsoft.AspNetCore.Authentication.Test
  Starting:    Microsoft.AspNetCore.Authentication.Test
  Finished:    Microsoft.AspNetCore.Authentication.Test
=== TEST EXECUTION SUMMARY ===
   Microsoft.AspNetCore.Authentication.Test  Total: 179, Errors: 0, Failed: 0, Skipped: 0, Time: 0.893s

I will try to figure out where the "extra" tests are coming from in the vstest.console case.

KevinH-MS picture KevinH-MS on 13 Feb 2017

@KevinH-MS When was the last time you restored? Could be https://github.com/aspnet/Testing/issues/245.

cesarblum picture cesarblum on 13 Feb 2017

@cesarbs yes-that likely explains the functional difference. Thanks!

KevinH-MS picture KevinH-MS on 13 Feb 2017

So, one thing I'm noticing when looking at profiles is time spent in telemetry code. I can't tell if this is actually blocking or if the TelemetrySession.Start is completing asynchronously. @codito is there a way to turn off telemetry in vstest.console entirely so we could get a clear idea of how much overhead that's adding?

Name                                                                                                                                                                                                                                                                                                                                                                                                                        Inc %         Inc
 | ||+ vstest.console!RockSteady.Program.Main(class System.String[])                                                                                                                                                                                                                                                                                                                                                          7.2   15,570.527
 | |||+ vstest.console!Executor.Execute                                                                                                                                                                                                                                                                                                                                                                                       7.2   15,540.523
 | ||||+ vstest.console!RunTestsArgumentProcessor.Execute                                                                                                                                                                                                                                                                                                                                                                     7.0   15,258.682
 | |||||+ vstest.console!RunTestsArgumentProcessor.RunTests                                                                                                                                                                                                                                                                                                                                                                   7.0   15,254.861
 | ||||||+ microsoft.visualstudio.testplatform.client!InProcTestPlatform.CreateTestRunRequest                                                                                                                                                                                                                                                                                                                                 4.4   9,465.202
 | |||||||+ microsoft.visualstudio.testplatform.client!TestPlatformBase.CreateTestRunRequest                                                                                                                                                                                                                                                                                                                                  4.4   9,465.202
 | ||||||| + microsoft.visualstudio.testplatform.client!Microsoft.VisualStudio.TestPlatform.Client.TestRunRequest..ctor(class Microsoft.VisualStudio.TestPlatform.ObjectModel.Client.TestRunCriteria,class Microsoft.VisualStudio.TestPlatform.Client.ITestExecutionManager,class Microsoft.VisualStudio.TestPlatform.Client.ITestDataCollectionClient,class Microsoft.VisualStudio.TestPlatform.Client.TestPlatformBase)     4.4   9,461.202
 | ||||||| |+ microsoft.visualstudio.testplatform.client!Microsoft.VisualStudio.TestPlatform.Client.Implementation.Telemetry.UnitTestTelemetryWrapper..ctor(class Microsoft.VisualStudio.TestPlatform.ObjectModel.Client.IUnitTestTelemetryServiceProvider)                                                                                                                                                                   4.4   9,460.201
 | ||||||| ||+ microsoft.visualstudio.testplatform.client!Microsoft.VisualStudio.TestPlatform.Client.Implementation.Telemetry.UnitTestNonVSTelemetryServiceProvider..ctor(bool)                                                                                                                                                                                                                                               4.3   9,406.193
 | ||||||| |||+ OTHER <<microsoft.visualstudio.telemetry!TelemetrySession.Start>>                                                                                                                                                                                                                                                                                                                                             4.3   9,406.193
KevinH-MS picture KevinH-MS on 13 Feb 2017

There are two classes of issues related to test platform here.

First one, delays in xunit adapter (show up prominently) for desktop targets. There are 3 potential areas for improvement (@Shyam-Gupta has more details in #485):

  1. Remove extra appdomain creation for getting source info using DiaSession
  2. Batching to reduce cross-appdomain communication
  3. Cost due to conversion of XUnitTestCase to VSTestCase (MarshalByRef object)

Our prototype fix for (1) is providing around ~25% improvement. We will raise a PR for this and get it reviewed with xunit community. It may come in the RTM timeframe. /cc @BradWilson @ONovotny

Secondly, we're observing a good amount of CPU cycles being spent on Serialization/Deserialization of TestCase/TestResult objects in the runner and testhost. Investigation is ongoing for this. Will share the numbers here in next update.

codito picture codito on 14 Feb 2017

Remove extra appdomain creation for getting source info using DiaSession

This can't be done without breaking VS <= 2015.

Batching to reduce cross-appdomain communication

Can you explain this?

Cost due to conversion of XUnitTestCase to VSTestCase (MarshalByRef object)

The Visual Studio runner (on which dotnet test is based on now in MSBuild-land, but wasn't previously in project.json-land) has always been agonizingly slow compared to every other environment. The multi-process design, with the need to serialize test cases, is just brutal for performance. We have actively steered people away from using it pretty much since we shipped 2.0. The fact that it's at the core of dotnet test is unfortunate in this respect, and it seems unlikely that you're going to be able to fix what is fundamentally a design flaw that dates back to 2012.

Our solution for this is: We intend to write a new dotnet command (dotnet xunit), and once that's available, tell people to stop using dotnet test. This will solve not only the poor performance issues, but also the fact that dotnet test is nowhere near as usable or feature rich as our other custom runners (as well as stops forcing people to opt into the Test Explorer integration even if all they cared about is command line test execution).

bradwilson picture bradwilson on 16 Feb 2017
👍2

Here are the numbers after applying the serialization optimizations and designmode support in test platform (https://github.com/xunit/visualstudio.xunit/pull/103 and https://github.com/Microsoft/vstest/pull/520):

| | project.json | csproj (before fix) | csproj (after fix) | csproj (after fix + no appdomain) |
| ------------- | ------------- | ------------- | ------------- | ------------- |
| net451 | 1.525s | 6.140s | 3.661s | 2.936s |
| netcoreapp1.1 | 2.483s | 3.140s | 2.928s | NA |

Notes:

  • All numbers are with dotnet test --no-build
  • For no appdomain, use dotnet test -- RunConfiguration.DisableAppDomain=true with csproj projects. This mode was default in dotnet-test-xunit (version used in repro steps).
codito picture codito on 21 Feb 2017
👍1

@bradwilson @onovotny Can you pl look at https://github.com/xunit/visualstudio.xunit/pull/103

sbaid picture sbaid on 22 Feb 2017

@sbaid Yes, of course, but we've already RTM'd 2.2, so this would go into a future 2.3 beta release.

bradwilson picture bradwilson on 22 Feb 2017

@bradwilson @onovotny VS rtw is still taking fixes (meeting the bar) and it will help to enable fixes in xunit stable release that will be available around the same time.

sbaid picture sbaid on 23 Feb 2017

We will not be making another RTM release before March 7th.

bradwilson picture bradwilson on 24 Feb 2017
😕1

If anyone wants to try out fixes in xunit/visualstudio.xunit#103, private patches are available at https://www.myget.org/F/codito-private/api/v3/index.json. Please provide your feedback on the xunit issue.

Kindly note that these packages are shared for feedback purpose only, they are not supported or maintained, these fixes may or may not make it into the official releases.

We will close this issue since required fixes in this context are in the test platform. Other performance issues in vstest platform itself are tracked at https://github.com/microsoft/vstest/issues?utf8=%E2%9C%93&q=is%3Aissue%20is%3Aopen%20label%3Aperf%20.

codito picture codito on 20 Mar 2017
Was this page helpful?
0 / 5 - 0 ratings

Related issues

suryagh picture suryagh  路  3Comments
ejcoyle88 picture ejcoyle88  路  3Comments
alastairtree picture alastairtree  路  4Comments
aumanjoa picture aumanjoa  路  3Comments
dlemstra picture dlemstra  路  5Comments