Thousands and thousands of EventSourceException while processing event "TraceOperationBegin" thrown throughout a debugging session

[davkean]

Windows Build: 15063.rs2_release.170317-1834

While debugging, I'm seeing thousands upon thousands of:

EventSourceException while processing event "TraceOperationBegin"

The stack at the time is:

           mscorlib.dll!System.Diagnostics.Tracing.EventSource.ReportOutOfBandMessage(string msg, bool flush) Line 3931       C#
           mscorlib.dll!System.Diagnostics.Tracing.EventSource.ThrowEventSourceException(string eventName, System.Exception innerEx) Line 2452       C#
           mscorlib.dll!System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore(int eventId, System.Guid* relatedActivityId, int eventDataCount, System.Diagnostics.Tracing.EventSource.EventData* data) Line 1230       C#
           mscorlib.dll!System.Threading.Tasks.TplEtwProvider.TraceOperationBegin(int TaskID, string OperationName, long RelatedContext) Line 653    C#
           mscorlib.dll!System.Threading.Tasks.AsyncCausalityTracer.TraceOperationCreation(System.Threading.Tasks.CausalityTraceLevel traceLevel, int taskId, string operationName, ulong relatedContext) Line 191         C#
           mscorlib.dll!System.Threading.Tasks.StandardTaskContinuation.StandardTaskContinuation(System.Threading.Tasks.Task task, System.Threading.Tasks.TaskContinuationOptions options, System.Threading.Tasks.TaskScheduler scheduler) Line 313                C#
           mscorlib.dll!System.Threading.Tasks.Task.ContinueWithCore(System.Threading.Tasks.Task continuationTask, System.Threading.Tasks.TaskScheduler scheduler, System.Threading.CancellationToken cancellationToken, System.Threading.Tasks.TaskContinuationOptions options) Line 4644       C#

The code that is throwing is:

                                if (etwSessions.IsEqualOrSupersetOf(m_curLiveSessions))
                                {
                                    // OutputDebugString(string.Format("  (1) id {0}, kwd {1:x}", 
                                    //                   m_eventData[eventId].Name, m_eventData[eventId].Descriptor.Keywords));
                                    // by default the Descriptor.Keyword will have the perEventSourceSessionId bit 
                                    // mask set to 0x0f so, when all ETW sessions want the event we don't need to 
                                    // synthesize a new one
                                    if (!m_provider.WriteEvent(ref m_eventData[eventId].Descriptor, pActivityId, relatedActivityId, eventDataCount, (IntPtr)data))
                                        ThrowEventSourceException(m_eventData[eventId].Name);  <!--- Throwing

Almost every time I break there's 1 or more threads sitting on the ReportOutOfBandMessage frame.

Any idea what's going on?

[danmoseley]

This is from TPL but I don't know why it's doing this. @brianrob ?

[davkean]

I'm unsure if this is only the TPL path that's throwing or whether it's all tracing. It's just that we kick off thousands of Tasks in VS and everyone of them is throwing.

[vancem]

This bug was fixed by the following PR in coreCLR.

dotnet/coreclr#11941 Fix failures in ETW logging on 4GB aware 32 bit processes

Basically the problem was that Rosyn compiler both uses Tasks heavily (which causes many TPL events), and used more than 2GB of heap. Some of the TPL event log the address of the object, and if this address is over 2GB, it got SIGN EXTENDED rather than zero extended and causes the OS to fail to log the event. EventSource in turn logs an OutputDebugString.

This bug has been fixed on CoreCLR, and the following bug tracks fixing it for the Desktop (it has not yet been ported however).

443469 Fix failures in ETW logging on 4GB aware 32 bit processes

However it turns out that the particular TPL events being logged are not event necessary, so rather than having to wait for a fixed .NET Runtime on Desktop, the VS debugger can be changed to only ask for the events it needs (which should eliminate the spew.

The following VS bug tracks that.

442073 Don't enable all TPL events in the debugger Cagri (Charlie) Aslan

I believe this issue can be closed as the work is now being tracked by the other two bugs.

Vance

[davkean]

Thanks @vancem