I'm not sure when this issue started but I noticed this due to the performance of our ASP.NET web app (.NET 4.8) being severally degraded.
NOTE: This is not exclusive to ASP.NET apps as it also occurs in our Windows WPF application; its just that our ASP.NET app utilizes Autofac a lot more.
When I looked at the 'Debug Output' in VS2020 I found that each HTTP request would add over a thousand duplicate messages:
The parameters to the Event method do not match the parameters to the WriteEvent method. This may cause the event to be displayed incorrectly.
I initially thought that it was related to 'EventSource' but I added code based on How to disable Task Parallel Library's ETW EventSource in a Universal App? and found that all the event sources seemed to be disabled (unless this somehow does not matter?).
There does not appear to be an associated exception with this output so I'm at a loss of how I can determine the root cause of this issue and fix it.
This problem substantially changes the performance characteristics of the web app under the debugger.
Unfortunately when I try to capture performance data it does not appear to happen.
Update:
By stepping through the code at the points where many messages were generated I have isolated the issue to an Autofac assembly (v6.2).
EventSource.LogEventArgsMismatches() at EventSource.cs:line 1,036 EventSource.WriteEventVarargs() at EventSource.cs:line 935 EventSource.WriteEvent() DiagnosticSourceEventSource.Event() DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>b__2() DiagnosticSourceEventSource.CallbackObserver<KeyValuePair<string, object>>.OnNext() DiagnosticListener.Write() DiagnosticSourceExtensions.OperationStart() ResolveOperation.ExecuteOperation() ResolveOperation.Execute()
For any attempt to resolve an instance through Autofac it will attempt to log the call with the a 'DiagnosticListener' (see 'IContainer.DiagnosticSource') and if one is subscribed then it produces the message above.
This only occurs if a 'DiagnosticListener' is attached. Here is the stack trace for the call-stack that leads to the 'DiagnosticListener.Subscribe' call.
DiagnosticListener.SubscribeInternal() at DiagnosticListener.cs:line 179 DiagnosticListener.Subscribe() at DiagnosticListener.cs:line 49 HttpHandlerDiagnosticListener.Subscribe() DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_0.<.ctor>b__0() DiagnosticSourceEventSource.CallbackObserver.OnNext() at DiagnosticSourceEventSource.cs:line 618 DiagnosticListener.AllListenerObservable.Subscribe() new DiagnosticSourceEventSource.FilterAndTransform() at DiagnosticSourceEventSource.cs:line 316 DiagnosticSourceEventSource.FilterAndTransform.CreateFilterAndTransformList() at DiagnosticSourceEventSource.cs:line 216 DiagnosticSourceEventSource.OnEventCommand() at DiagnosticSourceEventSource.cs:line 155 EventSource.DoCommand() at EventSource.cs:line 1,462 EventSource.SendCommand() at EventSource.cs:line 1,383 EventSource.OverideEventProvider.OnControllerCommand() at EventSource.cs:line 2,950 EventProvider.EtwEnableCallBack() at EventProvider.cs:line 205
I would love to know what triggers the 'EtwEnableCallback'. Is there any configuration for it?
Update 2
From debugging other events this looks more like a bug in 'DiagnosticSourceEventSource' rather than 'Autofac' as the same message is logged for other callers. Here is the trace for 'HttpClientHandler' logging an event to 'DiagnosticSourceEventSource':
EventSource.WriteEventVarargs() at EventSource.cs:line 936 EventSource.WriteEvent() at EventSource.cs:line 696 DiagnosticSourceEventSource.Event() DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>b__2() DiagnosticSourceEventSource.CallbackObserver<KeyValuePair<string, object>>.OnNext() DiagnosticListener.Write() HttpHandlerDiagnosticListener.RaiseResponseEvent() HttpHandlerDiagnosticListener.HttpWebRequestArrayList.RemoveAt() Connection.ReadStartNextRequest() ConnectStream.CallDone() ConnectStream.EndReadWithoutValidation() ConnectStream.EndRead() HttpClientHandler.WebExceptionWrapperStream.EndRead() StreamToStreamCopy.BufferReadCallback() LazyAsyncResult.Complete() ContextAwareResult.CompleteCallback() ExecutionContext.RunInternal() ExecutionContext.Run() ExecutionContext.Run() ContextAwareResult.Complete() LazyAsyncResult.ProtectedInvokeCallback() BaseOverlappedAsyncResult.CompletionPortCallback() _IOCompletionCallback.PerformIOCompletionCallback() [Native to Managed Transition]
This suggests that every event that goes through 'DiagnosticSourceEventSource' may write the same message to the 'Debug console'.
The issue however is still related to Autofac as is the only package that depends on 'System.Diagnostics.DiagnosticSource' (as verified from looking at 'project.assets.json' file).
The only way I've found to disable the behavior of 'DiagnosticsSourceEventSource' is to use reflection to 'Dispose' the 'EventSource'. This however seems less than ideal as I cannot predict the side effects of this approach (idea taken from https://stackoverflow.com/a/53191383/146900):
var diagnosticsLib = Assembly.Load("System.Diagnostics.DiagnosticSource, Version=4.0.5.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51");
var diagnosticSourceEventSourceType = diagnosticsLib.GetType("System.Diagnostics.DiagnosticSourceEventSource");
object diagnosticSourceEventSource = diagnosticSourceEventSourceType.InvokeMember("Logger", BindingFlags.Static | BindingFlags.GetField | BindingFlags.Public, null, null, null);
if (diagnosticSourceEventSource is IDisposable disposable)
disposable.Dispose();
Update 3
Seems there are multiple issues in the dotnet github repo that look like they might be related to this problem:
- https://github.com/dotnet/runtime/issues/30239 - Event method parameter mismatch in DiagnosticSourceEventSource causes poor performance
- https://github.com/dotnet/runtime/issues/11268 - Type check in EventSource makes it impossible to log interfaces as arguments without a warning
This seems to have been addressed in https://github.com/dotnet/coreclr/pull/26056. Unfortunately the change was made in 'System.Diagnostics.Tracing.EventSource' which in .NET Framework is part of 'mscorlib.dll' which means I cannot update a nuget package to resolve the issue. The change appears to be destined for .NET 5 and I'm guessing that this was not ported to .NET Framework which leaves me stuck with the bug.
