search

popcornmix / omxplayer

omxplayer
GNU General Public License v2.0
1.02k stars 333 forks source link

DTS/PTS jump backwards breaks live stream playback #260

Open fabled opened 10 years ago

fabled commented 10 years ago

I'm using 'omxplayer --live http://url/to/stream' to play a live MPEG TS stream (H264/AAC).

It is a long live stream (24/7h) and at first everything is ok. But after a day or two, the stream lag seems to have increased by one or two seconds and it becomes "jerky" or "dropping frames".

My suspicion is that there is clock drift and omxplayer's live stream buffers are filling up slowly (causing delay increase). After the socket buffers are full, the server starts to drop packets (causing the 'jumpiness').

Would it be possible for '--live' to also make sure the input stream buffers are kept minimum. And e.g. drop frames if necessary. Even better if the playback could be speed up "to catch up" frames if falling behind from the live stream.

fabled commented 10 years ago

Seems my initial hypothesis is incorrect. There's code to adapt playback rate to that of the live streams, and it seems to be doing good job. Also netstat shows there's no excess data in the buffers. I'm now trying to reproduce with logging enabled if it adds any insight.

fabled commented 10 years ago

Find attached the log of the moment when things start going wrong. Notice jump backwards in dts/pts. This apparently causes temporary glitch in latency calculation. As latency goes negative, the speed adjustment for live streams thinks it needs to slow down, and it is left in that state.

13:14:00 T:18446744073302391793    INFO: CDVDPlayerAudio::Decode dts:95383700400 pts:95383700400 size:684
13:14:00 T:18446744073302397780    INFO: CDVDPlayerVideo::Decode dts:95383681278 pts:95383681278 cur:95383681278, size:2851
13:14:00 T:18446744073302399754   DEBUG: Normal M:95383018183 (A:95383700400 V:95383681278) P:0 A:0.68 V:0.66/T:0.70 (0,0,0,0) A:0% V:0% (0.40,6.07)
13:14:00 T:18446744073302400136   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:0
13:14:00 T:18446744073302400321   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
13:14:00 T:18446744073302404405    INFO: CDVDPlayerAudio::Decode dts:95383721733 pts:95383721733 size:684
13:14:00 T:18446744073302407916   DEBUG: Keyboard: Process() m_bStop 0
13:14:00 T:18446744073302408849   DEBUG: Live: 0.63 (0.68) S:0.999 T:0.70
13:14:00 T:18446744073302420516    INFO: CDVDPlayerVideo::Decode dts:95383721278 pts:95383721278 cur:95383721278, size:99609
13:14:00 T:18446744073302421937    INFO: CDVDPlayerAudio::Decode dts:47288255289 pts:47288255289 size:680
13:14:00 T:18446744073302428518   DEBUG: Keyboard: Process() m_bStop 0
13:14:00 T:18446744073302429412   DEBUG: Normal M:95383047793 (A:47288255289 V:95383721278) P:0 A:-48094.79 V:0.67/T:0.70 (1,0,0,0) A:0% V:0% (0.37,6.07)
13:14:00 T:18446744073302429758   DEBUG: OMXClock::OMXSetSpeed(0.99) pause_resume:0
13:14:00 T:18446744073302429949   DEBUG: OMXClock::OMXSetSpeed(0.99) pause_resume:1
13:14:00 T:18446744073302431151   DEBUG: Live: -480.32 (-48094.79) S:0.990 T:0.70
13:14:00 T:18446744073302432681    INFO: CDVDPlayerVideo::Decode dts:47288273500 pts:47288273500 cur:47288273500, size:3064
13:14:00 T:18446744073302434934    INFO: CDVDPlayerVideo::Decode dts:47288313500 pts:47288313500 cur:47288313500, size:2901
13:14:00 T:18446744073302439701    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1.00 * 1.00)
13:14:00 T:18446744073302440043    INFO: CDVDPlayerAudio::Decode dts:47288276622 pts:47288276622 size:684
13:14:00 T:18446744073302445113    INFO: CDVDPlayerAudio::Decode dts:47288297956 pts:47288297956 size:684
13:14:00 T:18446744073302448973   DEBUG: Keyboard: Process() m_bStop 0
13:14:00 T:18446744073302450434    INFO: CDVDPlayerAudio::Decode dts:47288319289 pts:47288319289 size:680
13:14:00 T:18446744073302455340    INFO: CDVDPlayerAudio::Decode dts:47288340622 pts:47288340622 size:684
13:14:00 T:18446744073302460598    INFO: CDVDPlayerAudio::Decode dts:47288361956 pts:47288361956 size:684
13:14:00 T:18446744073302469375   DEBUG: Keyboard: Process() m_bStop 0
13:14:00 T:18446744073302615358   DEBUG: Previous line repeats 7 times.
13:14:00 T:18446744073302615358   DEBUG: Normal M:95383231850 (A:47288361956 V:47288313500) P:0 A:-48094.87 V:-48094.92/T:0.70 (1,1,0,0) A:0% V:0% (0.36,6.07)
13:14:00 T:18446744073302615810   DEBUG: OMXClock::OMXSetSpeed(0.99) pause_resume:0
13:14:00 T:18446744073302616000   DEBUG: OMXClock::OMXSetSpeed(0.99) pause_resume:1
13:14:00 T:18446744073302616448    INFO: CDVDPlayerAudio::Decode dts:47288383289 pts:47288383289 size:680
13:14:00 T:18446744073302618312   DEBUG: Live: -956.47 (-48094.87) S:0.990 T:0.70
13:14:00 T:18446744073302619375    INFO: CDVDPlayerVideo::Decode dts:47288353500 pts:47288353500 cur:47288353500, size:3200
13:14:00 T:18446744073302621161    INFO: CDVDPlayerVideo::Decode dts:47288393500 pts:47288393500 cur:47288393500, size:3145
13:14:00 T:18446744073302624324    INFO: CDVDPlayerVideo::Decode dts:47288433500 pts:47288433500 cur:47288433500, size:3196
13:14:00 T:18446744073302629531    INFO: CDVDPlayerAudio::Decode dts:47288404622 pts:47288404622 size:684
13:14:00 T:18446744073302631431   DEBUG: Keyboard: Process() m_bStop 0
13:14:00 T:18446744073302632665    INFO: CDVDPlayerVideo::Decode dts:47288473500 pts:47288473500 cur:47288473500, size:3086
13:14:00 T:18446744073302634777    INFO: CDVDPlayerVideo::Decode dts:47288513500 pts:47288513500 cur:47288513500, size:3123
13:14:00 T:18446744073302636351   DEBUG: Normal M:95383252686 (A:47288404622 V:47288513500) P:0 A:-48094.85 V:-48094.74/T:0.70 (1,1,0,0) A:0% V:0% (0.34,6.07)
13:14:00 T:18446744073302636747   DEBUG: OMXClock::OMXSetSpeed(0.99) pause_resume:0
13:14:00 T:18446744073302636962   DEBUG: OMXClock::OMXSetSpeed(0.99) pause_resume:1
13:14:00 T:18446744073302637629   DEBUG: Live: -1427.85 (-48094.85) S:0.990 T:0.70
popcornmix commented 10 years ago

Could you capture (or manufacture) a stream that provokes this behaviour? XBMC passes all timestamps through a "correction" phase. See https://github.com/xbmc/xbmc/pull/5248 We could possibly do something similar in omxplayer, but it's pretty ugly.

Ideally streams should have valid, monotonic timestamps...

fabled commented 10 years ago

Yes. This is a stream captured from ATEM TV Studio (with Fujitsu MB86H56 hardware encoder chip). The stream is dumped with https://github.com/fabled/bmd-tools and sent to vlc through named piped. VLC has sout gather:std{http}output which is read by omxplayer. I'm not sure if the discontinuity is from VLC or the hardware - I assume it's from the hardware. It'll take 24+ hours to reproduce.

As simple fix, I think just discarding negative temporary latencies from the average is enough. I assume the problem comes from the FIR averaging around in omxplayer.cpp:1619: m_latency = m_latency*0.99f + latency*0.01f;

Just having single (huge) sample of negative 'latency' modifies the m_latency permanently to be negative causing incorrect speed selection to stay a day or so until the next dts jump happens.

popcornmix commented 10 years ago

Can you rebuild omxplayer and check if that works? I guess if latency is wildly different (e.g. negative) to m_latency then you can skip updating the filtered version, but I'm not sure if that is the only issue.

fabled commented 10 years ago

I tried this:

diff --git a/omxplayer.cpp b/omxplayer.cpp
index 0e64aae..8b99af4 100644
--- a/omxplayer.cpp
+++ b/omxplayer.cpp
@@ -1543,6 +1543,9 @@ int main(int argc, char *argv[])
         }
       }

+      if (audio_pts < stamp) audio_pts = DVD_NOPTS_VALUE;
+      if (video_pts < stamp) video_pts = DVD_NOPTS_VALUE;
+
       float audio_fifo = audio_pts == DVD_NOPTS_VALUE ? 0.0f : audio_pts / DVD_TIME_BASE - stamp * 1e-6;
       float video_fifo = video_pts == DVD_NOPTS_VALUE ? 0.0f : video_pts / DVD_TIME_BASE - stamp * 1e-6;
       float threshold = std::min(0.1f, (float)m_player_audio.GetCacheTotal() * 0.1f);

It made the immediate problem go away, but is not working as expected either. It seem after the change latency check goes permanently off. Apparently stamp is monotonically increasing regadless of pts jump.

Log captured with the patch applied when the pts jump happens:

10:04:56 T:2134853803   DEBUG: Normal M:95383055941 (A:95383696489 V:95383654233) P:0 A:0.64 V:0.60/T:0.70 (0,0,0,0) A:0% V:0% (0.34
,6.07)
10:04:56 T:2134854163   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:0
10:04:56 T:2134854328   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
10:04:56 T:2134855191   DEBUG: Live: 0.64 (0.64) S:1.000 T:0.70
10:04:56 T:2134855739    INFO: CDVDPlayerAudio::Decode dts:95383717822 pts:95383717822 size:684
10:04:56 T:2134860043    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1.00 * 1.00)
10:04:56 T:2134860416    INFO: CDVDPlayerAudio::Decode dts:17851777033 pts:17851777033 size:680
10:04:56 T:2134862335    INFO: CDVDPlayerVideo::Decode dts:95383694233 pts:95383694233 cur:95383694233, size:2106
10:04:56 T:2134864384    INFO: CDVDPlayerVideo::Decode dts:17851772111 pts:17851772111 cur:17851772111, size:3269
10:04:56 T:2134864998    INFO: CDVDPlayerAudio::Decode dts:17851798367 pts:17851798367 size:684
10:04:56 T:2134866671    INFO: CDVDPlayerAudio::Decode dts:17851819700 pts:17851819700 size:684
10:04:56 T:2134868078   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2134869406    INFO: CDVDPlayerVideo::Decode dts:17851812411 pts:17851812411 cur:17851812411, size:4953
10:04:56 T:2134870676    INFO: CDVDPlayerAudio::Decode dts:17851841033 pts:17851841033 size:680
10:04:56 T:2134872252    INFO: CDVDPlayerAudio::Decode dts:17851862367 pts:17851862367 size:684
10:04:56 T:2134888449   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2135046918   DEBUG: Previous line repeats 7 times.
10:04:56 T:2135046918   DEBUG: Normal M:95383250381 (A:-4503599627370496 V:-4503599627370496) P:0 A:0.00 V:0.00/T:0.70 (0,0,0,0) A:0
% V:0% (0.32,6.07)
10:04:56 T:2135048820    INFO: CDVDPlayerVideo::Decode dts:17851852411 pts:17851852411 cur:17851852411, size:3880
10:04:56 T:2135050526   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2135050851    INFO: CDVDPlayerAudio::Decode dts:17851883700 pts:17851883700 size:684
10:04:56 T:2135052139    INFO: CDVDPlayerAudio::Decode dts:17851905033 pts:17851905033 size:680
10:04:56 T:2135053476    INFO: CDVDPlayerAudio::Decode dts:17851926122 pts:17851926122 size:684
10:04:56 T:2135055533    INFO: CDVDPlayerVideo::Decode dts:17851892411 pts:17851892411 cur:17851892411, size:4349
10:04:56 T:2135059665    INFO: CDVDPlayerVideo::Decode dts:17851932411 pts:17851932411 cur:17851932411, size:1945
10:04:56 T:2135060703    INFO: CDVDPlayerVideo::Decode dts:17851972411 pts:17851972411 cur:17851972411, size:5098
10:04:56 T:2135063156    INFO: CDVDPlayerVideo::Decode dts:17852012411 pts:17852012411 cur:17852012411, size:3636
10:04:56 T:2135064701    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1.00 * 1.00)
10:04:56 T:2135064996    INFO: CDVDPlayerAudio::Decode dts:17851947456 pts:17851947456 size:684
10:04:56 T:2135066197    INFO: CDVDPlayerAudio::Decode dts:17851968789 pts:17851968789 size:680
10:04:56 T:2135067429    INFO: CDVDPlayerAudio::Decode dts:17851990122 pts:17851990122 size:684
10:04:56 T:2135068695    INFO: CDVDPlayerAudio::Decode dts:17852011456 pts:17852011456 size:684
10:04:56 T:2135070034    INFO: CDVDPlayerAudio::Decode dts:17852032789 pts:17852032789 size:680
10:04:56 T:2135071026   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2135071819    INFO: CDVDPlayerAudio::Decode dts:17852054122 pts:17852054122 size:684
10:04:56 T:2135073086    INFO: CDVDPlayerAudio::Decode dts:17852075456 pts:17852075456 size:684
10:04:56 T:2135091420   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2135269512   DEBUG: Previous line repeats 8 times.
10:04:56 T:2135269512   DEBUG: Normal M:95383472089 (A:-4503599627370496 V:-4503599627370496) P:0 A:0.00 V:0.00/T:0.70 (0,0,0,0) A:0
% V:0% (0.10,6.07)
10:04:56 T:2135272118    INFO: CDVDPlayerVideo::Decode dts:17852052411 pts:17852052411 cur:17852052411, size:2057
10:04:56 T:2135273074    INFO: CDVDPlayerAudio::Decode dts:17852096622 pts:17852096622 size:680
10:04:56 T:2135273676   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2135274741    INFO: CDVDPlayerVideo::Decode dts:17852092411 pts:17852092411 cur:17852092411, size:2833
10:04:56 T:2135281903    INFO: COMXAudio::ApplyVolume - Volume=1.00 (* 1.00 * 1.00)
10:04:56 T:2135282215    INFO: CDVDPlayerAudio::Decode dts:17852117956 pts:17852117956 size:684
10:04:56 T:2135283379    INFO: CDVDPlayerAudio::Decode dts:17852139289 pts:17852139289 size:684
10:04:56 T:2135286000    INFO: CDVDPlayerAudio::Decode dts:17852160622 pts:17852160622 size:680
10:04:56 T:2135292790    INFO: CDVDPlayerVideo::Decode dts:17852131456 pts:17852131456 cur:17852131456, size:2810
10:04:56 T:2135294151   DEBUG: Keyboard: Process() m_bStop 0
10:04:56 T:2135294763   DEBUG: Normal M:95383498597 (A:-4503599627370496 V:-4503599627370496) P:0 A:0.00 V:0.00/T:0.70 (0,0,0,0) A:0
% V:0% (0.07,6.07)

As additional note, it seems the jump happens with about same dts value but to a lot lower value than during earlier log.

It also is weird, that everytime I launch omxplayer the dts starts with same value. Is omxplayer or the ffmpeg library somehow rebasing it? Or does this indicate that the vlc server is rewriting it for each client connection?

Any suggestions how to make omxplayer handle this kind of streams?

mcaptur commented 10 years ago

I seem to have a very similar issue.. I can replicate it at will by effecting tuner reception http://forum.kodi.tv/showthread.php?tid=192380&pid=1805635#pid1805635

If you need extra samples or need me to test something just let me know..