title: ASP.NET Core: Huge delay before HTTP request is handled
body: <p>I have an ASP.NET Core application running on Ubuntu-server 18.04 on an Intel NUC.</p>
  <p>The application receives commands and start up to 4 MPV video player processes on background threads.</p>
  <p>When a controller is called, it basically writes a command in one of 4 command queues and returns. Then the command is consumed by a background thread which start/kill the process using <code>System.Diagnostics.Process</code>. So the controller operation should be really fast.</p>
  <p>At the beginning of the middlewares chain I have a diagnostic middleware that measures the operation duration. This one always reports values near 3-4ms, which is what I expect as I only write in a queue</p>
  <p>The problem is that, sometimes, the caller of the API reports times that can span up to several seconds.</p>
  <p>I have a network capture showing that there is a huge delay between when the HTTP request is received by the OS and when it is handled by the application.</p>
  <p>Logs of the POST requests made by the caller</p>
  <pre><code>1  Fr Aug  7 10:37:14 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;53;76
  2  Fr Aug  7 10:37:17 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;54;101
  3  Fr Aug  7 10:37:20 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;55;74
  4  Fr Aug  7 10:37:23 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;56;47
  5  Fr Aug  7 10:37:26 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;57;84
  6  Fr Aug  7 10:37:29 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;58;67
  7  Fr Aug  7 10:37:32 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;59;91
  8  Fr Aug  7 10:37:35 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;60;57
  9  Fr Aug  7 10:37:39 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;61;50
  10 Fr Aug  7 10:37:42 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;62;71
  11 Fr Aug  7 10:37:45 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;63;69
  12 Fr Aug  7 10:37:49 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;64;948
  13 Fr Aug  7 10:37:52 CEST 2020;rtsp://192.168.8.12/VideoInput/1/H264/1;65;66
  14 Fr Aug  7 10:37:55 CEST 2020;rtsp://192.168.8.9/VideoInput/1/H264/1;66;56
  </code></pre>
  <p>The last number is the request time. We can see that most of the case it is &lt; 100ms but here we have a value near 1000ms at line 12</p>
  <p>TCP dump, where the slow request have been highlighted</p>
  <p><a href="https://i.stack.imgur.com/kVKQx.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/kVKQx.png" alt="TCP trace" /></a></p>
  <p>We can see that the numbers are consistent with the caller.</p>
  <p>Now, the logs from ASP.NET Core, where we can see that the request is logged approx 900ms later</p>
  <pre><code>[10:37:45.198 INF] Microsoft.AspNetCore.Hosting.Diagnostics - Request starting HTTP/1.1 POST http://192.168.8.200:9000/api/v1/video/affect?playerIndex=4 application/json 120
  [10:37:45.198 INF] Microsoft.AspNetCore.Routing.EndpointMiddleware - Executing endpoint 'VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer)'
  [10:37:45.199 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker - Route matched with {action = &quot;AffectCamera&quot;, controller = &quot;Player&quot;}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Boolean] AffectCamera(VideoPlayer.Controllers.AffectCameraInputDTO, Int32) on controller VideoPlayer.Controllers.PlayerController (VideoPlayer).
  [10:37:45.201 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'System.Boolean'.
  [10:37:45.201 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker - Executed action VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer) in 2.0618ms
  [10:37:45.202 INF] Microsoft.AspNetCore.Routing.EndpointMiddleware - Executed endpoint 'VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer)'
  [10:37:45.202 INF] VideoPlayer.Utils.RequestDiagnosticMiddleware - Request POST /api/v1/video/affect =&gt; 200 took 3ms -- IP source: 192.168.8.204
  [10:37:45.202 INF] Microsoft.AspNetCore.Hosting.Diagnostics - Request finished in 4.2783ms 200 application/json; charset=utf-8
  
  ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  [10:37:49.110 INF] Microsoft.AspNetCore.Hosting.Diagnostics - Request starting HTTP/1.1 POST http://192.168.8.200:9000/api/v1/video/affect?playerIndex=1 application/json 118
  [10:37:49.111 INF] Microsoft.AspNetCore.Routing.EndpointMiddleware - Executing endpoint 'VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer)'
  [10:37:49.112 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker - Route matched with {action = &quot;AffectCamera&quot;, controller = &quot;Player&quot;}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Boolean] AffectCamera(VideoPlayer.Controllers.AffectCameraInputDTO, Int32) on controller VideoPlayer.Controllers.PlayerController (VideoPlayer).
  [10:37:49.115 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'System.Boolean'.
  [10:37:49.115 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker - Executed action VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer) in 2.4829ms
  [10:37:49.116 INF] Microsoft.AspNetCore.Routing.EndpointMiddleware - Executed endpoint 'VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer)'
  [10:37:49.116 INF] VideoPlayer.Utils.RequestDiagnosticMiddleware - Request POST /api/v1/video/affect =&gt; 200 took 4ms -- IP source: 192.168.8.204
  [10:37:49.117 INF] Microsoft.AspNetCore.Hosting.Diagnostics - Request finished in 6.534ms 200 application/json; charset=utf-8
  ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  
  [10:37:49.127 INF] Microsoft.AspNetCore.Hosting.Diagnostics - Request starting HTTP/1.1 POST http://192.168.8.200:9000/api/v1/video/affect?playerIndex=2 application/json 118
  [10:37:49.128 INF] Microsoft.AspNetCore.Routing.EndpointMiddleware - Executing endpoint 'VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer)'
  [10:37:49.129 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker - Route matched with {action = &quot;AffectCamera&quot;, controller = &quot;Player&quot;}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Boolean] AffectCamera(VideoPlayer.Controllers.AffectCameraInputDTO, Int32) on controller VideoPlayer.Controllers.PlayerController (VideoPlayer).
  [10:37:49.132 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor - Executing ObjectResult, writing value of type 'System.Boolean'.
  [10:37:49.132 INF] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker - Executed action VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer) in 2.6272ms
  [10:37:49.133 INF] Microsoft.AspNetCore.Routing.EndpointMiddleware - Executed endpoint 'VideoPlayer.Controllers.PlayerController.AffectCamera (VideoPlayer)'
  [10:37:49.133 INF] VideoPlayer.Utils.RequestDiagnosticMiddleware - Request POST /api/v1/video/affect =&gt; 200 took 5ms -- IP source: 192.168.8.204
  [10:37:49.133 INF] Microsoft.AspNetCore.Hosting.Diagnostics - Request finished in 6.9064ms 200 application/json; charset=utf-8
  </code></pre>
  <p>Any idea what can cause this delay, how I can improve it or analyze it further?</p>
  <hr />
  <p>EDIT</p>
  <p>It seems it is somehow related with the fact I read the MPV process standard and error outputs (to get logs from the player)</p>
  <p>I tried to redirect the output and not consume it and everything works fine. As soon as I try to consume the output the issue appears randomly. Even if I don't do any processing with this output.</p>
  <p>I tried to read it using different methods</p>
  <ul>
  <li>With the <code>xxxDataReceived</code> events</li>
  <li>On a background thread using <code>StandardOutput</code> / <code>StandardError</code> properties
  <ul>
  <li>With <code>ReadLine()</code></li>
  <li>With <code>Read()</code> and a buffer</li>
  </ul>
  </li>
  </ul>
  <p>In all the cases lags appear.</p>
  <p>If I redirect the output, but don't consume it or if I don't redirect the output, everything is fine.</p>
  <p>The process doesn't output a lot. Less than 1 line/second</p>