tinypilot
tinypilot copied to clipboard
tiny-pilot
uStreamer service restarts are taking 90-120s
While @db39 was investigating an unrelated issue, he discovered that running sudo service ustreamer stop or sudo service ustreamer restart takes 90-120s to complete, when I'd expect it to be just a few seconds.
The bug is likely on our side, as we define the service and the wrapper script.
We should figure out what's slowing it down so much.
Per discussion today, it sounds like the restarts only take this long when we're using the MS2130 dongle. I originally thought this happened in general with our uStreamer service.
Given that it's a niche outside of our supported scenarios, we should limit this investigation to a 2-3 hours max. If we don't have a handle on it by then, we should write up what we found out and then shelve this bug for later.
Here's an example log of what happens when running into this issue:
Nov 14 15:51:20 raspberrypi systemd[1]: Stopping uStreamer - Lightweight, optimized video encoder...
Nov 14 15:52:50 raspberrypi systemd[1]: ustreamer.service: State 'stop-sigterm' timed out. Killing.
Nov 14 15:52:50 raspberrypi systemd[1]: ustreamer.service: Killing process 4339 (main) with signal SIGKILL.
Nov 14 15:52:50 raspberrypi systemd[1]: ustreamer.service: Killing process 4416 (stream) with signal SIGKILL.
Nov 14 15:52:50 raspberrypi systemd[1]: ustreamer.service: Killing process 4418 (jw-0) with signal SIGKILL.
Nov 14 15:52:50 raspberrypi systemd[1]: ustreamer.service: Main process exited, code=killed, status=9/KILL
Nov 14 15:52:50 raspberrypi systemd[1]: ustreamer.service: Failed with result 'timeout'.
Nov 14 15:52:50 raspberrypi systemd[1]: Stopped uStreamer - Lightweight, optimized video encoder.
I've been able to reproduce this consistently. And it relies on the values in /opt/ustreamer-launcher/configs.d/000-defaults.yml. With the default values using the MS2130 dongle, everything works ok.
# Settings for an HDMI to USB video capture dongle.
---
ustreamer_encoder: hw
ustreamer_format: jpeg
ustreamer_resolution: "1920x1080"
Changing ustreamer_encoder to m2m-image or cpu also work fine.
The problems start when changing ustreamer_format from jpeg to yuyv. ustreamer reports No Signal and when you try to restart or stop the ustreamer service, it times out (like the above).
Unfortunately, I don't know the underlying reason. I can't find any logs or info to suggest what the issue may be.
After some experimentation, I found that using --encoder cpu --format yuyv would work when running as the default user (pilot in my case). But when using the ustreamer service, it doesn't work (No Signal):
Nov 15 13:26:17 raspberrypi launch[4657]: + exec /opt/ustreamer/ustreamer --port 48001 --persistent --h264-sink tinypilot::ustreamer::h264 --h264-sink-mode 777 --h264-sink-rm --encoder cpu --format yuyv --resolution 1920x1080
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.735 main] -- Starting PiKVM uStreamer 5.43 ...
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.736 main] -- Using internal blank placeholder
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.736 main] -- Using H264-sink: tinypilot::ustreamer::h264
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.736 main] -- Listening HTTP on [127.0.0.1]:48001
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.736 stream] -- Using V4L2 device: /dev/video0
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.736 stream] -- Using desired FPS: 0
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.736 http] -- Starting HTTP eventloop ...
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.737 stream] -- H264: Initializing encoder ...
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.744 stream] -- H264: Configuring encoder: DMA=0 ...
Nov 15 13:26:17 raspberrypi launch[4657]: ================================================================================
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.865 stream] -- Device fd=10 opened
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.865 stream] -- Using input channel: 0
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.882 stream] -- Using resolution: 1920x1080
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.882 stream] -- Using format: YUYV
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.899 stream] -- Using HW FPS: 0 -> 60 (coerced)
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.899 stream] -- Using IO method: MMAP
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.912 stream] -- Requested 5 device buffers, got 5
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.917 stream] -- Capturing started
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.917 stream] -- Using JPEG quality: 80%
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.917 stream] -- Creating pool JPEG with 4 workers ...
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2327.918 stream] -- Capturing ...
Nov 15 13:26:17 raspberrypi launch[4657]: -- INFO [2328.111 stream] -- H264: Configuring encoder: DMA=1 ...
Nov 15 13:26:19 raspberrypi launch[4657]: -- INFO [2330.304 http] -- HTTP: NEW client (now=1): [192.168.0.133]:37752, id=654184b90f16cb63
Nov 15 13:26:21 raspberrypi launch[4657]: -- INFO [2331.786 http] -- HTTP: DEL client (now=0): [192.168.0.133]:37752, id=654184b90f16cb63, Resource temporarily unavailable (reading,eof)
Nov 15 13:26:21 raspberrypi launch[4657]: -- INFO [2331.786 http] -- HTTP: NEW client (now=1): [192.168.0.133]:51332, id=658c490773be3866
Running the same command as the ustreamer user also results in No Signal:
ustreamer@raspberrypi:/home/pilot$ /opt/ustreamer/ustreamer --port 48001 --persistent --h264-sink tinypilot::ustreamer::h264 --h264-sink-mode 777 --h264-sink-rm --encoder cpu --format yuyv --resolution 1920x1080
-- INFO [2519.590 main] -- Starting PiKVM uStreamer 5.43 ...
-- INFO [2519.591 main] -- Using internal blank placeholder
-- INFO [2519.591 main] -- Using H264-sink: tinypilot::ustreamer::h264
-- INFO [2519.592 main] -- Listening HTTP on [127.0.0.1]:48001
-- INFO [2519.592 stream] -- Using V4L2 device: /dev/video0
-- INFO [2519.592 stream] -- Using desired FPS: 0
-- INFO [2519.592 http] -- Starting HTTP eventloop ...
-- INFO [2519.593 stream] -- H264: Initializing encoder ...
-- INFO [2519.615 stream] -- H264: Configuring encoder: DMA=0 ...
================================================================================
-- INFO [2519.749 stream] -- Device fd=10 opened
-- INFO [2519.749 stream] -- Using input channel: 0
-- INFO [2519.766 stream] -- Using resolution: 1920x1080
-- INFO [2519.766 stream] -- Using format: YUYV
-- INFO [2519.783 stream] -- Using HW FPS: 0 -> 60 (coerced)
-- INFO [2519.783 stream] -- Using IO method: MMAP
-- INFO [2519.803 stream] -- Requested 5 device buffers, got 5
-- INFO [2519.813 stream] -- Capturing started
-- INFO [2519.813 stream] -- Using JPEG quality: 80%
-- INFO [2519.813 stream] -- Creating pool JPEG with 4 workers ...
-- INFO [2519.814 stream] -- Capturing ...
-- INFO [2519.996 stream] -- H264: Configuring encoder: DMA=1 ...
-- INFO [2526.318 http] -- HTTP: NEW client (now=1): [192.168.0.133]:50726, id=ffdb42c8514c4c22
-- INFO [2528.679 http] -- HTTP: DEL client (now=0): [192.168.0.133]:50726, id=ffdb42c8514c4c22, Resource temporarily unavailable (reading,eof)
-- INFO [2528.679 http] -- HTTP: NEW client (now=1): [192.168.0.133]:50734, id=485aed9584714398
-- INFO [2529.892 http] -- HTTP: NEW client (now=2): [192.168.0.133]:50750, id=ec31b5f91d3b23fc
-- INFO [2530.694 http] -- HTTP: DEL client (now=1): [192.168.0.133]:50734, id=485aed9584714398, Resource temporarily unavailable (reading,eof)
But running the same command as the default user works:
pilot@raspberrypi:~ $ /opt/ustreamer/ustreamer --port 48001 --persistent --h264-sink tinypilot::ustreamer::h264 --h264-sink-mode 777 --h264-sink-rm --encoder cpu --format yuyv --resolution 1920x1080
-- INFO [2566.303 main] -- Starting PiKVM uStreamer 5.43 ...
-- INFO [2566.303 main] -- Using internal blank placeholder
-- INFO [2566.303 main] -- Using H264-sink: tinypilot::ustreamer::h264
-- ERROR [2566.304 main] -- H264-sink: Can't open shared memory: Permission denied
-- INFO [2566.305 main] -- Listening HTTP on [127.0.0.1]:48001
-- INFO [2566.305 stream] -- Using V4L2 device: /dev/video0
-- INFO [2566.305 stream] -- Using desired FPS: 0
================================================================================
-- INFO [2566.309 http] -- Starting HTTP eventloop ...
-- INFO [2566.413 stream] -- Device fd=8 opened
-- INFO [2566.413 stream] -- Using input channel: 0
-- INFO [2566.430 stream] -- Using resolution: 1920x1080
-- INFO [2566.430 stream] -- Using format: YUYV
-- INFO [2566.447 stream] -- Using HW FPS: 0 -> 60 (coerced)
-- INFO [2566.447 stream] -- Using IO method: MMAP
-- INFO [2566.466 stream] -- Requested 5 device buffers, got 5
-- INFO [2566.475 stream] -- Capturing started
-- INFO [2566.475 stream] -- Using JPEG quality: 80%
-- INFO [2566.475 stream] -- Creating pool JPEG with 4 workers ...
-- INFO [2566.476 stream] -- Capturing ...
-- INFO [2568.194 http] -- HTTP: NEW client (now=1): [192.168.0.133]:33556, id=43701ad37e3f7a7d
The H264 error stood out to me:
-- ERROR [2566.304 main] -- H264-sink: Can't open shared memory: Permission denied
So tried running ustreamer with the ustreamer user without the h264 sink options (/opt/ustreamer/ustreamer --port 48001 --persistent --encoder cpu --format yuyv --resolution 1920x1080) and streaming worked?
Perhaps this H.264 issue is causing the timeout when trying to stop ustreamer?
@mtlynch - Do you have any ideas / suggestions here? Is this something I should continue looking into?
@db39 - Sorry, I'm having trouble following the current state.
Can you summarize what our current hypothesis is, what's pointing us to the hypothesis, and what next steps would be for investigating further?
@mtlynch - Sure!
My current hypothesis is that there's an issue with ustreamer's H.264 functionality when trying to use the yuyv format, causing ustreamer to hang (and the ustreamer service to timeout when stopping it).
I tried running the following ustreamer command as different users to see if that had an impact on the behavior I was seeing:
/opt/ustreamer/ustreamer \
--port 48001 \
--persistent \
--h264-sink tinypilot::ustreamer::h264 \
--h264-sink-mode 777 \
--h264-sink-rm \
--encoder cpu \
--format yuyv \
--resolution 1920x1080
Interestingly, running the command as the ustreamer user resulted in a No Signal. However, running the same command as the default user (pilot in my case) worked.
The difference is that there's a permission error for the H264 sink when running as the default user:
-- ERROR [2566.304 main] -- H264-sink: Can't open shared memory: Permission denied
So I tried running the same command again as the ustreamer user without the H264 options:
/opt/ustreamer/ustreamer \
--port 48001 \
--persistent \
--encoder cpu \
--format yuyv \
--resolution 1920x1080
And streaming worked.
For next steps, I'm not too sure, but I would start by looking into ustreamer's H.264 functionality to see if there are any obvious problems with the yuyv format / implementation.
Thanks! The summary is helpful.
It's surprising that it works under pilot but not under ustreamer but I guess pilot does have sudoer permissions, so maybe it's somehow elevating permissions somewhere.
Also, to clarify, this behavior you described is specifically with the MS2130 and not with the standard TinyPilot HDMI to CSI bridge, right?
If that's the case, we should shelve this issue, since it's not worth digging so deeply since it's not a critical bug and it doesn't affect our supported scenarios.
It's surprising that it works under
pilotbut not underustreamerbut I guess pilot does have sudoer permissions, so maybe it's somehow elevating permissions somewhere.
My understanding is that ustreamer works with the pilot user in this instance because it doesn't have the permissions to use the H.264 sink. So ustreamer just doesn't use H.264 (avoiding the issue).
Also, to clarify, this behavior you described is specifically with the MS2130 and not with the standard TinyPilot HDMI to CSI bridge, right?
Correct. I quickly tested this with TinyPilot Pro 2.6.2 and the CSI bridge (to double check), and this isn't an issue. It's worth noting that the CSI bridge uses the uyvu format, not yuyv. So when you try to request yuyv it falls back to uyvu:
-- ERROR [217.917 stream] -- Could not obtain the requested format=YUYV; driver gave us UYVY
-- INFO [217.917 stream] -- Falling back to format=UYVY
-- INFO [217.917 stream] -- Using format: UYVY