benaadams / Ben.BlockingDetector

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

Blocking against static files (css/js) #14

Open timgabrhel opened 4 years ago

timgabrhel commented 4 years ago

I am just getting started using the middleware, and I'm coming across some blocking notes against our html/css files. I am not sure how this should be handled. Any direction?

ASP.NET Core 3.1

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2.0 GET https://localhost:44307/login  
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'WebMvc.Areas.Account.Controllers.AuthController.Login (WebMvc)'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {area = "Account", action = "Login", controller = "Auth"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.IActionResult Login(System.String, System.String) on controller WebMvc.Areas.Account.Controllers.AuthController (WebMvc).
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[1]
      Executing action method WebMvc.Areas.Account.Controllers.AuthController.Login (WebMvc) - Validation state: Valid
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action method WebMvc.Areas.Account.Controllers.AuthController.Login (WebMvc), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0505ms.
info: Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor[1]
      Executing ViewResult, running view Login.
info: Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor[4]
      Executed ViewResult - view Login executed in 5.4982ms.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action WebMvc.Areas.Account.Controllers.AuthController.Login (WebMvc) in 9.9739ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'WebMvc.Areas.Account.Controllers.AuthController.Login (WebMvc)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2.0 GET https://localhost:44307/css/Site.css?v=637231648404436533  
warn: Ben.Diagnostics.BlockingMonitor[6]
      Blocking method has been invoked and blocked, this can lead to threadpool starvation.
         at System.IO.FileStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken, Int32& synchronousResult)
         at System.IO.FileStream.ReadAsyncTask(Byte[] array, Int32 offset, Int32 count, CancellationToken cancellationToken)
         at System.IO.FileStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
         at Microsoft.AspNetCore.Http.StreamCopyOperationInternal.CopyToAsync(Stream source, Stream destination, Nullable`1 count, Int32 bufferSize, CancellationToken cancel)
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
         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.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
         at System.Runtime.CompilerServices.TaskAwaiter.<>c.<OutputWaitEtwEvents>b__12_0(Action innerContinuation, Task innerTask)
         at System.Threading.Tasks.AwaitTaskContinuation.System.Threading.IThreadPoolWorkItem.Execute()
         at System.Threading.ThreadPoolWorkQueue.Dispatch()

info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[2]
      Sending file. Request path: '/css/Site.css'. Physical path: 'C:\dev\WebMvc\wwwroot\css\Site.css'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 47.1026ms 200 text/css
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2.0 GET https://localhost:44307/js/site.js?v=637231648404439536  
info: Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware[2]
      Sending file. Request path: '/js/site.js'. Physical path: 'C:\dev\wagt\WebMvc\wwwroot\js\site.js'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 72.4794ms 200 application/javascript
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 306.2087ms 200 text/html; charset=utf-8
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2.0 POST https://localhost:44307/profiler/results application/json 835
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 233.0392ms 200 application/json

Here's the Configure method.

        public void Configure(IApplicationBuilder app)
        {
            app.UseBlockingDetection();

            if (Environment.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            else
            {
                app.UseHsts();
                app.UseExceptionHandler("/error");
                app.UseStatusCodePagesWithRedirects("/error/{0}");
            }

            app.UseHttpsRedirection();

            app.UseSession();

            app.UseStaticFiles();

            app.UseRouting();

            app.UseAuthentication();
            app.UseAuthorization();

            app.UseMiniProfiler();

            // app custom
            app.UseMaintenanceMiddleware();
            app.UseLegacyRedirectMiddleware();
            app.UseRequestRefreshClaimsMiddleware();

            app.UseEndpoints(delegate (IEndpointRouteBuilder endpoints)
            {
                endpoints.MapControllerRoute("areaRoute", "{area:exists}/{controller=Dashboard}/{action=Index}/{id?}");
                endpoints.MapDefaultControllerRoute();
            });
        }
benaadams commented 4 years ago

That's quite interesting...

warn: Ben.Diagnostics.BlockingMonitor[6]
      Blocking method has been invoked and blocked, this can lead to threadpool starvation.
         at System.IO.FileStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken, Int32& synchronousResult)
         at System.IO.FileStream.ReadAsyncTask(Byte[] array, Int32 offset, Int32 count, CancellationToken cancellationToken)
         at System.IO.FileStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
         at Microsoft.AspNetCore.Http.StreamCopyOperationInternal.CopyToAsync(Stream source, Stream destination, Nullable`1 count, Int32 bufferSize, CancellationToken cancel)
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
         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.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
         at System.Runtime.CompilerServices.TaskAwaiter.<>c.<OutputWaitEtwEvents>b__12_0(Action innerContinuation, Task innerTask)
         at System.Threading.Tasks.AwaitTaskContinuation.System.Threading.IThreadPoolWorkItem.Execute()
         at System.Threading.ThreadPoolWorkQueue.Dispatch()

/cc @stephentoub

stephentoub commented 4 years ago

Presumably it's https://github.com/dotnet/runtime/issues/16341.

timgabrhel commented 4 years ago

Am I doing something unique to put me in this situation, or is this happening across the board for anyone using static files?

timgabrhel commented 4 years ago

@benaadams @stephentoub

Sorry if this isn't the right place, but I'm starting here cause of the blocking detector package.

I'm running in to another scenario that seems to be pointing back to the same IO issue. I have an ASP.NET Core 3.1 API returning a complex object (multiple objects as properties all of which recursively may have children objects). As it stands on my dev box (IIS Express, i7-6700k, 32GB RAM), the response of the request is triggering another blocking detector.

The response data of the request is 62KB. I am returning a new JsonResult(myObj). I've found when intentionally clearing one of the large properties on the response, it takes me down to 12KB and no buffering takes place. Am I hitting a JSON.NET object/ASP.NET response size limit?

Edit - looks like 30KB is the limit before it buffers to disk?

I see 32 instances of this blocker detected. Here are only the top couple lines of the stack trace.

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.FlushInternal(Boolean flushEncoder)
         at Microsoft.AspNetCore.WebUtilities.HttpResponseStreamWriter.Write(String 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.Serialize(JsonWriter jsonWriter, Object value, Type objectType)
         at Newtonsoft.Json.JsonSerializer.SerializeInternal(JsonWriter jsonWriter, Object value, Type objectType)
         at Newtonsoft.Json.JsonSerializer.Serialize(JsonWriter jsonWriter, Object value)
         at Microsoft.AspNetCore.Mvc.NewtonsoftJson.NewtonsoftJsonResultExecutor.ExecuteAsync(ActionContext context, JsonResult result)
         at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
         at Microsoft.AspNetCore.Mvc.NewtonsoftJson.NewtonsoftJsonResultExecutor.ExecuteAsync(ActionContext context, JsonResult result)
         at Microsoft.AspNetCore.Mvc.JsonResult.ExecuteResultAsync(ActionContext context)
benaadams commented 4 years ago

I'd raise that in https://github.com/dotnet/aspnetcore the System.Text.Json serializer may fare better than Newtonsoft.Json; though you need to check your outputs/inputs when changing as it has caveats like it only serializes properties not fields etc