Welcome Guest! To enable all features please Login or Register.

Notification

Icon
Error
Slow performance on writing testoutput using XUnit V3 and ITestOutputHelper
Options
Previous Topic Next Topic
erwinvandervalk
#1 Posted : Tuesday, March 11, 2025 2:11:34 PM(UTC)
Rank: Member

Groups: Registered
Joined: 12/23/2019(UTC)
Posts: 15
Location: Netherlands

Thanks: 3 times
Was thanked: 4 time(s) in 4 post(s)
Hi,

I ran into a weird situation today with one of our FOSS solutions. I added log writing and it caused a very noticeable delay.

Even a test like this takes in ncrunch 2+ seconds to run (but only in this solution). If I add this test to an empty solution (or to any other solutions), there's no delay.

Code:

public class MyTest(ITestOutputHelper output)
{
    [Fact]
    public void Can_Write()
    {
        for (int i = 0; i < 100; i++)
        {
            output.WriteLine(new string('a', 100));
        }
    }

}



When I run the tests using Resharper or using dotnet test, it runs fine (20 ms). If I change the output writing away from ITestOutputHelper to console.writeline ( then it's as fast as normal). NCrunch does report a hotspot around the TestLoggerProvider (which calls IOutputHelper).

I have submitted a bug report, which I hope also includes environmental info. Also I have verified that this problem doesn't only exist on my machine, but also on a colleague's machine.

You can checkout the branch yourself here if you wish to see what's going on.
https://github.com/Duend...oss/tree/ev/atm/no-wait

Grateful for any support you could provide.
Keep up the great work!

Erwin
Back to top
 |  Edit by user
Remco
#2 Posted : Tuesday, March 11, 2025 11:21:59 PM(UTC)
Rank: NCrunch Developer

Groups: Administrators
Joined: 4/16/2011(UTC)
Posts: 7,237

Thanks: 975 times
Was thanked: 1313 time(s) in 1218 post(s)
Hi Erwin,

Thanks for sharing this issue.

Could you try disabling RDI to see if this makes any difference? You can do this either via [EnableRdi(false)] on the test or through the 'Enable Rdi' NCrunch config setting.

Edit: I just checked this myself, and it's not RDI. It looks like this is being caused by the way data is being piped through Xunit3. Under NCrunch, Xunit3 pipes data from tests via stdout, which is somewhat slow when dealing with many fast, small requests. This problem doesn't exist when using Xunit3 under other runners, because their adapters used a different architecture. The problem isn't in NCrunch itself, so I don't have the ability to resolve it directly. You could try raising it with the Xunit team. My suggestion would be to use an abstraction and simply write to Console or Debug output (we're able to intercept these inside the NCrunch environment and handle them more efficiently).

I should clarify that this is probably a pretty niche issue. The test in question here writes to output only one character at a time, which is never going to be especially efficient. Writing data in bulk will be much faster.
Back to top
 |  Edit by user
erwinvandervalk
#3 Posted : Wednesday, March 12, 2025 6:50:37 AM(UTC)
Rank: Member

Groups: Registered
Joined: 12/23/2019(UTC)
Posts: 15
Location: Netherlands

Thanks: 3 times
Was thanked: 4 time(s) in 4 post(s)
Hi Remco, thank you for your quick reply.

I did raise the issue with the XUnit team: https://github.com/xunit/xunit/issues/3218.

However, I'd like to push back against this being a 'niche' issue. I usually write my tests in a integration test style, where I spin up an in-memory representation of (part) of my app, then run scenarios against them. The log output (which is very valuable) is then piped to the xunit output writer.

But even if you don't, I would certainly argue that unit tests should emit some log messages so failures can be analyzed without debugging (ie: during CI). In this example test, I'm only writing 100 log messages and this causes a 2 second delay for each test. This pretty much renders the immediate feedback from ncrunch useless.

Sure, I could put in an adapter that detects if the test is running in ncrunch and writes the output then to console, but this does feel like something ncrunch should be able to handle for me. Not everybody in the team is using ncrunch (lots of mac users) so it's hard to justify adding code like this.

I do realize that xunit's new architecture probably is difficult to support.

with kind regards,
Erwin
Back to top
erwinvandervalk
#4 Posted : Wednesday, March 12, 2025 7:18:10 AM(UTC)
Rank: Member

Groups: Registered
Joined: 12/23/2019(UTC)
Posts: 15
Location: Netherlands

Thanks: 3 times
Was thanked: 4 time(s) in 4 post(s)
However if other people are also running into this, this is my workaround for now:

#if NCRUNCH
Console.WriteLine(message);
#else
_writeOutput?.Invoke(message);
#endif
Back to top
Remco
#5 Posted : Wednesday, March 19, 2025 11:39:53 AM(UTC)
Rank: NCrunch Developer

Groups: Administrators
Joined: 4/16/2011(UTC)
Posts: 7,237

Thanks: 975 times
Was thanked: 1313 time(s) in 1218 post(s)
I've raised this with Brad Wilson (Xunit developer) and he's created a ticket for it: https://github.com/xunit/xunit/issues/3228.

The background for this is that Xunit has two modes of operation for reporting of test results. One is asynchronous (used by other test runners), the other is synchronous (used by NCrunch). NCrunch requires test results to be reported synchronously because we need to track the definite start and end point of each test, otherwise all our metrics tracking (code coverage, performance, RDI) goes askew.

This problem occurs in Xunit primarily when it's set to report results synchronously. Actually, it probably happens to a degree when it's asynchronous too, but the async architecture provides significant compensation by moving work onto background threads.

The mentioned ticket suggests a possible optimisation which would greatly reduce the overhead for reporting test results when working with an in-memory runner (such as NCrunch), thereby preventing the synchronous reporting from slowing down the runner.

Xunit3 is still very new and we're still working out the kinks here. I appreciate your patience with this issue.
Back to top
1 user thanked Remco for this useful post.
erwinvandervalk on 3/19/2025(UTC)
Users browsing this topic
Guest
Forum Jump  
You cannot post new topics in this forum.
You cannot reply to topics in this forum.
You cannot delete your posts in this forum.
You cannot edit your posts in this forum.
You cannot create polls in this forum.
You cannot vote in polls in this forum.

YAF | YAF © 2003-2011, Yet Another Forum.NET
This page was generated in 0.040 seconds.
Trial NCrunch
Take NCrunch for a spin
Do your fingers a favour and supercharge your testing workflow
Free Download