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.
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/DuendeSoftware/foss/tree/ev/atm/no-wait
Grateful for any support you could provide.
Keep up the great work!
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.
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.
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.