omxplayer can't catch up properly with an already long running RTSP stream

[StCyr]

I don't know yet if the bug is in omxplayer or not, but I thought I had enough info to be worth reporting.

I have a VLC streaming server streaming over RTSP:

/usr/bin/vlc -I dummy --quiet screen:// :screen-fps=25 --input-slave=pulse://alsa_output.pci-0000_00_03.0.hdmi-stereo.monitor --sout '#transcode{vcodec=h264,venc=x264{profile=baseline,level=3,preset=ultrafast,tune=zerolatency},vfilter=canvas{width=852,height=480},acodec=aac,ab=128,channels=2,samplerate=44100}:rtp{sdp=rtsp://:9090/kodi.sdp}'

Now, if I connect with omxplayer to this server soon after VLC being started, omxplayer will play the stream just OK.

But, if I wait a few minutes before connecting with omxplayer, omxplayer will always miss either the audio or the video stream and eventualy hangs after a few minutes.

By using the --stats option, I can see the Ca or Cv buffer (depending of the missing stream) usage growing until it reaches its maximum (as per the video_queue or audio_queue setting) which is when omxplayer hangs.

Looking at the logs, I can that in such cases the DTS/PTS of the audio and video streams are totally unrelated which is what I suspect is the problem.

Does that ring a bell to someone? Is that a bug in omxplayer or a bug in my mpeg-ts stream?

Best regards,

Cyrille

===============

Example when I only get video output:

21:53:24 T:1447326299   DEBUG: Normal M:0 (A:97392442385 V:831000) P:1 A:97392.45 V:0.83/T:0.70 (0,0,1,1) A:0% V:0% (0.00,6.34)
21:53:24 T:1447326410   DEBUG: Resume 97392.45,0.83 (0,0,1,1) EOF:0 PKT:(nil)
21:53:24 T:1447326475   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
21:53:24 T:1447342620    INFO: CDVDPlayerVideo::Decode dts:870467 pts:870467 cur:870467, size:4633
21:53:24 T:1447348683    INFO: CDVDPlayerAudio::Decode dts:97392465446 pts:97392465446 size:374
21:53:24 T:1447348843   DEBUG: Normal M:0 (A:97392465446 V:870467) P:0 A:97392.47 V:0.87/T:0.70 (0,0,1,1) A:0% V:0% (0.00,6.34)
21:53:24 T:1447348956   DEBUG: OMXClock::OMXSetSpeed(1.01) pause_resume:0

Example when I only get audio output:

22:03:23 T:2046287795    INFO: CDVDPlayerAudio::Decode dts:5229841 pts:5229841 size:388
22:03:23 T:2046288072   DEBUG: Normal M:0 (A:5229841 V:889976211) P:0 A:5.23 V:889.98/T:0.70 (0,0,1,1) A:0% V:0% (0.00,6.34)
22:03:23 T:2046288183   DEBUG: OMXClock::OMXSetSpeed(1.01) pause_resume:0
22:03:23 T:2046288236   DEBUG: OMXClock::OMXSetSpeed(1.01) pause_resume:1
22:03:23 T:2046288523   DEBUG: Live: 5.16 (5.23) S:1.010 T:0.70
22:03:23 T:2046305761    INFO: CDVDPlayerVideo::Decode dts:890014444 pts:890014444 cur:890014444, size:58563
22:03:23 T:2046306632    INFO: CDVDPlayerVideo::Decode dts:890056633 pts:890056633 cur:890056633, size:2451
22:03:23 T:2046307256    INFO: CDVDPlayerVideo::Decode dts:890096311 pts:890096311 cur:890096311, size:3493
22:03:23 T:2046307870    INFO: CDVDPlayerVideo::Decode dts:890134956 pts:890134956 cur:890134956, size:8931
22:03:23 T:2046308355   DEBUG: Normal M:0 (A:5229841 V:890134956) P:0 A:5.23 V:890.13/T:0.70 (0,0,1,1) A:0% V:0% (0.00,6.34)
22:03:23 T:2046308492   DEBUG: OMXClock::OMXSetSpeed(1.01) pause_resume:0
22:03:23 T:2046308544   DEBUG: OMXClock::OMXSetSpeed(1.01) pause_resume:1
22:03:23 T:2046308818   DEBUG: Live: 5.16 (5.23) S:1.010 T:0.70

Example when both streams are output (ie: when I connect omxplayer quickly enough):

21:48:44 T:1167309683   DEBUG: Normal M:0 (A:-4503599627370496 V:-4503599627370496) P:1 A:0.00 V:0.00/T:0.70 (0,0,0,0) A:0% V:0% (0.00,6.34)
21:48:44 T:1167310458    INFO: CDVDPlayerVideo::Decode dts:3167050 pts:3167050 cur:3167050, size:7222
21:48:44 T:1167310772   DEBUG: OMXVideo::Decode VDec : setStartTime 3.167050
21:48:44 T:1167310956    INFO: CDVDPlayerAudio::Decode dts:3179047 pts:3179047 size:348
21:48:44 T:1167311658   DEBUG: COMXAudioCodecOMX::Decode(0x11ecc30,348) format=8(8) chan=2 samples=1024 size=8192 data=0x6c0004b0,0x6c002590,(nil),(nil),(nil),(nil),(nil),(nil)
21:48:44 T:1167311763   DEBUG: COMXAudioCodecOMX::GetData size=8192/8192 line=4096/4096 buf=0x6c004608, desired=65536
21:48:44 T:1167311824    INFO: CDVDPlayerAudio::Decode dts:3202245 pts:3202245 size:388
21:48:44 T:1167324120    INFO: CDVDPlayerAudio::Decode dts:3225850 pts:3225850 size:398
21:48:44 T:1167347282    INFO: CDVDPlayerVideo::Decode dts:3207916 pts:3207916 cur:3207916, size:6742

[StCyr]

So, it seems it is an omxplayer bug: I have tested my stream with VLC on iPad, and, it could catch up with the stream at any time seamlessly.

I'm compiling omxplayer to test latest version

[StCyr]

I've compiled omxplayer from sources and tried again: problem still occurs...

[StCyr]

So, I've made a packet capture of an RTP session with a VLC client on a mac (which works flawlessly)

Here are some information about the streams and sessions. Do you see something that could explain omxplayer's behavior?

Best regards,

Cyrille

SDP:

Internet Protocol Version 4, Src: 192.168.0.43, Dst: 192.168.0.241
Transmission Control Protocol, Src Port: websm (9090), Dst Port: 49464 (49464), Seq: 1850630936, Ack: 3562659849, Len: 722
[2 Reassembled TCP Segments (932 bytes): #9(210), #11(722)]
Real Time Streaming Protocol
    Response: RTSP/1.0 200 OK\r\n
    Server: VLC/3.0.1\r\n
    Date: Mon, 26 Mar 2018 18:12:03 GMT\r\n
    Content-type: application/sdp
    Content-Base: rtsp://192.168.0.43:9090/kodi.sdp\r\n
    Content-length: 722
    Cache-Control: no-cache\r\n
    Cseq: 3\r\n
    \r\n
    Session Description Protocol
        Session Description Protocol Version (v): 0
        Owner/Creator, Session Id (o): - 16024852505733884133 16024852505733884133 IN IP4 debian-cyr
        Session Name (s): Unnamed
        Session Information (i): N/A
        Connection Information (c): IN IP4 0.0.0.0
        Time Description, active time (t): 0 0
        Session Attribute (a): tool:vlc 3.0.1
        Session Attribute (a): recvonly
        Session Attribute (a): type:broadcast
        Session Attribute (a): charset:UTF-8
        Session Attribute (a): control:rtsp://192.168.0.43:9090/kodi.sdp
        Media Description, name and address (m): audio 0 RTP/AVP 96
        Bandwidth Information (b): AS:128
        Bandwidth Information (b): RR:0
        Media Attribute (a): rtpmap:96 mpeg4-generic/44100/2
        Media Attribute (a): fmtp:96 streamtype=5; profile-level-id=15; mode=AAC-hbr; config=121056e500; SizeLength=13; IndexLength=3; IndexDeltaLength=3; Profile=1;
        Media Attribute (a): control:rtsp://192.168.0.43:9090/kodi.sdp/trackID=0
        Media Description, name and address (m): video 0 RTP/AVP 96
        Bandwidth Information (b): RR:0
        Media Attribute (a): rtpmap:96 H264/90000
        Media Attribute (a): fmtp:96 packetization-mode=1;profile-level-id=42c01e;sprop-parameter-sets=Z0LAHtoBQBbsBEAAAAMAQAAADKPFi6g=,aM4PyA==;
        Media Attribute (a): control:rtsp://192.168.0.43:9090/kodi.sdp/trackID=2

RTSP SETUP REPLIES:

Internet Protocol Version 4, Src: 192.168.0.43, Dst: 192.168.0.241
Transmission Control Protocol, Src Port: websm (9090), Dst Port: 49464 (49464), Seq: 1850631658, Ack: 3562660036, Len: 291
Real Time Streaming Protocol
    Response: RTSP/1.0 200 OK\r\n
    Server: VLC/3.0.1\r\n
    Date: Mon, 26 Mar 2018 18:12:03 GMT\r\n
    Transport: RTP/AVP/UDP;unicast;source=192.168.0.207;client_port=57264-57265;server_port=58093-58094;ssrc=C1386A05;mode=play
    Session: 1d3bb0a3a8f3cfb6;timeout=60
    Content-length: 0
    Cache-Control: no-cache\r\n
    Cseq: 4\r\n
    \r\n

Internet Protocol Version 4, Src: 192.168.0.43, Dst: 192.168.0.241
Transmission Control Protocol, Src Port: websm (9090), Dst Port: 49464 (49464), Seq: 1850631949, Ack: 3562660250, Len: 291
Real Time Streaming Protocol
    Response: RTSP/1.0 200 OK\r\n
    Server: VLC/3.0.1\r\n
    Date: Mon, 26 Mar 2018 18:12:03 GMT\r\n
    Transport: RTP/AVP/UDP;unicast;source=192.168.0.207;client_port=58316-58317;server_port=47542-47543;ssrc=3ED785E9;mode=play
    Session: 1d3bb0a3a8f3cfb6;timeout=60
    Content-length: 0
    Cache-Control: no-cache\r\n
    Cseq: 5\r\n
    \r\n

First RTP payloads:

Internet Protocol Version 4, Src: 192.168.0.207, Dst: 192.168.0.241
User Datagram Protocol, Src Port: 47542 (47542), Dst Port: 58316 (58316)
Real-Time Transport Protocol
    [Stream setup by RTSP (frame 17)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: DynamicRTP-Type-96 (96)
    Sequence number: 43048
    [Extended sequence number: 43048]
    Timestamp: 514606763
    Synchronization Source identifier: 0x3ed785e9 (1054311913)
    Payload: 419ae05a02cf11aaa9c36b95278cb4c0eaa6a3b94756790f...

Internet Protocol Version 4, Src: 192.168.0.207, Dst: 192.168.0.241
User Datagram Protocol, Src Port: 58093 (58093), Dst Port: 57264 (57264)
Real-Time Transport Protocol
    [Stream setup by RTSP (frame 14)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    1... .... = Marker: True
    Payload type: DynamicRTP-Type-96 (96)
    Sequence number: 28491
    [Extended sequence number: 94027]
    Timestamp: 252157330
    Synchronization Source identifier: 0xc1386a05 (3241699845)
    Payload: 00100cb8211b0ecfffffffffce5b1c684b34159663638fe7...

First Sender reports

Internet Protocol Version 4, Src: 192.168.0.207, Dst: 192.168.0.241
User Datagram Protocol, Src Port: 58094 (58094), Dst Port: 57265 (57265)
Real-time Transport Control Protocol (Sender Report)
    [Stream setup by RTSP (frame 14)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 0000 = Reception report count: 0
    Packet type: Sender Report (200)
    Length: 6 (28 bytes)
    Sender SSRC: 0xc1386a05 (3241699845)
    Timestamp, MSW: 3731076728 (0xde63b678)
    Timestamp, LSW: 57365060 (0x036b5244)
    [MSW and LSW as NTP timestamp: Mar 26, 2018 18:12:08.013356343 UTC]
    RTP timestamp: 252356122
    Sender's packet count: 195
    Sender's octet count: 76384
Real-time Transport Control Protocol (Source description)
    [Stream setup by RTSP (frame 14)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 0001 = Source count: 1
    Packet type: Source description (202)
    Length: 8 (36 bytes)
    Chunk 1, SSRC/CSRC 0xC1386A05
[RTCP frame length check: OK - 64 bytes]

Internet Protocol Version 4, Src: 192.168.0.207, Dst: 192.168.0.241
User Datagram Protocol, Src Port: 47543 (47543), Dst Port: 58317 (58317)
Real-time Transport Control Protocol (Sender Report)
    [Stream setup by RTSP (frame 17)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 0000 = Reception report count: 0
    Packet type: Sender Report (200)
    Length: 6 (28 bytes)
    Sender SSRC: 0x3ed785e9 (1054311913)
    Timestamp, MSW: 3731076728 (0xde63b678)
    Timestamp, LSW: 121227857 (0x0739ca51)
    [MSW and LSW as NTP timestamp: Mar 26, 2018 18:12:08.028225559 UTC]
    RTP timestamp: 515013835
    Sender's packet count: 809
    Sender's octet count: 814537
Real-time Transport Control Protocol (Source description)
    [Stream setup by RTSP (frame 17)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 0001 = Source count: 1
    Packet type: Source description (202)
    Length: 8 (36 bytes)
    Chunk 1, SSRC/CSRC 0x3ED785E9
[RTCP frame length check: OK - 64 bytes]

[StCyr]

Hi,

I've captured omxplayer's log and RTSP packets for both a properly working and a non-working playback (in this case, only audio was working).

Can you figure out what's going wrong (RTSP service is on port 9090)?

Best regards

omxplayer_bad.log
omxplayer_ok.log
omxplayer_bad.pcap.zip
omxplayer_ok.pcap.zip

[StCyr]

Hello,

For information, yesterday I made some tests and it seems that lowering (on the encoding size) x264's keyint parameter from (its default of) 250 to 50 solves the issue.

I must still validate this solution in the long term, but, yesterday I could restart omxplayer something like 10 times and every time it played both stream properly (while with the default keyint value of 250, omxplayer had something like 30% of success playing both streams succesfully (that's: I needed to restart omxplayer about 3 times in order to be sure omxplayer decodes both streams successfully))

Could it be that ffmpeg's default probesize prevented it to properly detect the streams info (via avformat_find_stream_info?) when a key frame only occurs every 10 seconds?

BR

[StCyr]

Hello,

I just want to say that the keyint parameter is not the solution: omxplayer has still troubles to play both streams.

BR

[StCyr]

I'm still having the problem. Anyone could help me troubleshoot? Do you think the weird DTS/PTS behaviour is a good trail?

A working workaround at the moment, is to make sure omxplayer is started before the screencasting