Console runner performance varies wildly depending on environmental characteristics

[mintsoft]

Hiya,

We've just rolled out NUnit 3 for the majority of our build suite, and we've found some interesting (to say the least) performance behaviour. I think this may be a duplicate of: #480

Basically we noticed that tests "are slow on CI"; after eliminating the hardware and installation etc. We've found that tests when executed through NUnit-console are quicker when Visual Studio is open, than when it's closed. This seems insane behaviour, however it is absolutely what we see (absolutely repeatable on multiple machines, including a freshly installed machine):

• With VS closed: 9.131 seconds
• With VS open: 2.54 seconds.

It happens with every test project we have with comparable performance differences (i.e. 1 minute to 4 minutes on the larger suites). When I say with Visual Studio open, I don't mean the relevant sln or csproj open, I mean just the application itself.

Here the first run was with VS open, the next 2 with it closed and then it open again:

D:\code>NUnit.ConsoleRunner.3.6.1\tools\nunit3-console.exe test\Web\Tests.csproj
NUnit Console Runner 3.6.1
Copyright (C) 2017 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.3.9600.0
  CLR Version: 4.0.30319.42000

Test Files
    test\Web\Tests.csproj


Run Settings
    BasePath: D:\code\test\Web\bin\
    DisposeRunners: True
    WorkDirectory: D:\code
    ImageRuntimeVersion: 4.0.30319
    ImageTargetFrameworkName: .NETFramework,Version=v4.6.1
    ImageRequiresX86: False
    ImageRequiresDefaultAppDomainAssemblyResolver: False
    NumberOfTestWorkers: 8

Test Run Summary
  Overall result: Passed
  Test Count: 175, Passed: 175, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2017-06-04 18:37:09Z
    End time: 2017-06-04 18:37:12Z
    Duration: 2.540 seconds

Results (nunit3) saved as TestResult.xml

D:\code>NUnit.ConsoleRunner.3.6.1\tools\nunit3-console.exe test\Web\Tests.csproj
NUnit Console Runner 3.6.1
Copyright (C) 2017 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.3.9600.0
  CLR Version: 4.0.30319.42000

Test Files
    test\Web\Tests.csproj


Run Settings
    BasePath: D:\code\test\Web\bin\
    DisposeRunners: True
    WorkDirectory: D:\code
    ImageRuntimeVersion: 4.0.30319
    ImageTargetFrameworkName: .NETFramework,Version=v4.6.1
    ImageRequiresX86: False
    ImageRequiresDefaultAppDomainAssemblyResolver: False
    NumberOfTestWorkers: 8

Test Run Summary
  Overall result: Passed
  Test Count: 175, Passed: 175, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2017-06-04 18:37:20Z
    End time: 2017-06-04 18:37:29Z
    Duration: 9.131 seconds

Results (nunit3) saved as TestResult.xml

D:\code>NUnit.ConsoleRunner.3.6.1\tools\nunit3-console.exe test\Web\Tests.csproj
NUnit Console Runner 3.6.1
Copyright (C) 2017 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.3.9600.0
  CLR Version: 4.0.30319.42000

Test Files
    test\Web\Tests.csproj


Run Settings
    BasePath: D:\code\test\Web\bin\
    DisposeRunners: True
    WorkDirectory: D:\code
    ImageRuntimeVersion: 4.0.30319
    ImageTargetFrameworkName: .NETFramework,Version=v4.6.1
    ImageRequiresX86: False
    ImageRequiresDefaultAppDomainAssemblyResolver: False
    NumberOfTestWorkers: 8

Test Run Summary
  Overall result: Passed
  Test Count: 175, Passed: 175, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2017-06-04 18:37:53Z
    End time: 2017-06-04 18:38:02Z
    Duration: 9.157 seconds

Results (nunit3) saved as TestResult.xml

D:\code>NUnit.ConsoleRunner.3.6.1\tools\nunit3-console.exe test\Web\Tests.csproj
NUnit Console Runner 3.6.1
Copyright (C) 2017 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.3.9600.0
  CLR Version: 4.0.30319.42000

Test Files
    test\Web\Tests.csproj


Run Settings
    BasePath: D:\code\test\Web\bin\
    DisposeRunners: True
    WorkDirectory: D:\code
    ImageRuntimeVersion: 4.0.30319
    ImageTargetFrameworkName: .NETFramework,Version=v4.6.1
    ImageRequiresX86: False
    ImageRequiresDefaultAppDomainAssemblyResolver: False
    NumberOfTestWorkers: 8

Test Run Summary
  Overall result: Passed
  Test Count: 175, Passed: 175, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2017-06-04 18:43:47Z
    End time: 2017-06-04 18:43:50Z
    Duration: 2.685 seconds

Results (nunit3) saved as TestResult.xml

D:\code>

This is running on:

• Server 2012R2
• VS 2015 Pro Update 3 (14.0.25420.01 Update 3)
• We do have ReSharper 2016.2 installed (it was mentioned extensively in Slow performance of nunit-console #480)
• Test project is a .NET 4.6.1 against NUnit 3.6.1.0 using the NUnit Console 3.6.1.0

I'm at a loss how to explain or debug this further; happy to provide any info or run any tests you like ??

[CharliePoole]

Running from the project file is somewhat unusual. That, combined with the fact that VS is involved, makes me suspicious. Can you see what happens if you just run the assembly?

[mintsoft]

@CharliePoole That's a good point, however I've just tried it with the same behaviour:

Microsoft Windows [Version 6.3.9600]
(c) 2013 Microsoft Corporation. All rights reserved.

C:\Users\Developer>cd /D D:\code

D:\code>NUnit.ConsoleRunner.3.6.1\tools\nunit3-console.exe D:\code\test\Web\bin\Tests.dll
NUnit Console Runner 3.6.1
Copyright (C) 2017 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.3.9600.0
  CLR Version: 4.0.30319.42000

Test Files
    D:\code\test\Web\bin\Tests.dll


Run Settings
    DisposeRunners: True
    WorkDirectory: D:\code
    ImageRuntimeVersion: 4.0.30319
    ImageTargetFrameworkName: .NETFramework,Version=v4.6.1
    ImageRequiresX86: False
    ImageRequiresDefaultAppDomainAssemblyResolver: False
    NumberOfTestWorkers: 8

Test Run Summary
  Overall result: Passed
  Test Count: 175, Passed: 175, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2017-06-04 20:37:00Z
    End time: 2017-06-04 20:37:07Z
    Duration: 7.195 seconds

Results (nunit3) saved as TestResult.xml

D:\code>NUnit.ConsoleRunner.3.6.1\tools\nunit3-console.exe D:\code\test\Web\bin\Tests.dll
NUnit Console Runner 3.6.1
Copyright (C) 2017 Charlie Poole

Runtime Environment
   OS Version: Microsoft Windows NT 6.3.9600.0
  CLR Version: 4.0.30319.42000

Test Files
    D:\code\test\Web\bin\Tests.dll


Run Settings
    DisposeRunners: True
    WorkDirectory: D:\code
    ImageRuntimeVersion: 4.0.30319
    ImageTargetFrameworkName: .NETFramework,Version=v4.6.1
    ImageRequiresX86: False
    ImageRequiresDefaultAppDomainAssemblyResolver: False
    NumberOfTestWorkers: 8

Test Run Summary
  Overall result: Passed
  Test Count: 175, Passed: 175, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2017-06-04 20:38:17Z
    End time: 2017-06-04 20:38:20Z
    Duration: 2.540 seconds

Results (nunit3) saved as TestResult.xml

D:\code>

The first run (~7seconds) was with VS closed, the second (~2seconds) was with it open.

[CharliePoole]

Interesting. As developers, we are almost always running NUnit tests locally with VS running, so those are the times we see. I'll do some experiments.

[mintsoft]

As developers, we are almost always running NUnit tests locally with VS running, so those are the times we see.

That's exactly what we found, it was only on CI that we noticed the run-time difference initially.

[CharliePoole]

I am unable to duplicate this so I'm marking it for somebody else to try to confirm.

When you did your experiments, did you try it with VS open but no solution loaded? I wonder if it could have to do with some assemblies being in memory already.

I'm assuming that neither your tests nor your SUT uses VS in any way - i.e. you are not loading the VS object model or anything like that.

[mintsoft]

@CharliePoole Yeah it was VS open with no projects loaded at all vs it unopened. The tests are totally in-memory standalone things. There's no relationship to VS in the tests at all.
What version of Windows are you using? I'm wondering if it's a Server vs Desktop runtime style difference

[CharliePoole]

I'm running on Windows 10.

[rprouse]

@mintsoft just a guess, but could you repeat the test with another .NET program running, even just a simple console app blocked in a Console.Readline()? It is a stretch, but I am curious if it isn't anything to do with Visual Studio, but instead the fact that a .NET program is running and therefore the CLR is in memory.

Also, are you only able to reproduce this on your CI machine or are you also reproducing this on your development machines?

[mintsoft]

@rprouse I've just tried that, the tests ran in ~9 seconds (that's the slow time) with a console application running in the background.

I can reproduce this on dev machines easily enough even with a fresh install of windows.

I've been experimenting with other applications being open, interestingly enough it doesn't seem to be limited to Visual Studio. One that was particularly interesting is the ModernUI WPF Example application (https://github.com/firstfloorsoftware/mui/tree/master/1.0/FirstFloor.ModernUI/FirstFloor.ModernUI.App). I compiled it, ran it and found that if it's running when the tests are executed they again run at about 2.5/3 seconds (fast speed). Close it, run the tests again and I'm back to 8 seconds. I am very confused now

[CharliePoole]

Maybe we are looking at this wrong. Could the problem be in how we report the time?

[mintsoft]

Maybe we are looking at this wrong. Could the problem be in how we report the time?

@CharliePoole I don't think so, when I'm watching the runs it physically takes longer to watch. I can do a video of the test if you want?

[mintsoft]

I've done a quick gif showing it:

There's nothing else open at all other than ShareX, cmd and nunit-console.

There are 3 runs that are slow (8-9 seconds), then I open the ModernUI app I've compiled (based on the one linked to earlier, but with stuff deleted from it) it's down to <3 seconds. I close the ModernUI app again, and it's back to 8-9 seconds.

I'm currently deleting stuff from the ModernUI application to see if I can delete something that will make the effect go away. Also debug vs release complication of the ModernUI app seems to make no difference, it's still .. making it quicker

[rprouse]

Looking at the pauses in the output, it looks like it is happening while starting up the remote agent. The actual running of the tests appears to be the same. Could you try running the tests with the --inprocess command line switch to see if it makes a difference and help narrow down the problem? I am thinking it is setting up remoting, networking or process launching.

[rprouse]

Sorry, I am wrong, the Run Settings is output at the end of the test run. It still could be related to the remote agent though, so please try the --inprocess switch and let me know the results.