search

tiny-pilot / tinypilot

Use your Raspberry Pi as a browser-based KVM.
https://tinypilotkvm.com
MIT License
2.95k stars 246 forks source link

uStreamer service restarts are taking 90-120s #1660

Open mtlynch opened 9 months ago

mtlynch commented 9 months ago

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.

mtlynch commented 8 months ago

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.

db39 commented 8 months ago

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.

db39 commented 8 months ago

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?

mtlynch commented 8 months ago

@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?

db39 commented 8 months ago

@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.

mtlynch commented 8 months ago

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.

db39 commented 8 months ago

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.

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
mtlynch commented 8 months ago

Okay, thanks! Let's deprioritize this for now.