Slow performance of nunit-console

[xplicit]

I've noticed, that tests are being run in nunit-console performing much slower than running them in Visual Studio or in simple console application. nunit-console performs 4-5 times slower on some tests.
I've tested this with NUnit 2.6.4, NUnit 3.0.0-alpha4 (from nuget packages) and with NUnit compiled from master branch (with changes from 2.0 target framework to 4.0 target framework of nunit-console and other projects). I tried various settings of --domain and --process parameters, they didn't help.

Here is the project which demonstrates the issue:

https://github.com/xplicit/Bond/tree/nunit

test UnitTest.GenericsTests.GenericInheritance takes 15-17 seconds on my machine if run it from Visual Studio tests or make a simple console application, which calls this method.
When I run it from nunit-console, it takes about 80 seconds.

Also I wrote a small app, which can be used to investigate the issue. When I run test from Visual Studio or console or with nunitlite it takes 22 seconds to run. If I run it using nunit-console it takes 36 seconds. However I can't be sure for 100% that the app shows the same issue as the first one.

https://github.com/xplicit/nunitperf

The test case, I test: https://github.com/xplicit/nunitperf/blob/master/nunitPerf/Class1.cs

This is critical issue, because it does not allow to run unit-tests on build machines with limited build time (like appveyor service).

Also I am looking for a workaround how I can run unit tests on the build machine and get the results on time with current versions of nunit libraries. I tried to use nunitlite but seems that all tests must be located in the *.exe assembly, and nunitlite can't load tests from other assemblies (no matter are they references or don't referenced by nunitlited exe). If it were able to load assemblies I would have create the console app with references to current tests and run them from command line.

[CharliePoole]

It's definitely a strange issue. I'll looked at your project and I see it's
somewhat complex. I'll wait for the small app that demonstrates the issue.
:-)

A few comments...

1. Make sure your timing is measuring the same thing in both cases. For
   example, both should either include or exclude the time it takes to load
   the assemblies.
2. Settle on a single version of NUnit for your tests. The approach to
   loading and running tests in nunit 3.0 and 2.6.4 are completely different.
   NUnit 3.0 is expected to be significantly faster, especially for large
   numbers of relatively small tests. We are likely to fix any issues you find
   in 3.0 but I can't say the same for 2.6.4. :-(

Charlie

On Sat, Jan 31, 2015 at 1:48 AM, Sergey Zhukov notifications@github.com
wrote:

I've noticed, that tests are being run in nunit-console performing much
slower than running them in Visual Studio or in simple console application.
nunit-console performs 4-5 times slower on some tests.

I've tested this with NUnit 2.6.4, NUnit 3.0.0-alpha4 (from nuget
packages) and with NUnit compiled from master branch (with changes from 2.0
target framework to 4.0 target framework of nunit-console and other
projects). I tried various settings of --domain and --process parameters,
they didn't help.

Here is the project which demonstrates the issue:

https://github.com/xplicit/Bond/tree/nunit

test UnitTest.GenericsTests.GenericInheritance takes 15-17 seconds on my
machine if run it from Visual Studio tests or make a simple console
application, which calls this method.
When I run it from nunit-console, it takes about 80 seconds.

Also I wrote a small app, which can be used to investigate the issue. When
I run test from Visual Studio or console or with nunitlite it takes 22
seconds to run. If I run it using nunit-console it takes 36 seconds.
However I can't be sure for 100% that the app shows the same issue as the
first one.

(I'll post the link here, when upload the project on github)

This is critical issue, because it does not allow to run unit-tests on
build machines with limited build time (like appveyor service).

Also I am looking for a workaround how I can run unit tests on the build
machine and get the results on time with current versions of nunit
libraries. I tried to use nunitlite but seems that all tests must be
located in the *.exe assembly, and nunitlite can't load tests from other
assemblies (no matter are they references or don't referenced by nunitlited
exe). If it were able to load assemblies I would have create the console
app with references to current tests and run them from command line.

—
Reply to this email directly or view it on GitHub
#480.

[CharliePoole]

Try modifying your nunit-console.exe.config file so that NUnit runs under .NET 4.0 / 4.5. Then execute using -process:Single.

The alpha-4 release chooses .NET 2.0 by preference, if present, which would cause your tests to be run in a separate process. The coming alpha-5 changes this to prefer 4.0.

In either case, a separate process is used by default, which may impact your timings. The option -process:Single eliminates the use of a separate process and runs your tests in the NUnit process. This is generally best for timing and debugging.

[xplicit]

I tried all settings combinations for 'process', 'domain' and 'x86' options. Also I tried to run with these combinations:
nunit.framework 2.6.4 + nunit-console 2.6.4 (from nuget)
nunit-framework-3.0.0-alpha4 + nunit-console 3.0.0-alpha4 (from nuget)
nunit-framework-3.0.0 + nunit-console 3.0.0 (built from sources and with changing of target platform for all relevant exe and dll from 2.0 to 4.0)

I suspected that this could be the issue of some domain security settings or remoting and tried to change instantiation of LoadAction, RunAction, etc in NUnit driver from reflection to direct creation of the objects, but this didn't help.

Also this issue exists only for .NET platform (I tested on Win 7 64bit), when I run the test on the mono (tested with mono 3.12, Ubuntu 32 bit), I've got the same times.

There is a link to small project in the first post.

[CharliePoole]

Hi Sergey,

Regarding settings, please see my earlier post for the only setting change that has a hope of affecting this! Do not use -x86 unless you are building tests for -x86. The -domain setting has no meaning unless you are running multiple assemblies. The key is to do nothing that causes NUnit to create a separate process.

Rebuilding for 4.0 is not necessary and isn't something we are likely to do so long as we support running on a machine with 2.0 only installed. Changing the config file is sufficient.

Directly linking to the framework is also something we wouldn't do, although it was a good idea as a diagnostic. The security possibility raises this question: are you running as admin? If not, you might give it a try.

Interesting that the difference only occurs on Windows!

I missed seeing your sample originally - thought you said you were going to write one. I'll check it out.

Charlie

[xplicit]

When I tested I made an decartian product of this values:
[--domain=None, Single,Multiply, (no option)]x[--process=Single,Separate,Multiple,(no option)]x[-x86 (has option),(no option)]. And tested all the combinations from this product. So command line
nunit-console.exe --process=Single assembly.dll was tested too.

Also, when I test NUnit compiled for .NET 4 I have removed the *.config file to exclude affecting .NET 2.0 stuff on the test.

The user is not Administrator, but it is included in the administrator group, I'll try to run the test under 'Administrator' user.

Did you able to reproduce the issue with my small sample?

[CharliePoole]

When I run your nunitPerf program directly, I get 16980ms. When I run it under the 3.0 a5 console I get 17036ms. Running it under nunitlite got me 16860ms.

[xplicit]

So you've got the same time for all runs. Is 3.0 a5 compiled under .NET 4.0 or .NET 2.0 target like 3.0 a4? Did you do any additional steps to run? Did you try to run nunit-console.exe --process=Single nunitPerf.exe?

I'll try to make tomorrow appveyor.yml for this project to demonstrate the difference

[CharliePoole]

All the NUnit 3.0 engine and runner assemblies are compiled for 2.0, since they are supposed to run on any machine with 2.0 or greater. The console runner runs under CLR4 if available, otherwise CLR2.

I didn't use any options on the command-line, so the runner ran in a separate process. Being in the same or a separate process should not make a difference, since you aren't timing NUnit's startup.

Maybe something in your own setup is causing this.

[xplicit]

I've got finally the same times for nunit-console and console application. It was successful only for 3a5, because for 3a4 the command without options does not work (it throws exception about .NET configuration System.ArgumentException: NUnit components for version 4.0.30319 of the CLR are not installed
Имя параметра: targetRuntime
в NUnit.Engine.Services.TestAgency.LaunchAgentProcess(RuntimeFramework targetRuntime, Boolean enableDebug, String agentArgs, Boolean useX86Agent))

So, this command shows the same time on my machine (18 sec):
nunit-console.exe nunitPerf.exe
These commands show other time (30 sec):
nunit-console.exe --framework=net-4.0 nunitPerf.exe
nunit-sonsole.exe --process=Single nunitPerf.exe

[CharliePoole]

I tried the same commands: the first gives me 17172ms, the second 17236ms.

[xplicit]

I tried to create appveyor build for the small project, but it does not show any differences in timing like on my local machine. I'll look more closely on original project issue (which was raised on appveyor) and try to create small reproducable project.

[xplicit]

Some additional info. I wrote a sample application, which loads all tests from the assembly and run them. Then I run this application and nunit-console with the same test assembly on appveyor. The times differ very significant.

Execution time.
Sample console app: 94 sec
nunit-console 3.0: 334 sec

Here is the appveyor log:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27

The commands I've run:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27#L1263
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27#L1264

This unit testing log starts here:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27#L1282

Here is the source code of sample app:
https://github.com/xplicit/bond/blob/nunit3/ConsoleApplication1/Program.cs

[CharliePoole]

I assume that you have not enabled parallel execution in your test dll. If
that's the case, we are still running with a set of parallel queues, but
only using one of them.

In case this is introducing some wait condition, give the 3.0 version a try
with --workers:0

This app is pretty complex. Is there any way to duplicate the same thing in
a simpler app? I know you tried that before, but it seemed that the
differences went away, at least for me.

Charlie

On Thu, Feb 5, 2015 at 11:33 AM, Sergey Zhukov notifications@github.com
wrote:

Some additional info. I wrote a sample application, which loads all tests
from the assembly and run them. Then I run this application and
nunit-console with the same test assembly on appveyor. The times differ
very significant.

Execution time.
Sample console app: 94 sec
nunit-console 3.0: 334 sec

Here is the appveyor log:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27

The commands I've run:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27#L1263
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27#L1264

This unit testing log starts here:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.27#L1282

Here is the source code of sample app:
https://github.com/xplicit/bond/blob/nunit3/ConsoleApplication1/Program.cs

—
Reply to this email directly or view it on GitHub
#480 (comment).

[xplicit]

I could not localize the issue in small example yet. The bad thing that on my local machine tests run slowly even on simple examples, but this does not reproduce on appveyor. At this moment I just can show slowness only for this big app. I'm still trying to localize the issue.

nunit-console --workers=0 (328 sec run)
https://ci.appveyor.com/project/xplicit/bond/build/1.0.28
nunit-console --workers=1 (354 sec run)
https://ci.appveyor.com/project/xplicit/bond/build/1.0.29

[CharliePoole]

Well, it was an idea anyway. Actually, I'm glad to see that the difference between --workers=0 and --workers=1 is so small.

Can you get the XML output file as an artifact from appveyor? That may tell you something about whether the additional time is distributed across all tests or is caused by some specific tests.

[xplicit]

Here is the build logs with atrifacts. Also I added timings for each test in console application.

https://ci.appveyor.com/project/xplicit/bond/build/1.0.31

You can see that test 'GenericInheritance' took 8 sec in console app and 31 sec in nunit-console.

[CharliePoole]

Yes, and most of the extra time seems to be taken in the fixture
SerializationTests, which runs for 249 seconds. Do these tests have
anything in common that might help explain the difference?

On Fri, Feb 6, 2015 at 12:25 AM, Sergey Zhukov notifications@github.com
wrote:

Here is the build logs with atrifacts. Also I added timings for each test
in console application.

https://ci.appveyor.com/project/xplicit/bond/build/1.0.31

You can see that test 'GenericInheritance' took 8 sec in console app and
31 sec in nunit-console.

—
Reply to this email directly or view it on GitHub
#480 (comment).

[xplicit]

SerializationTests very intensively use GC from dynamic delegates. I suspect (but can't be sure, because did not reproduce it yet on small test-case) that this can affect on the execution speed. Maybe Adam Sapek @sapek could say some additional information, what could possible influence on the tests speed.

[sapek]

It is true that the tests use LINQ expressions very extensively. However all the tests have this common: they built expression tree, compile it into a lambda and run it. What is special about the tests that take long time to run is that they serialize large classes with many nested containers. So there are two things that are big in those tests: expression trees that are built/compiled in the beginning and the data the test operates on (serialize to various encoding formats, including JSON and XML, deserialize, transcode, etc).

@xplicit One quick experiment that would tell us more is to run one of the large test (e.g. Containers) after commenting this line. This will still generate/compile the expression tree but the test will run only with empty object which for most protocols serializes into a few bytes. If this takes significant amount of time, and especially if the slowdown is dramatic with NUnit console, then the problem is with large expressions. Otherwise the problem is likely related to processing large amount of data. In the later case the next thing we could try would be to comment out Xml/JSON tests here and here (text encoding is obviously much bigger and more costly to parse than binary).

[xplicit]

I commented that line https://github.com/xplicit/bond/blob/3374531db9abb91e98abdbc7450dea906e71eb1d/cs/test/core/SerializationTests.cs#L441, here the results:

console app: 83 sec, nunit-console: 295 sec. So the times are close to original times without commenting.

https://ci.appveyor.com/project/xplicit/bond/build/1.0.40

[sapek]

@xplicit, I pulled your nunit3 branch and I get exactly the same time running tests from unint-console and from VisualStudio. I understand that this is different than what you get on your machine but the same what @CharliePoole sees. On my machine the tests run slightly slower than MSTest (Containers takes 11s in NUnit and 10s in MSTest, GenericInheritance takes 16s in NUnit and 11s in MSTest). So I'm not sure if we can say that tests run slower under nunit-console.

However a few things seem to be clear:

• NUnit tests run 4x times slower than MSTest on AppVeyor
• The simple application @xplicit wrote executes the same tests much faster on AppVeyor than nunit-console (and about 50% faster on my machine, which depending on the test, either matches or exceeds MSTest speed).

One thing that is special about AppVeyor is that the VMs are very slow and memory limited. So one theory is that NUnit is memory hungry and things get very slow on system with little memory. A counter evidence is that even when running a single test GenericInheritance nunit-console takes over 4 times longer than the simple app @xplicit wrote.

@xplicit do you know if your account on AppVeyor is Pro (trial is Pro) or open source. Open source accounts use much smaller/slower VMs.

[CharliePoole]

And I have yet to see a difference! I wish I could, as it would give me something to debug.

NUnit builds an entire model of the tests - which includes all test methods, test cases, test fixtures and setup fixtures - before it executes. This is true even if you limit execution via using the --test option.

I've experimented with an option that limits what is loaded but it's not ready for release. The problem is that we need an entirely different filter. If the tests are not yet loaded, we don't yet have ids or names for them. A load filter will need to rely on class and method names rather than test names and so may end up being a bit confusing to users. I would expedite this feature if we could somehow prove that this is the source of the problem.

[xplicit]

@sapek my AppVeyor instance is an open source account.

It's interesting that nunit-console shows different times on different configuration. Here some summary results to think about. Two projects: bond/nunit3 branch - original, and nunitperf (https://github.com/xplicit/nunitperf) - small application, which actively uses GC and small compiled lambla expressions (compared with sample console application)

My machine:
nunitperf: 4-5x times slower under nunit-console.
bond/nunit3: 4-5x times slower under nunit-console.
AppVeyor:
nunitperf: same time under ninit-console
bond/nunit3: 3.5-4x times slower under nunit-console
Charlie Poole machine:
nunitperf: same time under nunit-console
bond/nunit3: no data
Adam Sapek machine:
nunitperf: no data
bond/nunit3: same time under nunit-console

Please correct if something is wrong here.

Also I added testing with NUnitLite to the project. It shows exactly the same time on AppVeyor as my console application.

logs are here:
https://ci.appveyor.com/project/xplicit/bond/build/1.0.44

[xplicit]

@sapek I was wrong about my appveyor plan, it's not expired yet and it's 14-day pro-trial.

[xplicit]

I made a small project with SerializationTests were copied from bond project. https://github.com/xplicit/nunitperf2 It can be run for quick nunit tests without long compilation of bond project.

There are three testing option in it:

• using nunit-console
• using nunitlite
• using my simple console app which loads and executes all tests

nunitlite and my app show the same time of running tests, nunit-console is much slower.

I made two benchmarks run:

• the first runs only one test using nunitlite and nunit-console
• second runs all the tests using nunitlite, nunit-console and my console app.

The results:
One test (UnitTest.SerializationTests.Lists):
nunitlite - 2.6 sec
nunit-console.exe - 12.2 sec

All Tests:
nunitlite - 56.6 sec
nunit-console - 351.9 sec
console app - 56 sec

AppVeyor logs:
https://ci.appveyor.com/project/xplicit/nunitperf2/build/1.0.5

[CharliePoole]

The nunitlite comparison is pretty interesting because it provides very well-defined points of difference to the nunit-console tests:

1. NUnitLite runs tests in the primary AppDomain, nunit-console in a secondary domain. Is it possible your code behaves differently when not in the primary domain?
2. NUnitLite invokes the framework via a direct reference, nunit-console by reflection. This is probably not significant, since it's a single call per run.
3. NUnitLite communicates directly with the framework, nunit-console over remoting. I doubt that this is the issue, since it would show up as a systematic difference between the two for everyone.
4. NUnitlite receives results as objects, nunit-console must interpret XML. This happens after the test has completed, so would probably not be significant.
5. NUnitLite runs tests sequentially, nunit-console may run them in parallel. Hopefully, you are still using --workers:0 for nunit-console so that the same execution path is followed in both cases.

Charlie

[CharliePoole]

I'll give your new test app a try later today.

[sapek]

I get similar results, although the difference is not as big (Lists test):
nunitlite - 2.8 sec
nunit-console - 5.7 sec
console app - 2 sec

[CharliePoole]

@xplicit @sapek Based on the discussion on the Microsoft/bond issues forum, I now understand that you are building NUnit yourselves, possibly in a different way from how we build it. Is that right?

I may have misunderstood, so please clarify.

[xplicit]

@CharliePoole I tried to build nunitlite.exe (because it was faster on appveyor than nunit-console) from nuget package NUnitLite and have found that nunitlite is faster only when it is built with /platform:anycpu32bitpreferred csc option. Then I tried to use --x86 option in nunit-console and it helped on appveyor (on my local machine it did not help).
So finally I use nunit-console-x86 from appveyor nunit 2.6.3 build. Also I checked that nunit-console 3.0.0-alpha-5b from nuget with --x86 option works on appveyor at appropriate speed for bond project.

[SeriousM]

Hello @CharliePoole, is there any update on this issue?
I'm using nunit 3.4.1 and experience very slow tests with the console runner vs resharper/ncrunch execution.
How can I help?

[CharliePoole]

@SeriousM If you are seeing this online on GitHub, you will see that it's still labelled 'confirm' If you're using email, that's unfortunately hard to discover. I tried to leave enough hints here for somebody to take this on and confirm it, but it hasn't happened yet. How about it @nunit/contributors ?

Are you running nunit with multiple agent processes? If the slowdown you see is at the individual test level, that's what this issue is about, but if you are having a slowdown at a higher level (e.g. process startup) there are some other issues we are working on that could affect you.

[SeriousM]

It turns out that I wasn't affected by this problem, just the buildserver was very slow for a couple of days. Thanks

[tasoss]

@CharliePoole
Hello.I believe that the console version really runs tests slower.I have a specific test with takes up to 200ms in console but a few ms in ncrunch/resharper.How could i help you identify any potential problem?Thanks!

[rprouse]

Neither @CharliePoole nor I have Resharper nor NCrunch licenses, so it is hard for us to compare, but 200ms doesn't seem too slow. It sounds like you are running one test which isn't a fair comparison. When you run, R# and NCrunch have already pre-parsed your assemblies and can just run the test. The console has to parse the assembly, create all of the test cases, pick the right one and then run it.

Looking at your TestResults.xml, what is the duration of the test itself, not the entire test run which includes startup time?

If you are using NuGet to install the console, it would also be interesting to remove the package, clean out the packages directory and use NUnit.ConsoleRunner only. This doesn't include any engine extensions like the NUnit 2 runner. It would be interesting to see how much overhead the extensions add to startup time.

[asbjornu]

@rprouse: Off-topic, but I'm sure the NUnit project is qualified for a JetBrains Open Source License. As far as I know, NCrunch does not have an open source license.

[tasoss]

Thanks for replying.
a)You can use the evaluation versions but what you said"When you run, R# and NCrunch have already pre-parsed your assemblies and can just run the test. The console has to parse the assembly, create all of the test cases, pick the right one and then run it."
seems to explain a few things...I mean this could be a reason for delays,right?
b)

Looking at your TestResults.xml, what is the duration of the test itself, not the entire test run which includes startup time?

Please give me some time i want to be sure that what i am saying is correct.

c)I have downloaded the master version from github(before a few days) and compiled it.Then i'm using nunit3-console foobar.dll

[rprouse]

@asbjornu thanks for the link, but JetBrain's terms are fairly restrictive. They say that "Open Source licenses can only be used for non-commercial Open Source development". Since Resharper integrates with Visual Studio, I would need to turn it off whenever I was doing non-open source development. Since R# hijacks many of the keybindings for refactorings and quick fixes, I would end up working in a crippled environment whenever it was turned off.

[rprouse]

I am closing this because it has been inactive for so long. If anyone has further info, we can reopen.