Blocking detection in Development

[aspnet-hello]

From @benaadams on Saturday, December 30, 2017 9:21:33 PM

Warning when blocking calls are made on the threadpool.

Doesn't detect everything...

1. Won't alert for blocking on precompleted tasks (e.g. a single small Body.Write)
2. Won't alert for blocking that happens in syscalls (e.g. File.Read(...), Thread.Sleep)

Will detect CLR initiated waits lock,ManualResetEventSlim,Semaphore{Slim},Task.Wait,Task.Result etc; if they do block.

e.g. if you had a method like:

public Task BlockingWrite(HttpContext httpContext)
{
    var response = httpContext.Response;
    response.StatusCode = 200;
    response.ContentType = "text/plain";

    var s = new string('n', 160000);
    response.ContentLength = s.Length * 3;
    response.Body.Write(Encoding.ASCII.GetBytes(s), 0, s.Length);
    response.Body.Write(Encoding.ASCII.GetBytes(s), 0, s.Length);
    response.Body.Write(Encoding.ASCII.GetBytes(s), 0, s.Length);

    return Task.CompletedTask;
}

And UseDeveloperExceptionPage is added, it will ouput

warn: Microsoft.AspNetCore.Diagnostics.DetectBlocking[6]
      Blocking method has been invoked and blocked, this can lead to threadpool starvation.
         at System.Threading.ManualResetEventSlim.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
         at System.Threading.Tasks.Task.SpinThenBlockingWait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
         at System.Threading.Tasks.Task.InternalWait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
         at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.FrameResponseStream.Write(Byte[] buffer, Int32 offset, Int32 count)
         at AoA.Gaia.Startup.BlockingWrite(HttpContext httpContext)
         at AoA.Gaia.SpaceWebSocketsMiddleware.Invoke(HttpContext httpContext)
         at Microsoft.AspNetCore.WebSockets.WebSocketMiddleware.Invoke(HttpContext context)
         at AoA.Space.ErrorHandlerMiddleware.<Invoke>d__4.MoveNext()
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
         at AoA.Space.ErrorHandlerMiddleware.Invoke(HttpContext httpContext)
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.<Invoke>d__7.MoveNext()
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)
         at AoA.Gaia.BlockingDetection.BlockingDetectionMiddleware.<Invoke>d__3.MoveNext()
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
         at AoA.Gaia.BlockingDetection.BlockingDetectionMiddleware.Invoke(HttpContext httpContext)
         at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.<Invoke>d__3.MoveNext()
         at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
         at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(HttpContext httpContext)
         at Microsoft.AspNetCore.Hosting.Internal.HostingApplication.ProcessRequestAsync(Context context)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Frame`1.<ProcessRequestsAsync>d__2.MoveNext()
         at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
         at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe.<>c.<.cctor>b__67_3(Object o)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.LoggingThreadPool.<>c__DisplayClass6_0.<Schedule>b__0()
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.LoggingThreadPool.<RunAction>b__3_0(Object o)
         at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
         at System.Threading.ThreadPoolWorkQueue.Dispatch()

/cc @davidfowl @stephentoub

Copied from original issue: aspnet/Diagnostics#429

[aspnet-hello]

From @benaadams on Saturday, December 30, 2017 9:28:55 PM

And if you had a Demystifying logger attached it would look more like this

warn: Microsoft.AspNetCore.Diagnostics.DetectBlocking[6]
 Blocking method has been invoked and blocked, this can lead to threadpool starvation.
  at bool System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, CancellationToken cancellationToken)
  at bool System.Threading.Tasks.Task.SpinThenBlockingWait(int millisecondsTimeout, CancellationToken cancellationToken)
  at bool System.Threading.Tasks.Task.InternalWait(int millisecondsTimeout, CancellationToken cancellationToken)
  at void Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.FrameResponseStream.Write(byte[] buffer, int offset, int count)
  at Task AoA.Gaia.Startup.BlockingWrite(HttpContext httpContext) in C:\Work\AoA\src\AoA.Gaia\Startup.cs:line 116
  at Task AoA.Gaia.SpaceWebSocketsMiddleware.Invoke(HttpContext httpContext) in C:\Work\AoA\src\AoA.Gaia\SpaceWebSocketsMiddleware.cs:line 128
  at Task Microsoft.AspNetCore.WebSockets.WebSocketMiddleware.Invoke(HttpContext context)
  at async Task AoA.Space.ErrorHandlerMiddleware.Invoke(HttpContext httpContext) in C:\Work\AoA\src\AoA.Gaia\ErrorHandlerMiddleware.cs:line 29
  at void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start<TStateMachine>(ref TStateMachine stateMachine)
  at Task AoA.Space.ErrorHandlerMiddleware.Invoke(HttpContext httpContext)
  at async Task Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)
  at void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start<TStateMachine>(ref TStateMachine stateMachine)
  at Task Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)
  at async Task AoA.Gaia.BlockingDetection.BlockingDetectionMiddleware.Invoke(HttpContext httpContext) in C:\Work\AoA\src\AoA.Gaia\BlockingDetection\BlockingDetectionMiddleware.cs:line 33
  at void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start<TStateMachine>(ref TStateMachine stateMachine)
  at Task AoA.Gaia.BlockingDetection.BlockingDetectionMiddleware.Invoke(HttpContext httpContext)
  at async Task Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(HttpContext httpContext)
  at void System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start<TStateMachine>(ref TStateMachine stateMachine)
  at Task Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(HttpContext httpContext)
  at Task Microsoft.AspNetCore.Hosting.Internal.HostingApplication.ProcessRequestAsync(Context context)
  at async Task Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Frame<TContext>.ProcessRequestsAsync()
  at void Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe._scheduleContinuation(object o)
  at void Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.LoggingThreadPool.Schedule(Action<object> action, object state)+() => { }
  at void Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.LoggingThreadPool.RunAction()+(object o) => { }
  at bool System.Threading.ThreadPoolWorkQueue.Dispatch()

[aspnet-hello]

From @benaadams on Saturday, December 30, 2017 9:52:04 PM

Should it be added by WebHost.CreateDefaultBuilder instead so it warns in Production by default?

[aspnet-hello]

From @benaadams on Saturday, December 30, 2017 10:52:45 PM

Also catches held locks

120: public Task LockedMethod(HttpContext httpContext)
121: {
122:     var response = httpContext.Response;
123:     response.StatusCode = 200;
124:     response.ContentType = "text/plain";
125:     lock (obj) // **********
126:     {
127:         // locked outside for 1 sec
128:     }
129:     var s = new string('n', 16);
130:     response.ContentLength = s.Length;
131:     return response.WriteAsync(s);
132: }

Outputs (with some extra formatting)

warn: Microsoft.AspNetCore.Diagnostics.DetectBlocking[6]
 Blocking method has been invoked and blocked, this can lead to threadpool starvation.
     at Task AoA.Gaia.Startup.LockedMethod(HttpContext httpContext)
       in C:\Work\AoA\src\AoA.Gaia\Startup.cs:line 125 ********
     at IApplicationBuilder Microsoft.AspNetCore.Builder.UseExtensions.Use(IApplicationBuilder app, Func<HttpContext, Func<Task>, Task> middleware)+() => { }
....
     at void Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe._scheduleContinuation(object o)
     at void Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.LoggingThreadPool.Schedule(Action<object> action, object state)+() => { }
     at void Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.LoggingThreadPool.RunAction()+(object o) => { }
     at bool System.Threading.ThreadPoolWorkQueue.Dispatch()

[aspnet-hello]

From @benaadams on Saturday, December 30, 2017 11:14:41 PM

Raised issue for sys calls https://github.com/dotnet/coreclr/issues/15675

[benaadams]

@Eilon should this new bot be closing and locking PRs?

[aspnet-hello]

Nope, I was a bad bot. This totally isn't @Eilon 😁