add TestEventSource and use it in TestInvoker

[adamsitnik]

This PR contributes to #2484 by introducing a new type that derives from EventSource and defines Start and Stop events. These two events are raised only when tracing is enabled.

I've not provided any tests, as it would be quite hard to test: we would need to run as Admin on Windows, enable tracing, start a new trace, start the test project in a standalone process, stop the tracing and read the trace file to search for the events.

I am going to send 2nd PR with docs update.

[adamsitnik]

@bradwilson please let me know if you would accept a PR that backports this feature to v2 branch. Thanks!

[bradwilson]

How expensive/dynamic is this (meaning, is this worth caching)? I assume it's cheap since it would be counterproductive for it to be expensive, but I really don't know anything about the event source pipeline.

[bradwilson]

Or even, does consistency matter? (i.e., does it matter if there's a stop without first seeing a start?)

[adamsitnik]

How expensive/dynamic is this (meaning, is this worth caching)?

It's very cheap (it was designed to have absolute minimal overhead), we don't even cache it in BCL: https://github.com/search?q=repo%3Adotnet%2Fruntime%20%22Log.IsEnabled%22&type=code

does it matter if there's a stop without first seeing a start?

this is very important, otherwise the Concurrency Visualizer complains and can not visualize it properly

[bradwilson]

Does that mean we should only check once at the start, and only send the stop if we sent the start? That's a pretty simple change.

[bradwilson]

let me know if you would accept a PR that backports this feature to v2 branch.

Absolutely!

[bradwilson]

Do you see value in other event as well?

[bradwilson]

I'm going to do a little style edit and move the event source into a new folder.

[adamsitnik]

Do you see value in other event as well?

We could emit start and stop for the whole type that contains the tests. This is how it could look like (I took the SS from BenchmarkDotNet where I've implemented it a while ago):

[bradwilson]

Okay, let's do start/stop for types as well. If you think the change to ensure we only send stop if we sent start is also correct, let's do that as well.

[bradwilson]

I'm working on something else for a different PR at the moment. I can add these if you haven't gotten to it when I get free time. 😄

[bradwilson]

@adamsitnik Okay, looking for some feedback.

I added events for start/stop of assembly, test collection, and test class (in addition to test, which was already there). I added task types for all four, and event IDs for all four. I set the event IDs in groups of 100 in the event that we want to add more events later (for example, if we want to report test status).

I moved the reporting of test from TestInvoker.CallTestMethod to TestInvoker.InvokeTestMethodAsync because the latter is what does the waiting for async tests, so with the code where it was, the Stop event would have fired at the moment of the first await from the test method, and we actually want it to fire after the test method completes. Plus, CallTestMethod is purposefully a one-liner because it's intended to be replaced, and I didn't want to put any additional burdens on someone who overrides it (like the async wait, and now the event logging).

Also as we discussed above, I did cache the call to TestEventSource.Log.IsEnabled() to ensure that we'll never send a Stop event if we didn't send the Start event.

So please review the code and let me know if you think everything I've done is correct.

Additional question: Should there be some way in the event to correlate things together? For example, right now, there's no data in the reporting of a test which says "it belongs to this test class". Does that matter? If so, what's the appropriate way to create that correlation? I didn't see anything in these docs about correlation.

[bradwilson]

The easiest way for me to test this is to merge it and try it. :) So I will do that later today. Feel free to leave feedback even after the merge, since this will end up as the basis for the v2 back-port.

[bradwilson]

Turns out I didn't have to merge to test, of course I could just test it with the existing test projects. 😄 Which is good because it was broken because of my argument types. That was easy to fix.

However, I'm confused by the results I got running xunit.v3.assert.tests with it. I'm seeing things that don't make sense, like:

• Multiple start instances for the test assembly
• Multiple things that have starts but no stops
• Multiple things that have stops but no starts

Here's a screen shot that shows some of what I'm seeing:

For starters, the only markers I'm collecting are xUnit.TestEventSource, and I'm collecting them with normal priority.

The top three lines are all theoretical start events for the test assembly, from three different threads, with three wildly different start times. This really makes no sense to me and I'm not even sure how that's feasible. In this scenario, the assembly runner only runs once, so I'm not sure how we're seeing multiple start events.

The missing begin or end events, combined with the priority setting, make it feel like this is an event sampling technique and it's just missing events because of that. Am I correct in that assumption?

Can you help me interpret any of this @adamsitnik? 😂

[bradwilson]

Okay, well adding some Console.WriteLines has definitely elucidated that somehow I am definitely starting the test assembly more than once, and I have no idea why (yet):

xUnit.net v3 In-Process Runner v0.1.1-pre.369-dev+579cb5d6cd (64-bit .NET 6.0.27)
  Discovering: xunit.v3.assert.tests (method display = ClassAndMethod, method display options = None)
  Discovered:  xunit.v3.assert.tests (1121 test cases to be run)
*** Test Assembly Start on Thread 6 ***
  Starting:    xunit.v3.assert.tests (parallel test collections = on [24 threads], stop on fail = off, explicit = off, seed = 1279909920, culture = invariant)
*** Test Assembly Start on Thread 4 ***
*** Test Assembly Start on Thread 7 ***
*** Test Assembly Stop on Thread 4 ***
*** Test Assembly Stop on Thread 4 ***
*** Test Assembly Start on Thread 4 ***
*** Test Assembly Stop on Thread 4 ***
*** Test Assembly Stop on Thread 7 ***
  Finished:    xunit.v3.assert.tests
=== TEST EXECUTION SUMMARY ===
   xunit.v3.assert.tests  Total: 1352, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0, Time: 0.145s

[bradwilson]

Okay, phew. That's my acceptance tests. They fire up the whole machinery of stuff, and there are 3 of them in the assertion tests. I didn't think there were any, that's why I was so confused. 😂

[bradwilson]

Okay, so, for starters it appears that Concurrency Visualizer does not appreciate getting the start and stop events from different threads. It will not correlate them, because now I see the one and only assembly start and assembly stop, but they are marked as being a start without a stop, and a stop without a start, on two different threads:

Is there a way I can tell Concurrency Visualizer to stop doing this? 😂 I fear without it being able to correlate things starting on one thread and stopping on another, that the reporting will not be useful (at the very least, for Concurrency Visualizer).

[bradwilson]

On the plus side, I feel like utilization for the CPU from a single project is fairly good with this test assembly, which is primarily compute-bound.

[bradwilson]

The more I think about this, the more I'm convinced that Concurrency Visualizer isn't necessarily going to help, because we in no way guaranteeing that async tests will return back to the original thread they started on (and in fact, that's counter to our maximum utilization strategy).

So is this EventSource stuff still useful outside that context?

[adamsitnik]

Okay, so, for starters it appears that Concurrency Visualizer does not appreciate getting the start and stop events from different threads. It will not correlate them, because now I see the one and only assembly start and assembly stop, but they are marked as being a start without a stop, and a stop without a start, on two different threads

This is a great question. I don't know the answer, but here is what I've found.

According to https://learn.microsoft.com/en-us/dotnet/core/diagnostics/eventsource-activity-ids:

It's now common to use async and await so that a single request could be handled partially on many different threads before the work is complete. Thread IDs are no longer sufficient to correlate together all the messages produced for one request. Activity IDs solve this problem. They provide a finer grain identifier that can track individual requests, or portions of requests, regardless of if the work is spread across different threads.

The examples provided in this doc don't set the activity ID in explicit way:

private static async Task ProcessWorkItem(string requestName)
{
    DemoEventSource.Log.WorkStart(requestName);
    await HelperA();
    await HelperB();
    DemoEventSource.Log.WorkStop();
}

There is a heuristic:

EventSource has an automatic heuristic where defining an event named _Something_Start followed immediately by another event named _Something_Stop is considered the start and stop of a unit of work. Logging the start event for a new unit of work creates a new Activity ID and begins logging all events on the same thread with that Activity ID until the stop event is logged. The ID also automatically follows async control flow when using async and await.

My current understanding is that we have few options right now:

1. The code does not meet some of the heuristic criteria and does not properly set the Activity ID. I'll try to verify that later by opening the CV trace with PerfView. If this is the case we could call this overload and specify activityId and relatedActivityId in explicit way (the latter would be the Guid that describes assembly for the test class and test class for test method).
2. The Activity ID works as expected, but Concurrency Visualizer does not handle it properly.

cc @noahfalk who owns Diagnostics in .NET and contributed to the mentioned doc

[adamsitnik]

From what I can see, the Activity ID is missing for the events that CV is complaining about.

I've fetched latest changes and used CV to analyze "xunit.v3.core.tests" after re-building it.

I've found the trace files in here:

Opened the .user.etl trace with PerfView and opened the Events window, put "xunit" in the filter and "ArraysWork" (the name of the test CV was complaining aobut) in the Text Filter:

The Stop event was missing Activity ID

[bradwilson]

The ID also automatically follows async control flow when using async and await.

We schedule work on our own set of background threads, so this automatic heuristic would not apply to us.

The Stop event was missing Activity ID

I'm going to try this and see if that fixes it: https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.tracing.eventsource.writeeventwithrelatedactivityid

[bradwilson]

That didn't work, but this seems to have done the trick for the assembly start/stop:

var logEnabled = TestEventSource.Log.IsEnabled();
var activityId = Guid.Empty;

if (logEnabled)
{
	activityId = Guid.NewGuid();
	EventSource.SetCurrentThreadActivityId(activityId);
	TestEventSource.Log.TestAssemblyStart(ctxt.TestAssembly.Assembly.AssemblyPath ?? "<dynamic>", ctxt.TestAssembly.ConfigFileName ?? "<none>");
}

try
{
	// ...
}
finally
{
	if (logEnabled)
	{
		EventSource.SetCurrentThreadActivityId(activityId);
		TestEventSource.Log.TestAssemblyStop(ctxt.TestAssembly.Assembly.AssemblyPath ?? "<dynamic>", ctxt.TestAssembly.ConfigFileName ?? "<none>");
	}
}

I'm going to propagate this everywhere and see if it fixes everybody. It would certainly make this challenging if we wanted to do more than just start/stop (like flagging individual actions) because then we'd need to find a way to pass the Guid around, but at least is a start.

[bradwilson]

Nope, I was bitten by coincidence. That didn't actually fix it.

[bradwilson]

Okay, still stuck, and out of ideas.

[bradwilson]

Eh, I've got one more idea to try (grabbing the ID after the start has been issued)

[bradwilson]

Nope, that doesn't do it either. 😞

[adamsitnik]

I've tried following code:

internal void TestStart(string testName, Guid activityId)
{
	EventSourceOptions startOptions = new()
	{
		Level = EventLevel.Informational,
		Keywords = EventKeywords.All,
		Opcode = EventOpcode.Start
	};
	var copy = activityId;
	Guid emptyGuid = Guid.Empty;
	var data = new { testName = testName };
	Write("TestMethod", ref startOptions, ref copy, ref emptyGuid, ref data);
}

internal void TestStop(string testName, Guid activityId)
{
	EventSourceOptions stopOptions = new()
	{
		Level = EventLevel.Informational,
		Keywords = EventKeywords.All,
		Opcode = EventOpcode.Stop
	};
	var copy = activityId;
	Guid emptyGuid = Guid.Empty;
	var data = new { testName = testName };
	Write("TestMethod", ref stopOptions, ref copy, ref emptyGuid, ref data);
}

the right ETW events get emitted

but for some reason they are not recognized by CV. I also can't see any errors in the CV (I could when I was passing Guid by reference to both methods)

I have no idea why it does not like the "new" events. I'll try to attach a debugger to the right process tomorrow and see what is going on.

[adamsitnik]

Currently the only difference is lack of Task = Tasks.Test which is applied by [Event] attribute

[bradwilson]

So if I look at things with PerfView, it appears that Task maps to the event name that is the first argument of Write. If you don't have a Task, then the event name becomes something like EventId(n) which is the numeric event ID from [Event].

Here is without Task:

And here is with Task (Tasks.Test):

I don't understand why it picked TestStart instead of just Test. The layers of indirection here feel... strange to me.

So here's the output from the automatic stuff:

And here's the output from yours, using a name of "TestStart" to try to get it as close as possible to the original:

The only difference I see here now is the activity ID, which for the automatic stuff doesn't look like a GUID. I don't know if that's because EventSource is translating its non-random GUIDs into something easier to decode for ETW users, or because PerfView understands EventSource's non-random GUIDs and is doing the translation. I'd have to dig into the EventSource code to know for sure.

[bradwilson]

FWIW, I can't get CV to show the events when we use Write manually as opposed to WriteEvent, either. It feels like it will only show [Event] decorated methods.

[bradwilson]

I feel like we're swimming upstream here:

This is taken from https://learn.microsoft.com/en-us/visualstudio/profiling/visualizing-eventsource-events-as-markers

I am again out of ideas, and I've pushed off the next release of xUnit.net v2 for too long already, so it's going to have to ship without this. I can't wait any longer, and I feel like personally I'm just wasting time on this now. 😞

I'll leave this PR open in the event you can come up with a solution, but I'm done looking. If/when you're done looking, too, go ahead and close the PR.

[bradwilson]

@adamsitnik Based on the e-mail thread last week, is it safe to assume this is now dead? Or is there value in this PR outside of the use of Concurrency Visualizer?

[adamsitnik]

@bradwilson Please excuse me for the delay in responding and kind of wasting your time with this PR. Big thanks for your help here!

It's safe to say it's dead, unless... synchronous tests are common and we could at least use it for non-async tests. Thoughts?

Other than that my only idea (beside closing the PRs) is to send another doc PR that explains how to use CV to solve parallelization issues without the events (we can always solve the symbols and check which methods/tests were being executed). But with my current assignment to the removal of BinaryFormatter I won't be able to work on it anytime soon (next 2 months). The best I could do right now is to create an issue and start building a list of examples based on my experience.

For example, in dotnet/runtime there was a single synchronous test that was simply taking a LOT of time to execute and it was the reason why executing whole test suite on my thread ripper PC was taking so long. The example could be:

[Theory]
[InlineData(199933)]
[InlineData(39916801)]
[InlineData(479001599)]
//[InlineData(87178291199)]
public void IsPrimeNumber(long number)
{
    Assert.True(IsPrime(number));

    static bool IsPrime(long number)
    {
        for (long i = 2; i < number; i++)
        { 
            if (number % i == 0)
            {
                return false;
            }
        }
        return true;
    }
}

@bradwilson What do you think about such idea? I expect that as the owner of xUnit you may have recognized other patterns over the years.

[bradwilson]

Yeah, I'm confused (and a little saddened) by the idea that CV is supposed to support async/await but that clearly isn't the case, since this code should absolutely yield lined up start/stop for tests:

var logEnabled = TestEventSource.Log.IsEnabled();

if (logEnabled)
    TestEventSource.Log.TestStart(ctxt.Test.TestDisplayName);

try
{
    var result = CallTestMethod(ctxt, testClassInstance);
    var valueTask = AsyncUtility.TryConvertToValueTask(result);
    if (valueTask.HasValue)
        await valueTask.Value;
    else if (asyncSyncContext is not null)
    {
        var ex = await asyncSyncContext.WaitForCompletionAsync();
        if (ex is not null)
            ctxt.Aggregator.Add(ex);
    }
}
finally
{
    if (logEnabled)
        TestEventSource.Log.TestStop(ctxt.Test.TestDisplayName);
}

But it doesn't.

I'm fine with just merging the test event and removing all the other events, as the further "out" we go, the less likely that threads are to line up. I'll do that today, no work needed on your part, and get it ported over to v2 as well.

If you want to update the docs PR to talk about threading issues and CV (and/or whatever clarification you think is necessary), that'd be great. I'll finalize that once we have official releases that support the events. Thanks!

[bradwilson]

Re-running this now with just test events against xunit.v3.assert.tests, there's probably a pattern to the things that show up with misaligned events. I see EventAssertsTests.RaisesAsync, EventAssertsTests.RaisesAnyAsync, and CollectionAssertsTests.CollectionAsync, though I don't really see any reason why. The former two use an internal Task.Run, while the latter uses Task.Yield, but I don't see anything in particular that should be affecting the body of the test itself in any strange way, and all consumption by the assertion APIs is done via await. 🤷🏼