azure-signalr
azure-signalr copied to clipboard
Published
20 hours ago •
Azure
Azure
Azure SignalR ASP.NET (Full Framework) running on Azure App Service Pv3 results in excessive application logs
There is an issue when using a combination of the following:
- Running a full framework ASP.NET application on a Windows App Service hosting plan
- Running on App Service Plan of tier Premium v3
- Configuring Azure App Service with an Azure Monitor diagnostic setting logging the App Service Application Logs (AppServiceAppLogs) category. This is required since ASP.NET Windows applications (running on IIS) have no console output.
- Using Azure SignalR for ASP.NET library (Microsoft.Azure.SignalR.AspNet)
- Resolving a version of the Microsoft.Extensions.Logging.EventSource library v6 or greater (issue does not manifest with v2 specified by Microsoft.Azure.SignalR.AspNet as the minimum dependency, have not investigated why the issue only manifests with newer EventSource library versions)
The issue results from:
- Azure SignalR for ASP.NET startup creating a
ILoggerFactorythat configures an internal EventSource logger (AddEventSourceLogger) - The event source logger implementation emitting ETW events on the Windows for all SignalR events (also debug and trace events)
- The App Service Premium v3 plan with
AppServiceAppLogscategory logging enabled consuming all platform ETW events and shipping them to Azure Monitor
The end result is a system that logs several million debug logs per day to Azure Monitor.
The way I see it the actual bug is a combination of bugs in both Azure SignalR for ASP.NET library and Azure App Service Windows hosting infrastructure:
-
Microsoft.Azure.SignalR.AspNetshould not be creating its own internal logger factory with an event source logger over which the application has no control. Applications always create their own logging configuration and specify the desired targets. I understand the compatibility reason why it is done like this when integrating from full framework withMicrosoft.Extensions.Logging, but it should be opt-in with some sort of flag, and the normal usage should result in the use ofNullLogger. - App Service should not be emitting event source events to Azure Monitor from sources other than the officially declared AzureMonitorTraceListener (System.Diagnostics.Trace.Trace*). It should also be adhering to the APPSERVICEAPPLOGS_TRACE_LEVEL configuration (handled in
Microsoft.WindowsAzure.WebSites.Diagnostics.AzureMonitorTraceListener) as well as the 100 logs/minute threshold implemented by the internalMicrosoft.WindowsAzure.WebSites.Diagnostics.AzureMonitorTraceThrottler.
For now my workaround is to configure SignalR with a HubConfiguration and custom IDependencyResolver wrapping HubConfiguration.Resolver and for IDependencyResolver.GetService(Type serviceType) when serviceType = ILoggerFactory returning NullLoggerFactory.Instance.
I am facing the similar issue when running on Azure App Service Pv3 with Full Framework. Around 5000 event logs in one minute trace taken from the Azure App Service via Diagnostic Tools. Would love to have workaround other than dependency resolver.
Thanks @vicancy for thumbs up and looking into it. Wanted to add additional context. As you might already know this, these events are also source of major allocations. Allocations from a recent trace of slowdown - related to ETW events. I wonder how many and what sources it adds by default?
After spending weeks chasing the cause of slowdowns and high memory. I think ETW Trace writes are part of the bigger problem. as I am getting help from runtime team to track down in the linked issue. Excuse me if the tagging other issue is unrelated.
Using Dependency Resolver: Its .NET Framework 4.8 application, and we are using the Unity as DI container. I am reluctant to use Unity for the SignalR as it is another source of allocations and I suspect the level of support of some async scenarios.
That's why requesting for other workaround to avoid the trace writes without DR.
If I set the GlobalHost.TraceManager.Switch.Level = SourceLevels.Error; will that decrease the number Trace writes?
Additional Context - Allocations and Diagnostic Settings
Then when Drilling down for string allocations.
For byte[] drill down
Finally, here is how AzureSignalR Diagnostic Settings are configured. I try to find the events logged in the portal but was not able to. I guess these logs are lost but I see it in the PerfView as noted above.
Automated analysis suggestion - I tried removing the default trace listener but it did not have any impact.
An example SignalR Thread - It also have a call to clr!GCInterface::SuppressFinalize Not sure if it related to SignalR or part of the bigger problem in linked thread. But we do have exception happening time to time in the finalizer thread - https://github.com/Azure/azure-signalr/issues/1928
Thread Blocked/taking longer Probably due to ETW Trace Writes
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
|+ Thread (21464) CPU=176ms (.NET IO ThreadPool Worker) 27.3 7,191,035 29,227 0.0 0 0 0 0 79A***************************** 886.454 137,896.927
||+ module ntdll <<ntdll!_RtlUserThreadStart>> 27.3 7,183,970 28,951 0.0 0 0 0 0 _1A***************************** 7,947.213 137,896.927
|||+ module kernel32 <<kernel32!BaseThreadInitThunk>> 27.3 7,183,970 28,951 0.0 0 0 0 0 _1A***************************** 7,947.213 137,896.927
||| + module clr <<clr!Thread::intermediateThreadProc>> 27.3 7,183,970 28,951 0.0 0 0 0 0 _1A***************************** 7,947.213 137,896.927
||| + module mscorlib.ni <<mscorlib.ni!_IOCompletionCallback.PerformIOCompletionCallback>> 26.9 7,077,329 27,786 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |+ module System <<System!BaseOverlappedAsyncResult.CompletionPortCallback>> 26.9 7,077,328 27,763 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| ||+ module mscorlib.ni <<mscorlib.ni!ExecutionContext.Run>> 26.9 7,077,328 27,762 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||+ module System <<System!ContextAwareResult.CompleteCallback>> 26.9 7,077,327 27,761 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| ||||+ module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.TaskFactory`1+FromAsyncTrimPromise`1[System.Int32,System.__Canon].CompleteFromAsyncResult(System.IAsyncResult)>> 26.9 7,077,281 27,732 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||||+ module System <<System!System.Net.WebSockets.WebSocketConnectionStream+<ReadAsync>d__21.MoveNext()>> 25.9 6,819,864 27,495 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| ||||||+ module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.Task`1[System.Int32].TrySetResult(Int32)>> 25.9 6,819,864 27,495 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||||| + module System <<System!System.Net.WebSockets.WebSocketBase+WebSocketOperation+<Process>d__19.MoveNext()>> 25.9 6,819,864 27,495 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||||| + module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.Task`1[System.__Canon].TrySetResult(System.__Canon)>> 25.9 6,819,864 27,495 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||||| + module System <<System!System.Net.WebSockets.WebSocketBase+<ReceiveAsyncCore>d__45.MoveNext()>> 25.9 6,819,864 27,495 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||||| + module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.Task`1[System.__Canon].TrySetResult(System.__Canon)>> 25.9 6,819,864 27,495 0.0 0 0 0 0 __0***************************** 9,770.215 137,896.927
||| |||||| + module microsoft.azure.signalr.common <<microsoft.azure.signalr.common!Microsoft.Azure.SignalR.Connections.Client.Internal.WebSocketsTransport+<StartReceiving>d__20.MoveNext()>> 19.7 5,187,891.500 20,408 0.0 0 0 0 0 __0***************************** 9,770.215 136,788.051
||| |||||| |+ module mscorlib.ni <<mscorlib.ni!System.Runtime.CompilerServices.TaskAwaiter`1[System.__Canon].UnsafeOnCompleted(System.Action)>> 19.6 5,163,575 20,171 0.0 0 0 0 0 __.R**************************** 12,889.827 136,788.051
||| |||||| ||+ module microsoft.azure.signalr.common <<microsoft.azure.signalr.common!Microsoft.Azure.SignalR.Connections.Client.Internal.WebSocketsTransport+<StartReceiving>d__20.MoveNext()>> 19.3 5,081,434.500 19,708 0.0 0 0 0 0 ___7**************************** 14,211.613 136,788.051
||| |||||| |||+ module mscorlib.ni <<mscorlib.ni!System.Runtime.CompilerServices.TaskAwaiter`1[System.__Canon].UnsafeOnCompleted(System.Action)>> 18.5 4,872,051 19,427 0.0 0 0 0 0 ___5**************************** 14,211.640 136,788.051
||| |||||| ||||+ module microsoft.azure.signalr.common <<microsoft.azure.signalr.common!Microsoft.Azure.SignalR.Connections.Client.Internal.WebSocketsTransport+<StartReceiving>d__20.MoveNext()>> 18.5 4,866,545.500 8,759 0.0 0 0 0 0 ___5**************************** 14,776.870 136,781.427
||| |||||| |||||+ module System <<System!ClientWebSocket.ReceiveAsync>> 18.5 4,861,221 6,969 0.0 0 0 0 0 ___5**************************** 14,776.870 136,781.401
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1+ConfiguredTaskAwaiter[System.Int32].UnsafeOnCompleted(System.Action)>> 18.5 4,861,200 4,911 0.0 0 0 0 0 ___5**************************** 14,776.870 136,781.393
||| |||||| |||||||+ AWAIT_TIME 18.5 4,861,158 951 18.5 4,861,158 951 0 0 ___5**************************** 14,778.121 136,781.136
||| |||||| |||||||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 38.466 2,002 0.0 0 0 0 0 ___................_.o._..._.... 14,776.870 136,781.393
||| |||||| ||||||||+ module wow64 <<wow64!Wow64LdrpInitialize>> 0.0 38.445 2,001 0.0 0 0 0 0 ___................_.o._..._.... 14,776.870 136,781.393
||| |||||| |||||||||+ module wow64cpu <<wow64cpu!BTCpuSimulate>> 0.0 38.445 2,001 0.0 0 0 0 0 ___................_.o._..._.... 14,776.870 136,781.393
||| |||||| ||||||||| + module wow64 <<wow64!Wow64SystemServiceEx>> 0.0 38.445 2,001 0.0 0 0 0 0 ___................_.o._..._.... 14,776.870 136,781.393
||| |||||| ||||||||| + module ntdll <<ntdll!NtTraceEvent>> 0.0 38.445 2,001 0.0 0 0 0 0 ___................_.o._..._.... 14,776.870 136,781.393
||| |||||| ||||||||| + CPU_TIME 0.0 20.833 1,986 0.0 20.833 1,986 0 0 ___................_..._..._.... 14,776.870 136,781.393
||| |||||| ||||||||| + module ntoskrnl <<ntoskrnl!KiSystemServiceUser>> 0.0 17.612 15 0.0 0 0 0 0 ________..____..__.__o__.._____. 34,900.735 134,279.349
||| |||||| ||||||||| + module handlerc.sys <<handlerc!?>> 0.0 17.588 14 0.0 0 0 0 0 ________..____.._____o__.._____. 34,900.735 134,279.349
||| |||||| ||||||||| |+ module ntoskrnl <<ntoskrnl!KeAcquireGuardedMutex>> 0.0 17.442 4 0.0 0 0 0 0 _____________________o__________ 91,773.324 91,790.766
||| |||||| ||||||||| ||+ BLOCKED_TIME 0.0 17.378 2 0.0 17.378 2 0 0 _____________________o__________ 91,773.324 91,790.716
||| |||||| ||||||||| ||+ CPU_TIME 0.0 0.064 2 0.0 0.064 2 0 0 _____________________.__________ 91,773.461 91,790.766
||| |||||| ||||||||| |+ module ntoskrnl <<ntoskrnl!NtTraceEvent>> 0.0 0.087 8 0.0 0 0 0 0 ________..____..________.._____. 34,900.735 134,279.349
||| |||||| ||||||||| ||+ CPU_TIME 0.0 0.087 8 0.0 0.087 8 0 0 ________..____..________.._____. 34,900.735 134,279.349
||| |||||| ||||||||| |+ module ntoskrnl <<ntoskrnl!ExFreePool>> 0.0 0.034 1 0.0 0 0 0 0 _________________________.______ 109,892.342 109,892.376
||| |||||| ||||||||| ||+ CPU_TIME 0.0 0.034 1 0.0 0.034 1 0 0 _________________________.______ 109,892.342 109,892.376
||| |||||| ||||||||| |+ module ntoskrnl <<ntoskrnl!RtlCompareMemory>> 0.0 0.026 1 0.0 0 0 0 0 _________________________.______ 109,774.358 109,774.383
||| |||||| ||||||||| | + CPU_TIME 0.0 0.026 1 0.0 0.026 1 0 0 _________________________.______ 109,774.358 109,774.383
||| |||||| ||||||||| + CPU_TIME 0.0 0.024 1 0.0 0.024 1 0 0 __________________._____________ 81,890.343 81,890.366
||| |||||| ||||||||+ CPU_TIME 0.0 0.021 1 0.0 0.021 1 0 0 ____________.___________________ 53,771.351 53,771.372
||| |||||| |||||||+ CPU_TIME 0.0 21.981 1,923 0.0 21.981 1,923 0 0 ____..............._..._..._.... 20,769.785 136,781.162
||| |||||| |||||||+ module System <<System!System.Net.WebSockets.WebSocketConnectionStream+<ReadAsync>d__21.MoveNext()>> 0.0 21.682 9 0.0 0 0 0 0 _______..________._______o______ 34,192.662 109,915.107
||| |||||| |||||||+ module System <<System!System.Net.WebSockets.WebSocketBase+WebSocketOperation+<Process>d__19.MoveNext()>> 0.0 0.356 18 0.0 0 0 0 0 ______.___.____.._._..__..._..__ 29,898.228 125,769.365
||| |||||| |||||||+ module ntoskrnl <<ntoskrnl!KiDpcInterrupt>> 0.0 0.037 2 0.0 0 0 0 0 ______________._________________ 64,224.127 64,224.164
||| |||||| |||||||+ module clr <<clr!JIT_New>> 0.0 0.036 2 0.0 0 0 0 0 _________._____________________. 40,892.115 136,772.334
||| |||||| |||||||+ module clr <<clr!JIT_ChkCastInterface>> 0.0 0.026 1 0.0 0 0 0 0 _____________.__________________ 58,768.352 58,768.378
||| |||||| |||||||+ module System <<System!ContextAwareResult.CompleteCallback>> 0.0 0.026 1 0.0 0 0 0 0 _______________.________________ 64,890.342 64,890.368
||| |||||| |||||||+ module clr <<clr!AppDomainNative::GetId>> 0.0 0.018 1 0.0 0 0 0 0 ________________________._______ 103,914.352 103,914.369
||| |||||| |||||||+ module <<?!?>> 0.0 0.011 1 0.0 0 0 0 0 _____________________.__________ 91,772.352 91,772.363
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1+ConfiguredTaskAwaiter[System.__Canon].UnsafeOnCompleted(System.Action)>> 0.0 33.011 1,977 0.0 0 0 0 0 ___................_..._o.._.... 14,776.891 136,781.401
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!Stream.ReadAsync>> 0.0 1.298 27 0.0 0 0 0 0 ______...___..__..__..___..___.. 26,776.927 136,781.375
||| |||||| ||||||+ module clr <<clr!JIT_New>> 0.0 0.232 16 0.0 0 0 0 0 ____.___._.__._._.._..___.__..__ 20,775.302 125,897.021
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!RuntimeType.get_Cache>> 0.0 0.184 2 0.0 0 0 0 0 ____________________.___________ 86,778.109 86,778.293
||| |||||| ||||||+ module websocket <<websocket!WebSocketReceive>> 0.0 0.168 2 0.0 0 0 0 0 _______________.________._______ 64,888.337 103,894.411
||| |||||| ||||||+ module ntoskrnl <<ntoskrnl!KiDpcInterrupt>> 0.0 0.123 4 0.0 0 0 0 0 _____________.____._____________ 58,893.109 80,777.876
||| |||||| ||||||+ CPU_TIME 0.0 0.121 4 0.0 0.121 4 0 0 ___________._.___.______________ 48,768.353 76,891.394
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!CancellationToken.Register>> 0.0 0.078 2 0.0 0 0 0 0 _______.________________._______ 31,771.658 104,255.991
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!ExecutionContext.FastCapture>> 0.0 0.078 5 0.0 0 0 0 0 _________..______.___.__________ 42,767.868 92,897.932
||| |||||| ||||||+ module clr <<clr!HelperMethodFrameRestoreState>> 0.0 0.064 3 0.0 0 0 0 0 ____.___________________________ 20,775.316 20,775.380
||| |||||| ||||||+ module clr <<clr!JIT_MonReliableEnter>> 0.0 0.060 1 0.0 0 0 0 0 ________________________._______ 103,775.351 103,775.412
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!String.Concat>> 0.0 0.054 3 0.0 0 0 0 0 __________________.______.___.__ 81,905.100 125,893.779
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!RuntimeType.get_Name>> 0.0 0.044 2 0.0 0 0 0 0 ________________._____._________ 70,888.352 97,896.357
||| |||||| ||||||+ module clr <<clr!JIT_NewArr1>> 0.0 0.043 1 0.0 0 0 0 0 ______________________._________ 97,896.903 97,896.946
||| |||||| |||||||+ CPU_TIME 0.0 0.043 1 0.0 0.043 1 0 0 ______________________._________ 97,896.903 97,896.946
||| |||||| ||||||+ module websocket <<websocket!WebSocketGetAction>> 0.0 0.042 1 0.0 0 0 0 0 ____________.___________________ 53,775.350 53,775.393
||| |||||| ||||||+ module <<?!?>> 0.0 0.040 2 0.0 0 0 0 0 ____________________._._________ 86,777.351 97,895.358
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!Task.get_Id>> 0.0 0.038 2 0.0 0 0 0 0 _______________._________.______ 64,774.352 109,893.356
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!TplEtwProvider.TraceOperationBegin>> 0.0 0.020 1 0.0 0 0 0 0 _____________________.__________ 92,895.337 92,895.357
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!TaskAwaiter.OnCompletedInternal>> 0.0 0.019 1 0.0 0 0 0 0 ________________._______________ 70,891.352 70,891.370
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!ExecutionContextSwitcher.Undo>> 0.0 0.017 1 0.0 0 0 0 0 _______________.________________ 64,775.351 64,775.367
||| |||||| ||||||+ module mscorlib.ni <<mscorlib.ni!AsyncCausalityTracer.TraceOperationCreation>> 0.0 0.017 1 0.0 0 0 0 0 ______._________________________ 29,899.228 29,899.245
||| |||||| |||||+ module mscorlib.ni <<mscorlib.ni!System.Runtime.CompilerServices.TaskAwaiter`1[System.__Canon].UnsafeOnCompleted(System.Action)>> 0.0 5,162.926 1,200 0.0 0 0 0 0 ___.......o........_82._o.._.... 14,776.898 136,781.427
||| |||||| |||||+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass14_0`3[System.Net.WebSockets.WebSocketMessageType,System.Int32,System.Boolean].<Define>b__1(class Microsoft.Extensions.Logging.ILogger,!0,!1,!2,class System.Exception)>> 0.0 209.238 584 0.0 0 0 0 0 ___.oo........oo.oo_o.._o.o_o... 14,777.559 136,774.471
||| |||||| |||||+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.Logger`1[System.__Canon].Microsoft.Extensions.Logging.ILogger.IsEnabled(value class Microsoft.Extensions.Logging.LogLevel)>> 0.0 0.318 1 0.0 0 0 0 0 ____________________.___________ 86,767.336 86,767.655
||| |||||| |||||+ module <<?!?>> 0.0 0.213 2 0.0 0 0 0 0 _______________________________. 136,770.470 136,770.683
||| |||||| |||||+ module system.memory <<system.memory!MemoryMarshal.TryGetArray>> 0.0 0.063 1 0.0 0 0 0 0 _____________________________.__ 125,893.338 125,893.401
||| |||||| |||||+ module mscorlib.ni <<mscorlib.ni!ExecutionContext.FastCapture>> 0.0 0.027 2 0.0 0 0 0 0 _____________.__________._______ 58,893.534 104,255.366
||| |||||| ||||+ module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.FlushAsync(value class System.Threading.CancellationToken)>> 0.0 5,505.979 9,594 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| |||||+ module mscorlib.ni <<mscorlib.ni!ThreadPool.QueueUserWorkItem>> 0.0 5,505.914 9,593 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| ||||||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 5,505.747 9,590 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| |||||||+ module wow64 <<wow64!Wow64LdrpInitialize>> 0.0 5,505.747 9,590 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| ||||||| + module wow64cpu <<wow64cpu!BTCpuSimulate>> 0.0 5,505.747 9,590 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| ||||||| + module wow64 <<wow64!Wow64SystemServiceEx>> 0.0 5,505.747 9,590 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| ||||||| + module ntdll <<ntdll!NtTraceEvent>> 0.0 5,505.747 9,590 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| ||||||| + module microsoft.azure.signalr.common <<microsoft.azure.signalr.common!Microsoft.Azure.SignalR.ServiceConnectionBase+<ProcessIncomingAsync>d__69.MoveNext()>> 0.0 5,464.487 9,549 0.0 0 0 0 0 ___0oo0o200000o1000_10o_0o0_000o 14,927.015 136,788.051
||| |||||| ||||||| |+ module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.WriteAsync(value class System.ReadOnlyMemory`1,value class System.Threading.CancellationToken)>> 0.0 2,755.876 7,820 0.0 0 0 0 0 ___oooo.100000.000o_00o_0o0_o00o 14,929.771 136,788.051
||| |||||| ||||||| ||+ module mscorlib.ni <<mscorlib.ni!ThreadPool.QueueUserWorkItem>> 0.0 2,754.544 7,815 0.0 0 0 0 0 ___oooo.100000.000o_00o_0o0_o00o 14,929.771 136,788.051
||| |||||| ||||||| |||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 2,751.743 7,808 0.0 0 0 0 0 ___oooo.100000.000o_00o_0o0_o00o 14,929.771 136,788.051
||| |||||| ||||||| |||+ CPU_TIME 0.0 2.016 3 0.0 2.016 3 0 0 _________________.______..______ 75,784.335 109,782.295
||| |||||| ||||||| |||+ module <<?!?>> 0.0 0.425 2 0.0 0 0 0 0 __________._____._______________ 46,898.351 69,786.687
||| |||||| ||||||| |||+ module clr <<clr!JIT_WriteBarrierEAX>> 0.0 0.290 1 0.0 0 0 0 0 __________________________._____ 114,905.337 114,905.627
||| |||||| ||||||| |||+ module clr <<clr!JIT_New>> 0.0 0.069 1 0.0 0 0 0 0 ___.____________________________ 14,929.999 14,930.068
||| |||||| ||||||| ||+ module system.buffers <<system.buffers!System.Buffers.DefaultArrayPool`1[System.Byte].Rent(int32)>> 0.0 1.008 1 0.0 0 0 0 0 __________._____________________ 46,918.336 46,919.344
||| |||||| ||||||| ||+ CPU_TIME 0.0 0.250 3 0.0 0.250 3 0 0 ________________._.___________._ 70,905.350 131,780.430
||| |||||| ||||||| ||+ module <<?!?>> 0.0 0.074 1 0.0 0 0 0 0 _______________.________________ 64,780.351 64,780.425
||| |||||| ||||||| |+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass8_0.<Define>b__1(class Microsoft.Extensions.Logging.ILogger,class System.Exception)>> 0.0 1,578.507 675 0.0 0 0 0 0 ___o.o._00o0o0.000o_0o__o.0_o00. 14,929.527 136,787.809
||| |||||| ||||||| |+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass12_0`2[System.Int64,System.__Canon].<Define>b__1(class Microsoft.Extensions.Logging.ILogger,!0,!1,class System.Exception)>> 0.0 1,103.776 947 0.0 0 0 0 0 ___o.o.o00ooo0.0000_00o_o.o_o0o. 14,927.015 136,786.194
||| |||||| ||||||| |+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass14_0`3[System.Boolean,System.__Canon,System.__Canon].<Define>b__1(class Microsoft.Extensions.Logging.ILogger,!0,!1,!2,class System.Exception)>> 0.0 15.088 62 0.0 0 0 0 0 _______.__._._.__.___.__._._o__. 34,194.824 134,291.909
||| |||||| ||||||| |+ module <<?!?>> 0.0 2.330 7 0.0 0 0 0 0 ______.__________.__._______..__ 29,901.831 125,902.156
||| |||||| ||||||| |+ module System <<System!Stopwatch.GetTimestamp>> 0.0 1.482 2 0.0 0 0 0 0 __________._________________.___ 46,917.336 120,897.051
||| |||||| ||||||| |+ CPU_TIME 0.0 1.471 4 0.0 1.471 4 0 0 _____.___.._________.___________ 23,911.627 87,894.741
||| |||||| ||||||| |+ module mscorlib.ni <<mscorlib.ni!SemaphoreSlim.Release>> 0.0 1.138 3 0.0 0 0 0 0 ______________________.________. 97,781.351 136,779.588
||| |||||| ||||||| |+ module clr <<clr!JIT_New>> 0.0 1.014 2 0.0 0 0 0 0 ________________________.____.__ 104,257.521 125,776.342
||| |||||| ||||||| |+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass8_0.<Define>g__Log|0(class Microsoft.Extensions.Logging.ILogger,class System.Exception)>> 0.0 0.921 1 0.0 0 0 0 0 ________._______________________ 36,796.918 36,797.840
||| |||||| ||||||| |+ module clr <<clr!JIT_MonReliableEnter>> 0.0 0.689 4 0.0 0 0 0 0 ____________._________________._ 53,778.980 131,902.557
||| |||||| ||||||| ||+ CPU_TIME 0.0 0.546 2 0.0 0.546 2 0 0 ____________._________________._ 53,781.352 131,902.557
||| |||||| ||||||| ||+ module ntoskrnl <<ntoskrnl!KiDpcInterrupt>> 0.0 0.143 2 0.0 0 0 0 0 ____________.___________________ 53,778.980 53,779.123
||| |||||| ||||||| || + CPU_TIME 0.0 0.078 1 0.0 0.078 1 0 0 ____________.___________________ 53,779.045 53,779.123
||| |||||| ||||||| || + BLOCKED_TIME 0.0 0.065 1 0.0 0.065 1 0 0 ____________.___________________ 53,778.980 53,779.045
||| |||||| ||||||| |+ module mscorlib.ni <<mscorlib.ni!SemaphoreSlim.Wait>> 0.0 0.562 1 0.0 0 0 0 0 _____.__________________________ 23,896.628 23,897.190
||| |||||| ||||||| ||+ CPU_TIME 0.0 0.562 1 0.0 0.562 1 0 0 _____.__________________________ 23,896.628 23,897.190
||| |||||| ||||||| |+ module mscorlib.ni <<mscorlib.ni![COLD] System.DateTime.get_UtcNow()>> 0.0 0.550 3 0.0 0 0 0 0 __________._____________________ 44,206.344 44,206.894
||| |||||| ||||||| ||+ module ntoskrnl <<ntoskrnl!KiInterruptDispatchNoLockNoEtw>> 0.0 0.490 2 0.0 0 0 0 0 __________._____________________ 44,206.404 44,206.894
||| |||||| ||||||| |||+ BLOCKED_TIME 0.0 0.389 1 0.0 0.389 1 0 0 __________._____________________ 44,206.404 44,206.792
||| |||||| ||||||| |||+ CPU_TIME 0.0 0.102 1 0.0 0.102 1 0 0 __________._____________________ 44,206.792 44,206.894
||| |||||| ||||||| ||+ CPU_TIME 0.0 0.060 1 0.0 0.060 1 0 0 __________._____________________ 44,206.344 44,206.404
||| |||||| ||||||| |+ module microsoft.azure.signalr.protocols <<microsoft.azure.signalr.protocols!ServiceProtocol.TryParseMessage>> 0.0 0.444 7 0.0 0 0 0 0 _________________.__.___________ 74,237.774 86,798.301
||| |||||| ||||||| |+ module mscorlib.ni <<mscorlib.ni!ExecutionContext.FastCapture>> 0.0 0.229 4 0.0 0 0 0 0 ________________________.______. 103,786.795 134,285.333
||| |||||| ||||||| |+ module mscorlib.ni <<mscorlib.ni!ExecutionContextSwitcher.Undo>> 0.0 0.221 4 0.0 0 0 0 0 _________________.________._____ 75,794.935 115,791.332
||| |||||| ||||||| |+ module ntoskrnl <<ntoskrnl!KiDpcInterrupt>> 0.0 0.125 2 0.0 0 0 0 0 ______________________________._ 131,901.179 131,901.304
||| |||||| ||||||| |+ module mscorlib.ni <<mscorlib.ni!Number.TryParseInt32>> 0.0 0.070 1 0.0 0 0 0 0 ____________________________.___ 124,270.336 124,270.406
||| |||||| ||||||| + module ntoskrnl <<ntoskrnl!KiSystemServiceUser>> 0.0 39.393 24 0.0 0 0 0 0 _______oo_._____._____._._._..__ 31,776.423 125,895.408
||| |||||| ||||||| + module <<?!?>> 0.0 1.033 8 0.0 0 0 0 0 ________________.._____________. 70,899.336 134,283.727
||| |||||| ||||||| + module clr <<clr!JIT_IsInstanceOfClass>> 0.0 0.309 1 0.0 0 0 0 0 ____________________________.___ 120,898.335 120,898.644
||| |||||| ||||||| + module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.ThreadPoolScheduler+<>c.<Schedule>b__0_0(class System.Object)>> 0.0 0.217 3 0.0 0 0 0 0 ____________________.____.______ 86,793.859 109,901.447
||| |||||| ||||||| + module microsoft.azure.signalr.protocols <<microsoft.azure.signalr.protocols!ServiceProtocol.TryParseMessage>> 0.0 0.090 1 0.0 0 0 0 0 _____________________.__________ 91,780.351 91,780.442
||| |||||| ||||||| + module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeReader.ReadAsync(value class System.Threading.CancellationToken)>> 0.0 0.077 2 0.0 0 0 0 0 _________.______________________ 42,793.709 42,793.786
||| |||||| ||||||| + module mscorlib.ni <<mscorlib.ni!ExecutionContext.SetExecutionContext>> 0.0 0.073 1 0.0 0 0 0 0 _______________.________________ 64,777.352 64,777.424
||| |||||| ||||||| + module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeReader.GetResult(int16)>> 0.0 0.067 1 0.0 0 0 0 0 _____________________________.__ 125,781.350 125,781.417
||| |||||| ||||||+ CPU_TIME 0.0 0.068 1 0.0 0.068 1 0 0 ____________.___________________ 53,768.352 53,768.420
||| |||||| ||||||+ module clr <<clr!JIT_Ldelema_Ref>> 0.0 0.054 1 0.0 0 0 0 0 ________._______________________ 34,896.729 34,896.783
||| |||||| ||||||+ module clr <<clr!JIT_New>> 0.0 0.045 1 0.0 0 0 0 0 ____________.___________________ 53,774.927 53,774.971
||| |||||| |||||+ CPU_TIME 0.0 0.065 1 0.0 0.065 1 0 0 __________________________._____ 114,891.351 114,891.416
||| |||||| ||||+ CPU_TIME 0.0 150.020 988 0.0 150.020 988 0 0 ___...o.ooo.oo.oooo_ooo_ooo_ooo. 14,776.661 136,781.334
||| |||||| ||||+ module System <<System!ContextAwareResult.CompleteCallback>> 0.0 3.013 36 0.0 0 0 0 0 ______._.__..__...._._._..._.... 26,773.915 136,771.400
||| |||||| ||||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 2.005 38 0.0 0 0 0 0 ___..___________________________ 14,211.640 20,774.085
||| |||||| ||||+ module System <<System!System.Net.WebSockets.WebSocketBase+<ReceiveAsyncCore>d__45.MoveNext()>> 0.0 0.764 6 0.0 0 0 0 0 ___________._._..___.___________ 48,770.351 86,778.400
||| |||||| ||||+ module System <<System!System.Net.WebSockets.WebSocketBase+WebSocketOperation+<Process>d__19.MoveNext()>> 0.0 0.450 3 0.0 0 0 0 0 _________.________._____________ 42,771.360 80,780.814
||| |||||| ||||+ module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.Advance(int32)>> 0.0 0.147 1 0.0 0 0 0 0 ________._______________________ 34,893.727 34,893.874
||| |||||| ||||+ module clr <<clr!JIT_New>> 0.0 0.060 1 0.0 0 0 0 0 ____.___________________________ 17,893.969 17,894.029
||| |||||| ||||+ module System <<System!System.Net.WebSockets.WebSocketConnectionStream+<ReadAsync>d__21.MoveNext()>> 0.0 0.048 1 0.0 0 0 0 0 __________._____________________ 46,915.356 46,915.405
||| |||||| |||+ module System <<System!ClientWebSocket.ReceiveAsync>> 0.8 209,403.406 266 0.0 0 0 0 0 ___7**P_________________________ 14,211.613 26,777.645
||| |||||| |||+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass14_0`3[System.Net.WebSockets.WebSocketMessageType,System.Int32,System.Boolean].<Define>b__1(class Microsoft.Extensions.Logging.ILogger,!0,!1,!2,class System.Exception)>> 0.0 1.554 15 0.0 0 0 0 0 ____.___________________________ 17,892.773 20,773.435
||| |||||| ||+ module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.FlushAsync(value class System.Threading.CancellationToken)>> 0.3 82,140.727 389 0.0 0 0 0 0 ___6A9AA9999999AA9AAA94_________ 14,218.184 96,745.038
||| |||||| ||+ CPU_TIME 0.0 5.587 36 0.0 5.587 36 0 0 ___.o___________________________ 14,211.462 20,774.014
||| |||||| ||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 5.524 36 0.0 0 0 0 0 __..____________________________ 12,889.827 14,774.203
||| |||||| ||+ module System <<System!System.Net.WebSockets.WebSocketConnectionStream+<ReadAsync>d__21.MoveNext()>> 0.0 0.111 1 0.0 0 0 0 0 ____.___________________________ 20,768.337 20,768.449
||| |||||| ||+ module System <<System!ContextAwareResult.CompleteCallback>> 0.0 0.012 1 0.0 0 0 0 0 ____.___________________________ 17,894.029 17,894.040
||| |||||| |+ module System <<System!ClientWebSocket.ReceiveAsync>> 0.1 24,316.576 228 0.0 0 0 0 0 __0UP___________________________ 9,770.215 20,773.831
||| |||||| |+ module microsoft.extensions.logging.abstractions <<microsoft.extensions.logging.abstractions!Microsoft.Extensions.Logging.LoggerMessage+<>c__DisplayClass14_0`3[System.Net.WebSockets.WebSocketMessageType,System.Int32,System.Boolean].<Define>b__1(class Microsoft.Extensions.Logging.ILogger,!0,!1,!2,class System.Exception)>> 0.0 2.768 9 0.0 0 0 0 0 __..____________________________ 9,771.224 14,773.844
||| |||||| + module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.FlushAsync(value class System.Threading.CancellationToken)>> 6.2 1,632,144.500 7,087 0.0 0 0 0 0 __oD**************************** 9,798.647 137,896.927
||| |||||+ module pipelines.sockets.unofficial <<pipelines.sockets.unofficial!Pipelines.Sockets.Unofficial.StreamConnection+AsyncStreamPipe+<CopyFromStreamToReadPipe>d__13.MoveNext()>> 1.0 257,428.188 228 0.0 0 0 0 0 ___4NUUUTTTTTTTUUTUUM9999999993_ 15,390.783 130,883.042
||| ||||||+ module mscorlib.ni <<mscorlib.ni!System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1+ConfiguredTaskAwaiter[System.Int32].UnsafeOnCompleted(System.Action)>> 1.0 257,428.188 228 0.0 0 0 0 0 ___4NUUUTTTTTTTUUTUUM9999999993_ 15,390.783 130,883.042
||| |||||| + module pipelines.sockets.unofficial <<pipelines.sockets.unofficial!Pipelines.Sockets.Unofficial.StreamConnection+AsyncStreamPipe+<CopyFromStreamToReadPipe>d__13.MoveNext()>> 1.0 255,572.906 213 0.0 0 0 0 0 ___4MUUUTTTTTTTUUTUUM9999999993_ 15,390.931 130,883.042
||| |||||| + AWAIT_TIME 0.0 1,854.610 2 0.0 1,854.610 2 0 0 ___31___________________________ 15,390.793 17,718.566
||| |||||| + module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.FlushAsync(value class System.Threading.CancellationToken)>> 0.0 0.315 4 0.0 0 0 0 0 ____.___________________________ 20,045.114 20,045.430
||| |||||| + module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 0.163 4 0.0 0 0 0 0 ___.____________________________ 15,390.783 15,864.069
||| |||||| + CPU_TIME 0.0 0.120 3 0.0 0.120 3 0 0 ___..___________________________ 15,390.892 20,045.114
||| |||||| + module System <<System!ContextAwareResult.CompleteCallback>> 0.0 0.074 2 0.0 0 0 0 0 ____.___________________________ 20,045.469 20,045.543
||| |||||+ module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.FlushAsync(value class System.Threading.CancellationToken)>> 0.0 0.717 8 0.0 0 0 0 0 __._____________________________ 10,192.999 10,202.040
||| |||||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 0.0 0.006 1 0.0 0 0 0 0 _____________________.__________ 93,948.342 93,948.348
||| ||||+ module picohelper <<picohelper!?>> 0.0 37.671 10 0.0 0 0 0 0 _______._______o_.______________ 31,938.361 74,886.455
||| ||||+ module sspicli <<sspicli!InitializeSecurityContextW>> 0.0 7.989 7 0.0 0 0 0 0 ______o_________________________ 26,696.218 26,713.764
||| ||||+ CPU_TIME 0.0 0.376 2 0.0 0.376 2 0 0 __.______.______________________ 9,776.217 42,768.515
||| ||||+ module clr <<clr!AllocateObject>> 0.0 0.322 1 0.0 0 0 0 0 ___.____________________________ 14,768.715 14,769.036
||| ||||+ module mscorlib.ni <<mscorlib.ni!ExecutionContext.Run>> 0.0 0.123 3 0.0 0 0 0 0 ______._________________________ 26,722.814 26,722.937
||| ||||+ module mscorlib.ni <<mscorlib.ni!OverlappedData.UnsafePack>> 0.0 0.034 1 0.0 0 0 0 0 ______._________________________ 26,702.913 26,702.947
||| ||||+ module clr <<clr!GCInterface::SuppressFinalize>> 0.0 0.029 1 0.0 0 0 0 0 ______._________________________ 26,769.915 26,769.944
||| ||||+ module sspicli <<sspicli!DecryptMessage>> 0.0 0.026 1 0.0 0 0 0 0 ____.___________________________ 21,167.353 21,167.380
||| ||||+ module clr <<clr!Buffer::BlockCopy>> 0.0 0.018 1 0.0 0 0 0 0 ______________._________________ 63,887.352 63,887.370
||| ||||+ module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.TaskFactory`1+FromAsyncTrimPromise`1[System.Threading.Tasks.VoidTaskResult,System.__Canon].CompleteFromAsyncResult(System.IAsyncResult)>> 0.0 0.016 1 0.0 0 0 0 0 ______._________________________ 26,790.915 26,790.931
||| ||||+ module <<?!?>> 0.0 0.015 1 0.0 0 0 0 0 ________._______________________ 36,789.915 36,789.930
||| |||+ CPU_TIME 0.0 0.232 1 0.0 0.232 1 0 0 ___________.____________________ 48,767.352 48,767.585
||| ||+ module clr <<clr!JIT_New>> 0.0 0.014 1 0.0 0 0 0 0 _________.______________________ 42,803.304 42,803.317
||| |+ module clr <<clr!CheckVMForIOPacket>> 0.0 1.524 19 0.0 0 0 0 0 __......_.__.__._____.__________ 12,889.525 93,939.137
||| |+ module clr <<clr!JIT_ChkCastClassSpecial>> 0.0 0.232 1 0.0 0 0 0 0 __._____________________________ 12,899.528 12,899.760
||| |+ CPU_TIME 0.0 0.199 3 0.0 0.199 3 0 0 ____.___.______.________________ 19,974.233 67,886.426
||| + module picohelper <<picohelper!?>> 0.4 106,632.938 1,142 0.0 0 0 0 0 _19999999999999999999999996_____ 7,947.213 114,959.333
||| + module kernelbase <<kernelbase!WaitForSingleObjectEx>> 0.0 17.472 8 0.0 0 0 0 0 ____o___________________________ 19,940.612 19,958.084
||| + module ntoskrnl <<ntoskrnl!KiVmbusInterruptDispatch>> 0.0 2.932 2 0.0 0 0 0 0 ____.___________________________ 19,930.011 19,932.943
||| + module ntdll <<ntdll!EtwEventWrite>> 0.0 0.374 7 0.0 0 0 0 0 __.._._._.___.__________________ 9,804.224 58,906.381
||| + CPU_TIME 0.0 0.227 5 0.0 0.227 5 0 0 ____._.________.._______________ 17,718.008 69,887.407
||| + module <<?!?>> 0.0 0.120 1 0.0 0 0 0 0 __._____________________________ 12,123.448 12,123.568
||+ BLOCKED_TIME 0.0 7,027.567 106 0.0 7,027.567 106 0 0 78______________________________ 887.065 7,947.137
||+ CPU_TIME 0.0 33.192 142 0.0 33.192 142 0 0 oo______________________________ 886.454 7,947.213
||+ module ntdll <<ntdll!LdrInitializeThunk>> 0.0 3.313 23 0.0 0 0 0 0 __...._..._._._.________________ 9,775.216 65,976.378
||+ BROKEN 0.0 0.648 4 0.0 0 0 0 0 __.______.__.___________________ 9,769.949 53,946.437
||+ module ntdll <<ntdll!LdrpValidateUserCallTargetBitMapRet>> 0.0 0.511 1 0.0 0 0 0 0 __________._____________________ 46,885.338 46,885.848
I suggest just working around this by overriding the logging infrastructure to log to a null logger.
public class AzureSignalRDependencyResolver : IDependencyResolver
{
private readonly IDependencyResolver _resolver;
public AzureSignalRDependencyResolver(IDependencyResolver resolver) => _resolver = resolver;
public void Dispose() => _resolver.Dispose();
public object GetService(Type serviceType) => serviceType == typeof(ILoggerFactory) ? NullLoggerFactory.Instance : _resolver.GetService(serviceType);
public IEnumerable<object> GetServices(Type serviceType) => _resolver.GetServices(serviceType);
public void Register(Type serviceType, Func<object> activator) => _resolver.Register(serviceType, activator);
public void Register(Type serviceType, IEnumerable<Func<object>> activators) => _resolver.Register(serviceType, activators);
}
public class Startup
{
public void Configuration(IAppBuilder app)
{
var hubConfiguration = new HubConfiguration();
hubConfiguration.Resolver = new AzureSignalRDependencyResolver(hubConfiguration.Resolver);
app.MapAzureSignalR("", hubConfiguration);
}
}