benaadams / Ben.BlockingDetector

Blocking Detection for ASP.NET Core
Apache License 2.0
731 stars 35 forks source link

Block Detected in Web API while writing output #25

Open spenceclark opened 3 years ago

spenceclark commented 3 years ago

I have a pretty standard dotnet Web API which returns JSON. All standard framework stuff.

I am getting this in my logs everytime the size of the response goes above a certain level. For example I can call an API with parameters that causes it to return a few records and I don't get the message. But then the same API with parameters that cause it to return 50 records I get the warning - in fact this same warning is reported hundreds of times at once.

As the stack trace seems to be entirely inside the MVC framework code, it doesn't seem like I can do anything about it.

Has anyone else seen this? As it stands it is creating too much noise in the log to be able to identify real problems.


warn: Ben.Diagnostics.BlockingMonitor[6]
      Blocking method has been invoked and blocked, this can lead to threadpool starvation.
         at System.IO.FileStream.Write(Byte[] array, Int32 offset, Int32 count)
         at Microsoft.AspNetCore.WebUtilities.PagedByteBuffer.MoveTo(Stream stream)
         at Microsoft.AspNetCore.WebUtilities.FileBufferingWriteStream.Write(Byte[] buffer, Int32 offset, Int32 count)
         at Microsoft.AspNetCore.WebUtilities.HttpResponseStreamWriter.Write(Char value)
         at Newtonsoft.Json.JsonTextWriter.WritePropertyName(String name, Boolean escape)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeObject(JsonWriter writer, Object value, JsonObjectContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeList(JsonWriter writer, IEnumerable values, JsonArrayContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeObject(JsonWriter writer, Object value, JsonObjectContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeList(JsonWriter writer, IEnumerable values, JsonArrayContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeObject(JsonWriter writer, Object value, JsonObjectContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.Serialize(JsonWriter jsonWriter, Object value, Type objectType)
         at Newtonsoft.Json.JsonSerializer.SerializeInternal(JsonWriter jsonWriter, Object value, Type objectType)
         at Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonOutputFormatter.WriteResponseBodyAsync(OutputFormatterWriteContext context, Encoding selectedEncoding)
         at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
         at Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonOutputFormatter.WriteResponseBodyAsync(OutputFormatterWriteContext context, Encoding selectedEncoding)
         at Microsoft.AspNetCore.Mvc.Formatters.TextOutputFormatter.WriteAsync(OutputFormatterWriteContext context)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor.ExecuteAsync(ActionContext context, ObjectResult result)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeResultAsync>g__Logged|21_0(ResourceInvoker invoker, IActionResult result)
         at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeResultAsync>g__Logged|21_0(ResourceInvoker invoker, IActionResult result)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.ResultNext[TFilter,TFilterAsync](State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResultFilterAsync[TFilter,TFilterAsync]()
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.ResultNext[TFilter,TFilterAsync](State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResultFilterAsync[TFilter,TFilterAsync]()
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResultFilterAwaitedAsync[TFilter,TFilterAsync]()
         at Microsoft.AspNetCore.Mvc.Filters.ActionFilterAttribute.OnResultExecutionAsync(ResultExecutingContext context, ResultExecutionDelegate next)
         at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
         at Microsoft.AspNetCore.Mvc.Filters.ActionFilterAttribute.OnResultExecutionAsync(ResultExecutingContext context, ResultExecutionDelegate next)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.ResultNext[TFilter,TFilterAsync](State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResultFilterAsync[TFilter,TFilterAsync]()
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.ResultNext[TFilter,TFilterAsync](State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeResultFilters()
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
         at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
         at System.Runtime.CompilerServices.TaskAwaiter.<>c.<OutputWaitEtwEvents>b__12_0(Action innerContinuation, Task innerTask)
         at System.Threading.ExecutionContext.RunForThreadPoolUnsafe[TState](ExecutionContext executionContext, Action`1 callback, TState& state)
         at System.Threading.ThreadPoolWorkQueue.Dispatch()```
spenceclark commented 3 years ago

OK its seems to be specific to Newtonsoft - I switched my JSON serialisation from Newtonsoft to the new System.Text.Json implementation and I no longer get those warnings.

spenceclark commented 3 years ago

Hmmm, System.Text.Json has too many other shortcomings for me to migrate to it for now. Having to revert to Newtonsoft and live with the potential blocking.

Would be interested to hear if anyone else has this problem.

spenceclark commented 3 years ago

Ah - https://github.com/JamesNK/Newtonsoft.Json/issues/1193 - Ben, it looks like you already raised the issue of async serialisation in Newtonsoft, and its never going to happen.

spenceclark commented 3 years ago

https://github.com/dotnet/aspnetcore/blob/v3.1.11/src/Mvc/Mvc.NewtonsoftJson/src/NewtonsoftJsonOutputFormatter.cs

This appears to be where it is happening inside MVC - Its strange, I have AllowSynchronousIO turned off so the framework should actually stop if it detects sync writes to output stream.

webprofusion-chrisc commented 3 years ago

Hi, I just found the exact same thing. Upgrading from .net core 3.1 to .net 5 seems to have fixed it(?)

spenceclark commented 3 years ago

Hi, I just found the exact same thing. Upgrading from .net core 3.1 to .net 5 seems to have fixed it(?)

Ah ok. Upgrade is on my roadmap soon at least. But did it fix it, or did it silently switch you from Newtonsoft to System.Text.Json?

webprofusion-chrisc commented 3 years ago

I don't think it can switch us automatically, we're using JsonConvert.SerializeObject. It also seemed to fixed an issue on linux where we were encountering 'thread exhaustion' when lots of people hit our API.

Excuse the code, it's 10 years old: https://github.com/openchargemap/ocm-system/blob/0a7a52d85e4671b42b0b5ed52cb958be3068ed51/API/OCM.Net/OCM.API.Web/Compatibility/OutputProviders/JSONOutputProvider.cs#L20