Execute OneTimeTearDown as early as possible when running fixtures in parallel #2335

jtomkiew-ITM · Jul 28, 2017

NUnit 3.7.1

Setup:

Running fixtures in parallel (Parallelizable(ParallelScope.Fixtures) set in AssemblyInfo.cs) in at least 2 threads (LevelOfParallelism(2) set in AssemblyInfo.cs).

Multiple fixtures with tests and OneTimeTearDown's for each of them exist.

Problem:

All [OneTimeTearDown] methods are executed in bulk when first available thread finishes.

Example:

Tests:

using System.Threading;
using NLog;
using NUnit.Framework;

namespace Skanska.Korab2.UITests.Infrastructure.Tests
{
    class Common
    {
        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

        public static void LogMe(string message)
        {
            Logger.Log(LogLevel.Info, $"{message} from {Thread.CurrentThread.Name}");
        }
    }

    class Class1Fast
    {
        [Test]
        public void Test1()
        {
            Common.LogMe(nameof(Test1));
        }

        [Test]
        public void Test11()
        {
            Common.LogMe(nameof(Test11));
        }

        [OneTimeTearDown]
        public void Test1TearDown()
        {
            Common.LogMe(nameof(Test1TearDown));
        }
    }

    class Class2Slow
    {
        [Test]
        public void Test2()
        {
            Thread.Sleep(1000);
            Common.LogMe(nameof(Test2));
        }

        [Test]
        public void Test22()
        {
            Thread.Sleep(1000);
            Common.LogMe(nameof(Test22));
        }

        [OneTimeTearDown]
        public void Test2TearDown()
        {
            Common.LogMe(nameof(Test2TearDown));
        }
    }

    class Class3Slow
    {
        [Test]
        public void Test3()
        {
            Thread.Sleep(1000);
            Common.LogMe(nameof(Test3));
        }

        [Test]
        public void Test33()
        {
            Thread.Sleep(1000);
            Common.LogMe(nameof(Test33));
        }

        [OneTimeTearDown]
        public void Test3TearDown()
        {
            Common.LogMe(nameof(Test3TearDown));
        }
    }

    class Class4
    {
        [Test]
        public void Test4()
        {
            Common.LogMe(nameof(Test4));
        }

        [Test]
        public void Test44()
        {
            Common.LogMe(nameof(Test44));
        }

        [OneTimeTearDown]
        public void Test4TearDown()
        {
            Common.LogMe(nameof(Test4TearDown));
        }
    }

    class Class5
    {
        [Test]
        public void Test5()
        {
            Common.LogMe(nameof(Test5));
        }

        [Test]
        public void Test55()
        {
            Common.LogMe(nameof(Test55));
        }

        [OneTimeTearDown]
        public void Test5TearDown()
        {
            Common.LogMe(nameof(Test5TearDown));
        }
    }

    class Class6
    {
        [Test]
        public void Test6()
        {
            Common.LogMe(nameof(Test6));
        }

        [Test]
        public void Test66()
        {
            Common.LogMe(nameof(Test66));
        }

        [OneTimeTearDown]
        public void Test6TearDown()
        {
            Common.LogMe(nameof(Test6TearDown));
        }
    }

    class Class7
    {
        [Test]
        public void Test7()
        {
            Common.LogMe(nameof(Test7));
        }

        [Test]
        public void Test77()
        {
            Common.LogMe(nameof(Test77));
        }

        [OneTimeTearDown]
        public void Test7TearDown()
        {
            Common.LogMe(nameof(Test7TearDown));
        }
    }

    class Class8Slow
    {
        [Test]
        public void Test8()
        {
            Thread.Sleep(1000);
            Common.LogMe(nameof(Test8));
        }

        [Test]
        public void Test88()
        {
            Thread.Sleep(1000);
            Common.LogMe(nameof(Test88));
        }

        [OneTimeTearDown]
        public void Test8TearDown()
        {
            Common.LogMe(nameof(Test8TearDown));
        }
    }
}

AssemblyInfo.cs

[assembly: Parallelizable(ParallelScope.Fixtures)]
[assembly: LevelOfParallelism(2)]

Result:

2017-07-28 18:09:03.0068|INFO|   Test1 from Worker#2
2017-07-28 18:09:03.0338|INFO|   Test11 from Worker#2
2017-07-28 18:09:03.8560|INFO|   Test2 from Worker#1
2017-07-28 18:09:04.0419|INFO|   Test3 from Worker#2
2017-07-28 18:09:04.8612|INFO|   Test22 from Worker#1
2017-07-28 18:09:04.8732|INFO|   Test4 from Worker#1
2017-07-28 18:09:04.8732|INFO|   Test44 from Worker#1
2017-07-28 18:09:04.8862|INFO|   Test5 from Worker#1
2017-07-28 18:09:04.8862|INFO|   Test55 from Worker#1
2017-07-28 18:09:04.8982|INFO|   Test6 from Worker#1
2017-07-28 18:09:04.8982|INFO|   Test66 from Worker#1
2017-07-28 18:09:04.9132|INFO|   Test7 from Worker#1
2017-07-28 18:09:04.9132|INFO|   Test77 from Worker#1
2017-07-28 18:09:05.0482|INFO|   Test33 from Worker#2
2017-07-28 18:09:05.0522|INFO|   Test1TearDown from Worker#2
2017-07-28 18:09:05.0522|INFO|   Test2TearDown from Worker#2
2017-07-28 18:09:05.0677|INFO|   Test4TearDown from Worker#2
2017-07-28 18:09:05.0677|INFO|   Test5TearDown from Worker#2
2017-07-28 18:09:05.0677|INFO|   Test6TearDown from Worker#2
2017-07-28 18:09:05.0677|INFO|   Test7TearDown from Worker#2
2017-07-28 18:09:05.0677|INFO|   Test3TearDown from Worker#2
2017-07-28 18:09:05.9266|INFO|   Test8 from Worker#1
2017-07-28 18:09:06.9321|INFO|   Test88 from Worker#1
2017-07-28 18:09:06.9321|INFO|   Test8TearDown from Worker#1

Expected result:

Test1TearDown is run before Worker#2 has started tests from other fixtures.

Previous versions:

Logs from NUnit 3.6.1:

2017-07-28 18:18:19.3493|INFO|   Test1 from Worker#2
2017-07-28 18:18:19.3913|INFO|   Test11 from Worker#2
2017-07-28 18:18:19.4018|INFO|   Test1TearDown from Worker#2
2017-07-28 18:18:19.9824|INFO|   Test2 from Worker#1
2017-07-28 18:18:20.4252|INFO|   Test3 from Worker#2
2017-07-28 18:18:20.9884|INFO|   Test22 from Worker#1
2017-07-28 18:18:20.9914|INFO|   Test2TearDown from Worker#1
2017-07-28 18:18:20.9914|INFO|   Test4 from Worker#1
2017-07-28 18:18:20.9914|INFO|   Test44 from Worker#1
2017-07-28 18:18:21.0085|INFO|   Test4TearDown from Worker#1
2017-07-28 18:18:21.0085|INFO|   Test5 from Worker#1
2017-07-28 18:18:21.0224|INFO|   Test55 from Worker#1
2017-07-28 18:18:21.0224|INFO|   Test5TearDown from Worker#1
2017-07-28 18:18:21.0224|INFO|   Test6 from Worker#1
2017-07-28 18:18:21.0424|INFO|   Test66 from Worker#1
2017-07-28 18:18:21.0424|INFO|   Test6TearDown from Worker#1
2017-07-28 18:18:21.0574|INFO|   Test7 from Worker#1
2017-07-28 18:18:21.0574|INFO|   Test77 from Worker#1
2017-07-28 18:18:21.0724|INFO|   Test7TearDown from Worker#1
2017-07-28 18:18:21.4422|INFO|   Test33 from Worker#2
2017-07-28 18:18:21.4452|INFO|   Test3TearDown from Worker#2
2017-07-28 18:18:22.0818|INFO|   Test8 from Worker#1
2017-07-28 18:18:23.0879|INFO|   Test88 from Worker#1
2017-07-28 18:18:23.0879|INFO|   Test8TearDown from Worker#1

You have used an assembly-level attribute to indicate that all fixtures may run in parallel. That's what they are doing.

If you really don't want test1 to run in parallel with the others, you can use an attribute to indicate that.

Perhaps you are asking for NUnit to somehow prioritize running teardowns. That's a feature request. I even considered doing it in the implementation but it was a fair bit more complex so I postponed it.

CharliePoole · Jul 30, 2017

You have used an assembly-level attribute to indicate that all fixtures may run in parallel. That's what they are doing.

If you really don't want test1 to run in parallel with the others, you can use an attribute to indicate that.

Perhaps you are asking for NUnit to somehow prioritize running teardowns. That's a feature request. I even considered doing it in the implementation but it was a fair bit more complex so I postponed it.

I do want all the fixtures to run in parallel. Is OneTimeTearDown not supposed to be run at the end of the fixture it is in (like, after tests, not after tests from other fixtures)? In the result above from 3.7.1, OneTimeTearDown's are 'queued' at the end, when the worker has finished all other tests.

The "Logs from NUnit 3.6.1" is what I expected to happen.

jtomkiew-ITM · Jul 31, 2017

I do want all the fixtures to run in parallel. Is OneTimeTearDown not supposed to be run at the end of the fixture it is in (like, after tests, not after tests from other fixtures)? In the result above from 3.7.1, OneTimeTearDown's are 'queued' at the end, when the worker has finished all other tests.

The "Logs from NUnit 3.6.1" is what I expected to happen.

OneTimeTearDown for a fixture is guaranteed to run...

After all the tests in the fixture.
Before any higher-level OneTimeTearDown runs.

That's all we guarantee currently.

More is a new feature, which means you or someone else would need to scope it out fairly precisely for us to evaluate.

CharliePoole · Jul 31, 2017

OneTimeTearDown for a fixture is guaranteed to run...

After all the tests in the fixture.
Before any higher-level OneTimeTearDown runs.

That's all we guarantee currently.

More is a new feature, which means you or someone else would need to scope it out fairly precisely for us to evaluate.

OK, thanks for the explanation, I'll see what I can do about that feature request.

jtomkiew-ITM · Aug 1, 2017

OK, thanks for the explanation, I'll see what I can do about that feature request.

You can just post here and we'll make this a feature request.

One possibility is to simply give teardowns some sort of priority, without guaranteeing a particular order. That would allow resources to be released more quickly but is a fairly big change.

Another is to somehow determine whether the teardown can be run on the same thread as the last test completed. That would allow faster release in many most cases, while still using normal scheduling when the teardown called for a different thread. This probably boils down to checking the required Apartment, but it would take some analysis to be sure.

Note that this issue only arises if both the fixture and the test cases are run in parallel.

CharliePoole · Aug 1, 2017

You can just post here and we'll make this a feature request.

One possibility is to simply give teardowns some sort of priority, without guaranteeing a particular order. That would allow resources to be released more quickly but is a fairly big change.

Another is to somehow determine whether the teardown can be run on the same thread as the last test completed. That would allow faster release in many most cases, while still using normal scheduling when the teardown called for a different thread. This probably boils down to checking the required Apartment, but it would take some analysis to be sure.

Note that this issue only arises if both the fixture and the test cases are run in parallel.

+1 on this issue.

My group is also running concurrent fixtures that can run as high as 60 per project/assembly. Each test class inherits from a base class containing OneTimeSetUp and OneTimeTearDown which manage the driver resources for that fixture.

Our test runner hosts (8 x 2.9Ghz + 15GB RAM) are grinding to a halt due to memory saturation at about the 20th fixture (ie 20 open browsers, many of which are inactive). When running a smaller set of fixtures it is clear that OneTimeTearDown not executing until all fixtures have completed their test runs as drivers/browsers are not disposed until the end of the entire run.

As the other reporter noted, once we rolled back our test runner pool to 3.6.1, the issue disappeared. With this version, the active driver/browser count is almost always equivalent to the configured number of workers so memory management is not a problem.

I'd be happy to provide more detailed debug info if needed.

p.s. Thank you for all your great work on this project over the years!

othersuttree · Aug 3, 2017

+1 on this issue.

My group is also running concurrent fixtures that can run as high as 60 per project/assembly. Each test class inherits from a base class containing OneTimeSetUp and OneTimeTearDown which manage the driver resources for that fixture.

Our test runner hosts (8 x 2.9Ghz + 15GB RAM) are grinding to a halt due to memory saturation at about the 20th fixture (ie 20 open browsers, many of which are inactive). When running a smaller set of fixtures it is clear that OneTimeTearDown not executing until all fixtures have completed their test runs as drivers/browsers are not disposed until the end of the entire run.

As the other reporter noted, once we rolled back our test runner pool to 3.6.1, the issue disappeared. With this version, the active driver/browser count is almost always equivalent to the configured number of workers so memory management is not a problem.

I'd be happy to provide more detailed debug info if needed.

p.s. Thank you for all your great work on this project over the years!

Unfortunately, the behavior in 3.6.1 was incorrect. The teardown always ran on the same thread as the last test to complete. This is not a problem if the thread requirements of each test match those of the fixture, but it is incorrect if any test has different requirements (e.g. ApartmentState) and that test happens to be the last one to run.

We don't need +1s on this issue, we have accepted that it's a problem. A specific proposal that takes into account the various factors would speed it along.

CharliePoole · Aug 3, 2017

Unfortunately, the behavior in 3.6.1 was incorrect. The teardown always ran on the same thread as the last test to complete. This is not a problem if the thread requirements of each test match those of the fixture, but it is incorrect if any test has different requirements (e.g. ApartmentState) and that test happens to be the last one to run.

We don't need +1s on this issue, we have accepted that it's a problem. A specific proposal that takes into account the various factors would speed it along.

@CharliePoole

I might have found a workaround, or it's incorrect behaviour just like in 3.6.1, as @CharliePoole stated in his previous comment.

In my test setup (from my first post) I added a new base class and gave it [Parallelizable(ParallelScope.Default)] attribute - all other fixtures inherit after it. Running all the tests now gives me the same "expected" result as in 3.6.1.

Current test setup for NUnit 3.7.1 looks like this:

using System.Threading;
using NLog;
using NUnit.Framework;

namespace Skanska.Korab2.UITests.Infrastructure.Tests
{
    [Parallelizable(ParallelScope.Default)]
    class Base
    {
    }

    class Common
    {
    [...]
    }

    class Class1Fast : Base
    {
    [...]
    }

    class Class2Slow : Base
    {
    [...]
    }

    class Class3Slow : Base
    {
    [...]
    }

    class Class4 : Base
    {
    [...]
    }

    class Class5 : Base
    {
    [...]
    }

    class Class6 : Base
    {
    [...]
    }

    class Class7 : Base
    {
    [...]
    }

    class Class8Slow : Base
    {
    [...]
    }
}

AssemblyInfo remained unchanged from that in my first post (still has [assembly: Parallelizable(ParallelScope.Fixtures)])

Any idea why ParallelScope.Default "fixes" it?

jtomkiew-ITM · Aug 4, 2017

I might have found a workaround, or it's incorrect behaviour just like in 3.6.1, as @CharliePoole stated in his previous comment.

In my test setup (from my first post) I added a new base class and gave it [Parallelizable(ParallelScope.Default)] attribute - all other fixtures inherit after it. Running all the tests now gives me the same "expected" result as in 3.6.1.

Current test setup for NUnit 3.7.1 looks like this:

using System.Threading;
using NLog;
using NUnit.Framework;

namespace Skanska.Korab2.UITests.Infrastructure.Tests
{
    [Parallelizable(ParallelScope.Default)]
    class Base
    {
    }

    class Common
    {
    [...]
    }

    class Class1Fast : Base
    {
    [...]
    }

    class Class2Slow : Base
    {
    [...]
    }

    class Class3Slow : Base
    {
    [...]
    }

    class Class4 : Base
    {
    [...]
    }

    class Class5 : Base
    {
    [...]
    }

    class Class6 : Base
    {
    [...]
    }

    class Class7 : Base
    {
    [...]
    }

    class Class8Slow : Base
    {
    [...]
    }
}

AssemblyInfo remained unchanged from that in my first post (still has [assembly: Parallelizable(ParallelScope.Fixtures)])

Any idea why ParallelScope.Default "fixes" it?

I stated earlier that the problem only arises when both fixtures and tests are parallel. I'm not 100% sure of this - it may be a problem whenever the fixtures are run in parallel. Whoever works the issue will have to debug to see if that's so.

But in any case, when you use ParallelScope.Default, you are overriding the assembly level setting. Your fixtures are no longer being run in parallel, so the problem does not arise.

CharliePoole · Aug 4, 2017

I stated earlier that the problem only arises when both fixtures and tests are parallel. I'm not 100% sure of this - it may be a problem whenever the fixtures are run in parallel. Whoever works the issue will have to debug to see if that's so.

But in any case, when you use ParallelScope.Default, you are overriding the assembly level setting. Your fixtures are no longer being run in parallel, so the problem does not arise.

when you use ParallelScope.Default, you are overriding the assembly level setting. Your fixtures are no longer being run in parallel

That's what I thought, but they do run in parallel - with both Parallelizable(ParallelScope.Fixtures) on assembly level and Parallelizable(ParallelScope.Default) on base fixture, all fixtures run in parallel and OneTimeTearDown's are run right after its fixture tests (just like in 3.6.1, but using 3.7.1).

the problem only arises when both fixtures and tests are parallel

I guess in this case Parallelizable(ParallelScope.Default) on base fixture is overriding tests' ability to be run in parallel, but not fixtures', which are set at the assembly level.

jtomkiew-ITM · Aug 4, 2017

when you use ParallelScope.Default, you are overriding the assembly level setting. Your fixtures are no longer being run in parallel

That's what I thought, but they do run in parallel - with both Parallelizable(ParallelScope.Fixtures) on assembly level and Parallelizable(ParallelScope.Default) on base fixture, all fixtures run in parallel and OneTimeTearDown's are run right after its fixture tests (just like in 3.6.1, but using 3.7.1).

the problem only arises when both fixtures and tests are parallel

I guess in this case Parallelizable(ParallelScope.Default) on base fixture is overriding tests' ability to be run in parallel, but not fixtures', which are set at the assembly level.

Interesting. That calls for some debugging I guess.

FWIW, ParallelScope.Default is not intended to be used by users. We hide it in the Intellisense, but a bug in VS is currently making it visible. It's an internal setting that means "no parallelizable attribute was used." I think we will eventually want to separate the internal settings from the user settings, as should have been done in the first place.

Writing the above, it begins to make sense. The attribute tricks NUnit into believing that no attribute was used, so the assembly-level attribute rules.

CharliePoole · Aug 4, 2017

Interesting. That calls for some debugging I guess.

FWIW, ParallelScope.Default is not intended to be used by users. We hide it in the Intellisense, but a bug in VS is currently making it visible. It's an internal setting that means "no parallelizable attribute was used." I think we will eventually want to separate the internal settings from the user settings, as should have been done in the first place.

Writing the above, it begins to make sense. The attribute tricks NUnit into believing that no attribute was used, so the assembly-level attribute rules.

@nunit/framework-team @nunit/core-team
What do you think? I"m coming to believe that we should try to run all fixture teardowns as soon as possible, since they may release resources that would otherwise be held.

CharliePoole · Aug 4, 2017

@nunit/framework-team @nunit/core-team
What do you think? I"m coming to believe that we should try to run all fixture teardowns as soon as possible, since they may release resources that would otherwise be held.

What do you think? I"m coming to believe that we should try to run all fixture teardowns as soon as possible, since they may release resources that would otherwise be held.

I definitely agree. This would bring a return of the memory issues we were facing around 3.0. I don't believe we've upgraded all of our test suites to 3.7 yet, but in some places this could ground things to a halt.

ChrisMaddock · Aug 5, 2017

What do you think? I"m coming to believe that we should try to run all fixture teardowns as soon as possible, since they may release resources that would otherwise be held.

I definitely agree. This would bring a return of the memory issues we were facing around 3.0. I don't believe we've upgraded all of our test suites to 3.7 yet, but in some places this could ground things to a halt.

(Of course, this is more specific, as it only affects tests with OneTimeTearDown's rather than all tests - but would otherwise cause a major issue for us.)

ChrisMaddock · Aug 5, 2017

(Of course, this is more specific, as it only affects tests with OneTimeTearDown's rather than all tests - but would otherwise cause a major issue for us.)

Actually I think it may affect all tests. Even if there is no one time teardown per se, that's where we release the reference.

CharliePoole · Aug 5, 2017

Actually I think it may affect all tests. Even if there is no one time teardown per se, that's where we release the reference.

I changed the title to reflect the objective. Since this pertains to an area I worked in, I'm assigning it to myself.

CharliePoole · Aug 5, 2017

I changed the title to reflect the objective. Since this pertains to an area I worked in, I'm assigning it to myself.

CharliePoole changed the title from All [OneTimeTearDown] methods are executed in bulk when first available thread finishes to Execute OneTimeTearDown as early as possible when running fixtures in parallel Aug 5, 2017

CharliePoole self-assigned this Aug 5, 2017

CharliePoole added is:enhancement pri:high labels Aug 5, 2017

CharliePoole referenced this issue Aug 6, 2017
Merged
Execute OneTimeTearDown as early as possible #2350

rprouse closed this in #2350 Aug 9, 2017

rprouse added the closed:done label Aug 22, 2017

rprouse added this to the 3.8 milestone Aug 22, 2017

nunit/nunit

Join GitHub today

Execute OneTimeTearDown as early as possible when running fixtures in parallel #2335

Comments

jtomkiew-ITM commented Jul 28, 2017

Setup:

Problem:

Example:

Tests:

AssemblyInfo.cs

Result:

Expected result:

Previous versions:

This comment has been minimized.

CharliePoole commented Jul 30, 2017

This comment has been minimized.

jtomkiew-ITM commented Jul 31, 2017

This comment has been minimized.

CharliePoole commented Jul 31, 2017 • edited

This comment has been minimized.

jtomkiew-ITM commented Aug 1, 2017

This comment has been minimized.

CharliePoole commented Aug 1, 2017

This comment has been minimized.

othersuttree commented Aug 3, 2017

This comment has been minimized.

CharliePoole commented Aug 3, 2017

This comment has been minimized.

jtomkiew-ITM commented Aug 4, 2017

This comment has been minimized.

CharliePoole commented Aug 4, 2017

This comment has been minimized.

jtomkiew-ITM commented Aug 4, 2017

This comment has been minimized.

CharliePoole commented Aug 4, 2017

This comment has been minimized.

CharliePoole commented Aug 4, 2017

This comment has been minimized.

ChrisMaddock commented Aug 5, 2017 • edited

This comment has been minimized.

ChrisMaddock commented Aug 5, 2017

This comment has been minimized.

CharliePoole commented Aug 5, 2017

CharliePoole changed the title from All [OneTimeTearDown] methods are executed in bulk when first available thread finishes to Execute OneTimeTearDown as early as possible when running fixtures in parallel Aug 5, 2017

This comment has been minimized.

CharliePoole commented Aug 5, 2017

CharliePoole self-assigned this Aug 5, 2017

CharliePoole added is:enhancement pri:high labels Aug 5, 2017

CharliePoole referenced this issue Aug 6, 2017

rprouse closed this in #2350 Aug 9, 2017

rprouse added the closed:done label Aug 22, 2017

rprouse added this to the 3.8 milestone Aug 22, 2017

CharliePoole commented Jul 31, 2017 •

edited

ChrisMaddock commented Aug 5, 2017 •

edited