У меня есть приложение ASP. NET Core, работающее на Ubuntu-server 18.04 на Intel NU C.
Приложение получает команды и запускает до 4 процессов видеоплеера MPV в фоновом режиме потоков.
Когда вызывается контроллер, он в основном записывает команду в одну из 4 очередей команд и возвращает ее. Затем команда используется фоновым потоком, который запускает / завершает процесс, используя System.Diagnostics.Process. Так что работа контроллера должна быть очень быстрой.
В начале цепочки промежуточного ПО у меня есть c промежуточное ПО диагностики, которое измеряет продолжительность работы. Этот всегда сообщает значения около 3-4 мс, что я и ожидал, поскольку я пишу только в очереди
Проблема в том, что иногда вызывающий API сообщает время, которое может охватывать до нескольких секунд.
У меня есть снимок сети, показывающий, что существует огромная задержка между получением HTTP-запроса операционной системой и его обработкой приложением.
Журналы POST-запросов, выполненных вызывающий
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
Последнее число - время запроса. Мы можем видеть, что в большинстве случаев это <100 мс, но здесь у нас есть значение около 1000 мс в строке 12 </p>
Дамп TCP, где был выделен медленный запрос
Трассировка TCP
Мы видим, что числа соответствуют вызывающему.
Теперь логи из ASP. NET Core, где мы видим, что запрос зарегистрирован примерно через 900 мсек
[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 = "AffectCamera", controller = "Player"}. 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 => 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 = "AffectCamera", controller = "Player"}. 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 => 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 = "AffectCamera", controller = "Player"}. 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 => 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
Есть идеи, что может вызвать эту задержку, как я могу ее улучшить или проанализировать дальше?
РЕДАКТИРОВАТЬ
Кажется, это как-то связано с тем фактом, что я прочитал стандартный процесс MPV и сообщения об ошибках (для получения логов от плеера) потребляйте его, и все работает нормально. Как только я пытаюсь использовать вывод, проблема возникает случайным образом. Даже если я не обрабатываю этот вывод.
Я пытался прочитать его разными методами
- С событиями
xxxDataReceived - На фоновый поток с использованием
StandardOutput / StandardError свойств - С
ReadLine() - С
Read() и буфером
В появляются задержки во всех случаях.
Если я перенаправляю вывод, но не использую его, или если я не перенаправляю вывод, все в порядке.
Процесс не выводится много. Менее 1 строки в секунду