Same test takes longer to run if it's running at the end rather than the beginning of a test suite

[WindingWinter]

I don't think this must be a Nunit or NUnit console bug per se, but I still want to post it here in the hopes that someone with familiarity with the underlying Nunit can shed some lights on this.

I have a test at the beginning of the test suite ( because I put it in a namespace that starts with A), it's really just a time waster:

        [Test]
        public void FirstTestRun()
        {
            void DummyFunction(int nCount)
            {
                for (int j = 0; j < nCount; j++)
                {
                    for (int i = 0; i < nCount; i++)
                    {
                        int sst = 0;
                        sst += 4;
                        var random = new Random();

                        // Generate a random integer
                        int randomNumber = random.Next();
                    }
                }

            }

            var stopWatch = new Stopwatch();
            stopWatch.Start();
            DummyFunction((int)Math.Pow(10, 3));
            TestContext.WriteLine($"Running Time for {nameof(AAATest)}{nameof(FirstTestRun)} {stopWatch.ElapsedMilliseconds}");
            stopWatch.Stop();
        }

And the same test function is put in another class ( this time with a namespace that starts with Z). There are around 400 tests that separate these two tests.

Since the content of the test is the same, so I would expect that the running time should be the same (~400 ms).

But while the first test finishes in around 400ms, the second test finishes in around 2300 ms! More than 5X the difference.

I've made sure that

1. My computer has enough memory all the time. The memory usage never exceeds 70%. So Garbage Collection is not an issue.
2. No other processes are running at that time
3. I'm running it via nunit-console, and only one single process is running because it has only one test assembly running at that time.

It seems that it must be that the additional tests running in between of these two tests that contribute to the slowness of the second test run. But from what I know each test is quite independent of each other ( they create their own Autofac container and dispose them after a test is finished), there seems no reason why additional prior test runs will impact the time.

Why is this happening? Any ideas?

[stevenaw]

I agree it's likely related to some of the work going on in your suite. Have you tried have that test duplicated in namespace "A" and "Z" with no other tests in between?

If the timing of that is the same then I'd suggest trying to use a profiler on the full test run to try to find the cause. Visual Studio 17.8 or JetBrains are options for profiling tests, but you may research others too based on which licenses you may have available to you.

In particular I would watch out for if there are lots of large allocations over 85KB or if there are lots of Gen2 garbage collections (https://learn.microsoft.com/en-us/dotnet/standard/garbage-collection/large-object-heap).

[WindingWinter]

Your point about large allocation is interesting: but why would that contribute to program slowing down, given that I still have plenty of unused memory and GC doesn't have to work?

…

On Wed, Mar 20, 2024, 6:29 PM Steven Weerdenburg ***@***.***> wrote: I agree it's likely related to some of the work going on in your suite. Have you tried have that test duplicated in namespace "A" and "Z" with no other tests in between? If the timing of that is the same then I'd suggest trying to use a profiler on the full test run to try to find the cause. Visual Studio 17.8 or JetBrains are options for profiling tests, but you may research others too based on which licenses you may have available to you. In particular I would watch out for if there are lots of large allocations over 85KB or if there are lots of Gen2 garbage collections ( https://learn.microsoft.com/en-us/dotnet/standard/garbage-collection/large-object-heap ). — Reply to this email directly, view it on GitHub <#4667 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADENIZSSZR4NY6HZ33M6ZB3YZFQHZAVCNFSM6AAAAABE7GDBBWVHI2DSMVQWIX3LMV43SRDJONRXK43TNFXW4Q3PNVWWK3TUHM4DQNJRGA2TI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[stevenaw]

There's a bit more nuance to garbage collection than just the amount of physical memory on the machine so having free memory on the machine doesn't automatically mean there's no garbage collections happening. The link I shared above gives a bit more info, as does https://learn.microsoft.com/en-us/dotnet/standard/garbage-collection/fundamentals#conditions-for-a-garbage-collection

My suggestion to identify if your tests or system under test is doing any large allocations will help identify if any particularly expensive (non-ephemeral) collections may be taking place. Ultimately, this is a bit of guess work on my part though. The best tool to help identify what's going on is to profile your suite.

[stevenaw]

Another way to emulate and verify if this is related to your suite or not is that instead of removing the main tests of the suite, you can make a new suite and emulate running the same number of empty tests by using a TestCaseSource. This will force NUnit to do similar work as in the suite you're seeing the issues on and so any differences between runs would hint too at if the issue is within something your tests or system under test is doing.

Untested code:

[TestCaseSource(nameof(GeneratorFunction))]
public static void TestMethod(int a) {
  Assert.Pass();
}

public static IEnumerable<object> GeneratorFunction() {
  const int TEST_CASE_COUNT = 400;
  for (var i = 0; i < TEST_CASE_COUNT; i++)
    yield return i;
}

[WindingWinter]

@stevenaw , with your code, I can confirm that the time taken is about the same for the first and last test. Therefore most likely problem lies with my code. Thanks for the pointer.

[stevenaw]

Thanks for the update @WindingWinter I'm glad I was able to help narrow it down for you.