CESNET / UltraGrid

UltraGrid low-latency audio and video network transmission system
http://www.ultragrid.cz
Other
492 stars 53 forks source link

Receiver: 1 frame dropped every 30 seconds #242

Open alatteri opened 2 years ago

alatteri commented 2 years ago

This is what happens if you use Drop-Frame timecode, but we are not. This has been happening for as long as I've used UG, but this is the first time I am reporting it.

Input- 23.976 SDI, non-drop frame timecode. Resolution doesn't matter, I've tested HD, 2K DCI, and UHD.

encoder- ./UltraGrid-continuous-x86_64.AppImage -c libavcodec:encoder=hevc_nvenc -t decklink:codec=R10k 10.55.118.59 (the encoder settings don't really matter as it happens no matter the encoder codec)

Receiver- ./UltraGrid-continuous-x86_64.AppImage -d sdl:fs -r alsa:pulse --param audio-buffer-len=1000 --audio-channel-map 6:0,7:1 --audio-scale none --param force-lavd-decoder=hevc_cuvid

using hevc_cuvid has no bearing on this issue, happens with SW decode also.

Notice in the below log, that SDL drops 1 Frame every 30 seconds.

This isn't a huge deal, but it is noticeable during playback, that the dropped frame is truly dropped and the video skips.

[2022-08-05 10:47:44] SSRC 61ec7910: 6144/6144 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:47:45] [SDL] 120 frames in 5.00446 seconds = 23.9786 FPS
[2022-08-05 10:47:49] SSRC 61ec7910: 7040/7040 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:47:50] [SDL] 120 frames in 5.00463 seconds = 23.9778 FPS
**[2022-08-05 10:47:54] [SDL] 1 frame(s) dropped!**
[2022-08-05 10:47:54] SSRC 61ec7910: 10496/10496 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:47:55] [SDL] 119 frames in 5.00455 seconds = 23.7784 FPS
[2022-08-05 10:47:56] Video dec stats (cumulative): 1437 total / 1436 disp / 0 drop / 0 corr / 1 missing.
[2022-08-05 10:47:59] SSRC 61ec7910: 10752/10752 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:00] [SDL] 120 frames in 5.0047 seconds = 23.9775 FPS
[2022-08-05 10:48:04] SSRC 61ec7910: 9600/9600 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:05] [SDL] 120 frames in 5.00483 seconds = 23.9768 FPS
[2022-08-05 10:48:09] SSRC 61ec7910: 8192/8192 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:10] [SDL] 120 frames in 5.00476 seconds = 23.9772 FPS
[2022-08-05 10:48:14] SSRC 61ec7910: 10624/10624 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:15] [SDL] 120 frames in 5.00476 seconds = 23.9772 FPS
[2022-08-05 10:48:19] SSRC 61ec7910: 9088/9088 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:20] [SDL] 120 frames in 5.00472 seconds = 23.9774 FPS
**[2022-08-05 10:48:24] [SDL] 1 frame(s) dropped!**
[2022-08-05 10:48:24] SSRC 61ec7910: 9728/9728 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:25] [SDL] 119 frames in 5.00483 seconds = 23.7771 FPS
[2022-08-05 10:48:27] Video dec stats (cumulative): 2180 total / 2179 disp / 0 drop / 0 corr / 1 missing.
[2022-08-05 10:48:29] SSRC 61ec7910: 10368/10368 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:30] [SDL] 120 frames in 5.00497 seconds = 23.9762 FPS
[2022-08-05 10:48:34] SSRC 61ec7910: 10752/10752 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:35] [SDL] 120 frames in 5.005 seconds = 23.976 FPS
[2022-08-05 10:48:39] SSRC 61ec7910: 10240/10240 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:40] [SDL] 120 frames in 5.00486 seconds = 23.9767 FPS
[2022-08-05 10:48:44] SSRC 61ec7910: 10624/10624 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:45] [SDL] 120 frames in 5.00493 seconds = 23.9763 FPS
[2022-08-05 10:48:49] SSRC 61ec7910: 9728/9728 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:50] [SDL] 120 frames in 5.00489 seconds = 23.9766 FPS
**[2022-08-05 10:48:54] [SDL] 1 frame(s) dropped!**
[2022-08-05 10:48:54] SSRC 61ec7910: 9984/9984 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:48:55] [SDL] 119 frames in 5.00498 seconds = 23.7763 FPS
[2022-08-05 10:48:58] Video dec stats (cumulative): 2923 total / 2922 disp / 0 drop / 0 corr / 1 missing.
[2022-08-05 10:48:59] SSRC 61ec7910: 9728/9728 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:00] [SDL] 120 frames in 5.0048 seconds = 23.977 FPS
[2022-08-05 10:49:04] SSRC 61ec7910: 10112/10112 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:05] [SDL] 120 frames in 5.00499 seconds = 23.9761 FPS
[2022-08-05 10:49:09] SSRC 61ec7910: 10496/10496 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:10] [SDL] 120 frames in 5.00485 seconds = 23.9767 FPS
[2022-08-05 10:49:15] SSRC 61ec7910: 9600/9600 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:15] [SDL] 120 frames in 5.00484 seconds = 23.9768 FPS
[2022-08-05 10:49:20] SSRC 61ec7910: 8576/8576 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:20] [SDL] 120 frames in 5.00498 seconds = 23.9761 FPS
**[2022-08-05 10:49:24] [SDL] 1 frame(s) dropped!**
[2022-08-05 10:49:25] SSRC 61ec7910: 5888/5888 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:25] [SDL] 119 frames in 5.00484 seconds = 23.777 FPS
[2022-08-05 10:49:30] SSRC 61ec7910: 8448/8448 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:30] Video dec stats (cumulative): 3666 total / 3665 disp / 0 drop / 0 corr / 1 missing.
[2022-08-05 10:49:30] [SDL] 120 frames in 5.0063 seconds = 23.9698 FPS
[2022-08-05 10:49:35] SSRC 61ec7910: 10112/10112 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:35] [SDL] 120 frames in 5.00337 seconds = 23.9838 FPS
[2022-08-05 10:49:40] SSRC 61ec7910: 10496/10496 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:40] [SDL] 120 frames in 5.00489 seconds = 23.9766 FPS
[2022-08-05 10:49:45] SSRC 61ec7910: 10240/10240 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:45] [SDL] 120 frames in 5.00496 seconds = 23.9762 FPS
[2022-08-05 10:49:50] SSRC 61ec7910: 8448/8448 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:50] [SDL] 120 frames in 5.00485 seconds = 23.9767 FPS
**[2022-08-05 10:49:54] [SDL] 1 frame(s) dropped!**
[2022-08-05 10:49:55] SSRC 61ec7910: 8320/8320 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:49:55] [SDL] 119 frames in 5.00486 seconds = 23.7769 FPS
[2022-08-05 10:50:00] SSRC 61ec7910: 9216/9216 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:50:00] [SDL] 120 frames in 5.00486 seconds = 23.9767 FPS
[2022-08-05 10:50:01] Video dec stats (cumulative): 4409 total / 4408 disp / 0 drop / 0 corr / 1 missing.
[2022-08-05 10:50:05] SSRC 61ec7910: 10752/10752 packets received (100%), 0 lost, max loss 0.
[2022-08-05 10:50:05] [SDL] 120 frames in 5.00545 seconds = 23.9738 FPS
MartinPulec commented 2 years ago

I assume that the display is also set to 23.976 mode, right?

Would it help if you add --param decoder-drop-policy=blocking? If not, I may add a option to increase display buffer size.

alatteri commented 2 years ago

Correct, I set the display rate to 23.98 with xrandr prior to UG launch. I will try that param.

alatteri commented 1 year ago

Finally got a chance to test --param decoder-drop-policy=blocking, problem still exists. This behavior of dropping 1 frame every 30 seconds is the literal definition of "drop frame timecode"

/usr/bin/uv -d sdl fs -r alsa:pulse --param audio-buffer-len=1000 --audio-channel-map 6:0,7:1 --audio-scale none --param force-lavd-decoder=hevc_cuvid,decoder-drop-policy=blocking -V

[2022-09-10 15:08:54] [1662847734.457] [SDL] 119 frames in 5.00502 seconds = 23.7761 FPS
[2022-09-10 15:08:56] [1662847736.168] Video dec stats (cumulative): 1456 total / 1436 disp / 0 drop / 5 corr / 20 missing.
[2022-09-10 15:08:59] [1662847739.336] SSRC 0x20cf56a6: 17792/17792 packets received (100.0000%), 0 lost, max loss 0
[2022-09-10 15:08:59] [1662847739.462] [SDL] 120 frames in 5.00456 seconds = 23.9781 FPS
[2022-09-10 15:09:04] [1662847744.321] SSRC 0x20cf56a6: 17280/17280 packets received (100.0000%), 0 lost, max loss 0
[2022-09-10 15:09:04] [1662847744.466] [SDL] 120 frames in 5.00464 seconds = 23.9777 FPS
[2022-09-10 15:09:09] [1662847749.326] SSRC 0x20cf56a6: 16512/16512 packets received (100.0000%), 0 lost, max loss 0
[2022-09-10 15:09:09] [1662847749.470] [SDL] 120 frames in 5.00427 seconds = 23.9795 FPS
[2022-09-10 15:09:14] [1662847754.335] SSRC 0x20cf56a6: 12672/12672 packets received (100.0000%), 0 lost, max loss 0
[2022-09-10 15:09:14] [1662847754.475] [SDL] 120 frames in 5.00451 seconds = 23.9784 FPS
[2022-09-10 15:09:19] [1662847759.336] SSRC 0x20cf56a6: 18048/18048 packets received (100.0000%), 0 lost, max loss 0
[2022-09-10 15:09:19] [1662847759.480] [SDL] 120 frames in 5.00476 seconds = 23.9772 FPS
[2022-09-10 15:09:24] [1662847764.350] SSRC 0x20cf56a6: 10368/10368 packets received (100.0000%), 0 lost, max loss 0
[2022-09-10 15:09:24] [1662847764.484] [SDL] 119 frames in 5.00474 seconds = 23.7775 FPS
[2022-09-10 15:09:27] [1662847767.196] Video dec stats (cumulative): 2199 total / 2179 disp / 0 drop / 6 corr / 20 missing.

timecode.pdf

mpiatka commented 1 year ago

Occasionally dropping or doubling a frame when the display refresh rate is set to the frame rate is expected. This is because the clock that drives the display refresh is not synchronized with the video content in any way, which means that the display runs a bit faster, or in this particular case, a bit slower than the incoming content. If video frames are arriving faster than the display is able to display them, you either have to drop one occasionally or introduce an continually growing delay.

Without some sort of adaptive refresh sync technology like FreeSync or G-Sync there is not much that can be done about this. If dropping a whole frame is unacceptable for you, then your best bet is to set the display to the highest available refresh rate (and live with the jitter introduced by the rate mismatch)

MartinPulec commented 1 year ago

I believe that @mpiatka is right. From the output it looks like the source is actually faster than 24/1.001 FPS relatively to the receiver. (Because it is in receiver scale, it may be also the thing that receiver clock runs slower and sender is ok compared to, let's say, atomic clock.)

Most of the 5-sec display summaries (excluding the first ones after "frame drop" because those contain the drop) are > ~23.976. For the exact evaluation I think you can use timestamped output as you did and leave UltrGrid running for a long period and then compute the difference of time and total number of frames. Anyways, a new version of UltraGrid is needed for that, I've just noticed that from some time point, dropped frames were not counted (fixed by 0bb204fdc).

alatteri commented 1 year ago

Hi Martin,

The input to UG is 23.976 2K SDI. All machine are using NTP default Ubuntu configuration for time sync and even in the above test, within the same LAN. I've set the display, using xrandr --mode --rate "23.98"

Are there any further tests you would like me to do? One thing, I haven't yet tried is setting monitor to --rate 24. Even though it is counter intuitive, it might work.

mpiatka commented 1 year ago

I'd like to clarify that by the term "clock" here we don't mean the time-of-day clock, but rather the crystal oscillator which controls how the gpu generates the image carrying signal for the monitor. These oscillators are not affected by NTP in any way. When using vsync, it is only possible to change the displayed image during the "vertical blanking interval", which happens regularly at approximately the configured rate.

The rate is only approximate and not exact, because subtle manufacturing differences and even environmental factors like temperature make the crystal oscillators oscillate slightly slower or faster than intended. This slight difference adds up over time and eventually results in a frame drop or duplication. This is basically the same reason why you can never perfectly sync your car turn indicator to the car in front of you when waiting at an intersection.

Fiddling with the refresh rate might make the source/display mismatch a bit smaller and make the dropouts or frame doublings less frequent, but it will never eliminate the problem completely.

MartinPulec commented 1 year ago

Returning to this issue to see if there is anything that can be done. What I'd been asking for is actually the output of this command:

uv -d sdl -V 2>&1 | grep '\[SDL\] Reconfigure\|Video dec stats'

(from a run lasting at least several minutes, better at least tens of minutes or a hour)

Also just from your output snippet with decoder-drop-policy=blocking there is actually no drop and it is a 35 seconds window (compared to the 30). Anyways, even if it seem to fix the problem, the question is its root:

  1. it can be just a jitter, in which case it would fix the issue (and systematically we could increase the buffer size in SDL)
  2. a clock drift - this could have been detected from the command above - in this case there is no easy solution in my opinion. The blocking behavior will work, but the latency would continually increase, which may be undesirable. Even if the latency won't matter, it will buffer some 0.5 GB an hour for FHD

Added note (2023-06-03): the above is relevant only if it is still issue for you, if not, feel free to close.

alatteri commented 1 year ago

I'll look into this in the next week or so.

MartinPulec commented 1 year ago

No problem, no rush here, whenever you have time. I've just noticed that this has became abandoned (at least from our side) so just to keep it going a bit (or dismiss).