Test method EventSource for easier diagnostics

[adamsitnik]

Hello everyone!

I was recently wondering how I could reduce the time it takes to run all dotnet/runtime unit tests. I've done some profiling and realized, that for many CPU-bound unit tests projects we are not even close to using 50% of all the CPU cores. Example: System.Linq.Tests use 15% of all my 24 cores.

The best way to visualize such information is by using dedicated tools like Concurrency Visualizer or Chromium Developer Tools.

But these tools need some extra information, which can be emitted by using EventSource (part of .NET Standard 1.1).

So I've forked xUnit and extended it with custom EventSource and the logic that simply logs start and stop events for every test invocation. The code itself is very simple:

using System.Diagnostics.Tracing;

namespace Xunit.Sdk
{
    [EventSource(Name = SourceName, Guid = "ae399e80-45fc-4219-aacc-b73a458ad7e1")]
    internal sealed class TestMethodEventSource : EventSource
    {
        internal const string SourceName = "xUnit.TestMethodEventSource";

        internal const int TestMethodStartEventId = 1;
        internal const int TestMethodStopEventId = 2;

        internal class Tasks
        {
            internal const EventTask TestMethod = (EventTask)1;
        }

        internal static readonly TestMethodEventSource Log = new TestMethodEventSource();

        private TestMethodEventSource() { }

        [Event(TestMethodStartEventId, Level = EventLevel.Informational, Task = Tasks.TestMethod, Opcode = EventOpcode.Start)]
        internal void TestMethodStart(string testMethodId) => WriteEvent(TestMethodStartEventId, testMethodId);

        [Event(TestMethodStopEventId, Level = EventLevel.Informational, Task = Tasks.TestMethod, Opcode = EventOpcode.Stop)]
        internal void TestMethodStop(string testMethodId) => WriteEvent(TestMethodStopEventId, testMethodId);
    }
}

if (TestMethodEventSource.Log.IsEnabled())
{
    TestMethodEventSource.Log.TestMethodStart(DisplayName);
}

var result = CallTestMethod(testClassInstance);

if (TestMethodEventSource.Log.IsEnabled())
{
    TestMethodEventSource.Log.TestMethodStop(DisplayName);
}

I've configured VS Concurrency Visualizer to log these events (every event is disabled by default):

And profiled the test project.

The Concurrency Visualizer recognizes Start & Stop events and displays them nicely in the Threads view. In the following example I was able to quickly identify few unit tests that run alone when all other tests have already finished:

@bradwilson would you be interested in me adding such EventSource to xUnit? I could provide implementation for all versions and documentation with examples. EventSource is part of .NET Standard 1.1 and logging is disabled by default, so there is no perf penalty for users who don't use it. Start & Stop events are recognized by other profilers and diagnostics software.

[bradwilson]

Sure, that would be great!

[roji]

@adamsitnik want this :)

[bradwilson]

The event source is now available in pre-release builds.

Available in v2 2.7.1-pre.5
Available in v3 0.1.1-pre.375

@adamsitnik has an open PR for documentation that needs to be iterated on, because in particular, Concurrency Visualizer has strict requirements regarding threads that xUnit.net cannot comply with. So when using CV and visualizing your tests, you may run into situations where you see start & stop events that are "disconnected" from one another by virtue of being on different threads. Purely synchronous tests should not have issues here, and in theory tests which use only async and await should also work, but in practice we've found instances which should've correlated but don't. Even so, you should still be able to see the disconnected start/stop events as red diamonds and do manual correlation yourself in terms of timing.

As an example, here is some timing from running xunit.v3.assert.tests:

Most of the tests are successfully correlated start/stop, but some still show up as red diamonds and mismatched pairs of start/stop, which you could track down by hand if needed. (You'll probably need to click through the image to see any level of detail.)

[bradwilson]

I'm going to leave this issue open until we have the docs finalized and deployed.

[bradwilson]

It's probably also worth pointing out that any test which is async will have "questionable" timing, since any time await is hit, the worker thread is given back to xUnit.net to run other things, and a test may not return to running status until much later when it gets another turn at the thread pool. Our default for thread pool size is one thread per CPU thread (as exposed to the OS), and most test projects will have significantly more tests than you have CPU threads. 😄 The primary value here is going to be for synchronous tests, which should not have correlation issues.

[bradwilson]

Alternatively, if you're just looking for a way to find long-running tests, you can enable long running test detection support. Combining this with disabling parallelization (and only running a single test project on an otherwise idle machine) will help to give very accurate timing of individual tests, even though the full test run may take significantly longer as a result.