Thread pool scheduling event listener behave differently when it is run on xunit app

[NazmiAltun]

Not sure if this is a bug, so I decided to start a discussion.

I have an event listener class that listens to thread pool scheduling events. Here is the code ;

public class ThreadPoolSchedulingEventListener : EventListener
    {
        private const long ThreadPoolKeyword = 0x0002;
        private const int EnqueueId = 30;
        private const int DequeueId = 31;
        private static readonly Guid EventSourceGuid = Guid.Parse("8E9F5090-2D75-4d03-8A81-E5AFBF85DAF1");

        private readonly Action<string> _writer;

        public ThreadPoolSchedulingEventListener(Action<string> writer)
        {
            _writer = writer;
            EventSourceCreated += OnEventSourceCreated;
        }

        protected override void OnEventWritten(EventWrittenEventArgs eventData)
        {
            _writer($"EventId={eventData.EventId} Event={GetEvent(eventData.EventId)} Payload[0]={eventData.Payload[0]}");
        }

        private string GetEvent(int id)
        {
            return id == EnqueueId ? "Enqueue" : "Dequeue";
        }

        private void OnEventSourceCreated(object sender, EventSourceCreatedEventArgs e)
        {
            var es = e.EventSource;

            if (es?.Guid == EventSourceGuid)
            {
                EnableEvents(es, EventLevel.Verbose, (EventKeywords)ThreadPoolKeyword);
            }
        }

        public override void Dispose()
        {
            EventSourceCreated -= OnEventSourceCreated;
            base.Dispose();
        }
    }

When i run this code in a console application as ;

const int TaskCount = 3;
using var threadPoolSchedulingEventListener = new ThreadPoolSchedulingEventListener(Console.WriteLine);

for (var i = 0; i < TaskCount; i++)
{
   await Task.Run(() => { });
}

I get following output ;

EventId=30 Event=Enqueue Payload[0]=1548335764952
EventId=31 Event=Dequeue Payload[0]=1548335764952
EventId=30 Event=Enqueue Payload[0]=1548336147224
EventId=31 Event=Dequeue Payload[0]=1548336147224
EventId=30 Event=Enqueue Payload[0]=1548336148216
EventId=31 Event=Dequeue Payload[0]=1548336148216

So 3 tasks were scheduled to run on thread pool, and our event listener class captured Enqueue and Dequeue events for all these 3 tasks.
When i run the same code in xunit project as ;

public class ThreadPoolSchedulingEventListenerTests
    {
        private const int TaskCount = 3;
        private readonly ITestOutputHelper _testOutputHelper;

        public ThreadPoolSchedulingEventListenerTests(ITestOutputHelper testOutputHelper)
        {
            _testOutputHelper = testOutputHelper;
        }

        [Fact]
        public async Task ShouldListenAllScheduledTasks()
        {
            using var listener = new ThreadPoolSchedulingEventListener(_testOutputHelper.WriteLine);
            for (var i = 0; i < TaskCount; i++)
            {
                await Task.Run(() => { });
            }
        }
    }

This is the output ;

Standard Output Messages:
EventId=31 Event=Dequeue Payload[0]=1671971580720
EventId=30 Event=Enqueue Payload[0]=1671971336784
EventId=31 Event=Dequeue Payload[0]=1671971336784
EventId=30 Event=Enqueue Payload[0]=1671971338328
EventId=31 Event=Dequeue Payload[0]=1671971338328

So , we were unable to capture "Enqueue" event for the first task that was scheduled to run on thread pool, but we only received Dequeue event for that task. I wonder what would cause this behaviour. Why this class was not able to capture first Enqueue event when it was run in Xunit project, but it successfully captured all the events when it was run in a console application.

Here is source code of the whole sample : https://github.com/NazmiAltun/ThreadPoolSchedulingEventListener

[bradwilson]

I honestly don't know the answer to this question, but here is some information about the way xUnit.net works that might contribute to you finding an answer.

We have two synchronization contexts (that is, classes which derive from SynchronizationContext): AsyncTestSyncContext and MaxConcurrencySyncContext.

• AsyncTestSyncContext allows us to support tests that are written as async void and still track the proper lifetime of the test method.
• MaxConcurrencySyncContext allows us to create a limited set of worker threads to be used for scheduling Tasks that we have created, so as to limit the number of threads that are allowed to run in parallel at any given time.

In normal operation we use them both. It's possible that one or both of these are somehow interfering with what you're trying to do, although my understanding is that simply calling Task.Run should schedule your work on the default thread pool-based Task runner; you would only stay on our sync context through the use of async and await while running on our thread.

You can't turn off AsyncTestSyncContext, but you can turn off MaxConcurrencySyncContext by saying you want unlimited threads (simplest way is to set maxParallelThreads to -1). This is the first place I'd start, to see if that's the one that's causing the problem (and if one of them is, it certainly seems to be the most likely candidate in my mind).

[bradwilson]

Going to mark this as answered. Please let me know if you have any further questions.