Azure / azure-signalr

Azure SignalR Service SDK for .NET
https://aka.ms/signalr-service
MIT License
422 stars 100 forks source link

Azure SignalR ASP.NET (Full Framework) running on Azure App Service Pv3 results in excessive application logs #1837

Open maskati opened 11 months ago

maskati commented 11 months ago

There is an issue when using a combination of the following:

The issue results from:

The end result is a system that logs several million debug logs per day to Azure Monitor.

image

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:

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.

marafiq commented 5 months ago

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.

image

marafiq commented 5 months ago

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

image

Then when Drilling down for string allocations. image

For byte[] drill down image

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.

image

Automated analysis suggestion - I tried removing the default trace listener but it did not have any impact.

image

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
maskati commented 5 months ago

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);
    }
}
marafiq commented 5 months ago

Thank you @maskati will try out the workaround.