Error: No room to store incoming packet

msanis commented 6 years ago

Hello

We are experiencing "No room to store incoming packet" error on certain conditions. The source multicast is from a professional encoder (Tandberg)

Condition 1: When TS bit rate of source is up to 16Mbps, then SRT works perfect

Condition 2: When we increase the TS bit rate higher (eg. 17 Mbps), then we see the below error message RX side: Accepted SRT source connection 18:11:36.374843/SRT:RcvQ:workerE: SRT.c: %1005060842:No room to store incoming packet: offset=0 avail=0 ack.seq=489148889 pkt.seq=489148889 rcv-remain=8191 18:11:36.375572/SRT:RcvQ:workerE: SRT.c: %1005060842:No room to store incoming packet: offset=1 avail=0 ack.seq=489148889 pkt.seq=489148890 rcv-remain=8191

TX side: 155288 bytes lost, 21560028 bytes sent, 31287900 bytes received 15353772 bytes lost, 21560028 bytes sent, 46486384 bytes received 31324748 bytes lost, 21560028 bytes sent, 62457360 bytes received 47340468 bytes lost, 21560028 bytes sent, 78473080 bytes received 63335132 bytes lost, 21560028 bytes sent, 94467744 bytes received

Condition 3: We start SRT streaming initially with 16Mbps and when it is fully functioning, we increase the source TS bit rate from the encoder settings on the fly to 25Mbps. Still SRT continues to function without any errors and at the RX side we see 25Mbps on output multicast.

It seems SRT is currently handling traffic only upto 16Mbps. Any suggestions ?

Our commands: TX: stransmit "udp://@226.24.112.4:2000?ttl=64" "srt://1.2.3.4:7005?mode=caller&latency=5000" -t:-1 -s:3000

RX: stransmit "srt://:7005?mode=listener" "udp://@225.10.10.10:2000?ttl=64" -t:-1 -s:3000 -v

ethouris commented 6 years ago

The "No room to store incoming packet" message appears when the RX buffer gets completely full and is waiting for the receiving application to extract the waiting packets. This rcv-remain data shows how many buffers (each one containing data transmitted by a single UDP packet, typically 1316 bytes) are still waiting until the application extracts them.

If you are using the SRT 1.2 version stransmit, just note that this was at that time only a testing tool and choking on the output medium may prevent it from reading from SRT medium on time. Although I have never seen it happening on UDP output, only with file://con output with pipeline to another application.

I would keenly see the debug logs from this session and see how fast the data extraction on RX happens, especially at the moment when the RX buffer level increases.

Mind also that the "latency control" facility (TSBPD) is using the RX buffer to magazine the incoming packets until their "time to play" comes. I can see that you have set quite a long latency (5 seconds) and mind that effectively the RX buffer will have to magazine packets for 5 seconds of stream constantly. Might be that with high bitrates combined with high latency the RX buffer size might be too small, or at least balance on the edge. You can change the size of the receiver buffer through the rcvbuf option (mind that it will be fixed to not exceed the fc option). The default value for rcvbuf is 8192 and for fc - 25600.

rmsoto commented 6 years ago

Hello Ethouris,

I´m also having a similar issue trying to send an hevc 60mbs TS, I can only get 42,5 at output of SRT whily trying the same with a 25TS its fine... where you can change the parameters you said above?

something like this?

./srt-live-transmit -v -r:30 -s:30 -t:0 "udp://@224.168.204.41:2041" "srt://:9001?latency=500&sndbuf=8192&fc=25600"

./srt-live-transmit -v -r:30 -s:30 -t:0 "srt://127.0.0.1:9001?latency=500&rcvbuf=8192&fc=25600" "udp://@224.168.204.250:2250"

Thanks

jeandube commented 6 years ago

@rmsoto you may want to set the max output bw that is capped at 30Mbps by default (this option is not working well and that could explain the 42.5 you get). The option "maxbw" is in bytes/sec.

jeandube commented 6 years ago

Sorry, I just read this issue again, my proposal would not fix the 'no room' on the receiver. but only ensure proper drainage of the sender's buffers.

rmsoto commented 6 years ago

Hi @jeandube , the mxbw helped to achieve the same output bitrate than the input one but I still get the error:

14:44:53.373608/SRT:RcvQ:worker*E: SRT.c: %328810773:No room to store incoming packet: offset=0 avail=0 ack.seq=2053936868 pkt.seq=2053936868 rcv-remain=8191

_increasing the parameters rcvbuf=16384&fc=51200 does not make any good result as I get less bw than expected...I think I´m not introducing the correct units...

Thanks

jeandube commented 6 years ago

@rmsoto Good if you fixed the sender but the noroom problem on the receiver is an indication that the receiving app is not draining the received packets fast enough. Increasing the received buffer just delay the problem. By fixing the sender you just exacerbated the receiver's problem.

rmsoto commented 6 years ago

I think its now working better since we changed the values of sdnbuf, rcvbuf and flight window inside core.cpp and recompile...let’s see how it works during 24h

Thanks!

haozhenxiao commented 6 years ago

@ethouris I also got the same error and I checked the number of packets dropped by the kernel is 0: RX errors 0 dropped 0 overruns 0 frame 0, as you mentioned

The "No room to store incoming packet" message appears when the RX buffer gets completely full

In this case, the kernel should start dropping packets, right? Or I misunderstood RX buffer you mentioned?

ethouris commented 6 years ago

Again: this "No room to store incoming packet" may happen in two cases:

The application works slowly and doesn't do the calls to srt_recvmsg even though when it did it would read the packet of data immediately (IOW, it's not the app waiting for the data from SRT, but it's SRT waiting for the application to pick up what is already delivered to it).
In some strict cases it may be the problem of too small reception buffer due to TSBPD. TSBPD keeps packets in the buffer until the "time to play" comes, so if you multiply the latency by the bitrate expressed as a number of 1316-byte packets, it should give you the size of the buffer used by TSBPD. By doing it in reverse you'll get the maximum time of the video that can be stored in the receiver buffer (and compare it to latency - the part taken by latency should be much less than the rest of the buffer).

Both these things happen when the packet has already passed the network link, that is, the work for transporting the packet through the network has been already successfully finished.

May happen that the application experiences some temporary slowdown, which will get evened up later; in this case increasing the size will help. But not in case when the application is systematically increasing the delay between the moment when the packet is given up to the application and the moment when the application reads it - in this case a buffer of any size will eventually be overflown.

haozhenxiao commented 6 years ago

@ethouris so RX buffer is not the linux kernel buffer, right? I increased rmem_default and rmem_max but still getting the same error.

ethouris commented 6 years ago

We are talking SRT here, the userspace solution, which uses instrumentally UDP to implement the transmission. It provides its own buffers that work according to the rules it defines. Kernel parameters have nothing to do with this.

Let me be more precise about the above: both these things happen when the packet has already passed the network link and all system buffers and is about to be stored by SRT in its private buffers.

ethouris commented 5 years ago

As you have once faced this problem that is likely to result from performance problems, would you be able to test the version from this branch?

https://github.com/ethouris/srt/tree/dev-rcvworker-sleeps

maxsharabayko commented 5 years ago

This looks like a problem with receiver buffer size. The size should be at least Buf_rcv >= bps × RTT_sec / (8 × (1500 - 28)) + (latency_sec × bps) Bear in mind #700.

Default receiver buffer size is 8192 × (1500-28) = 12058624 bytes or approximately 96 Mbits. Default flow control window size is 25600 packets or approximately 300 Mbits.

ethouris commented 5 years ago

Related to #355

maxsharabayko commented 4 years ago

Closed due to lack of activity.

boxerab commented 4 years ago

I am seeing this issue with latest obs+srt(with epoll patch)+ffmpeg:

GStreamer pipeline:

 GST_DEBUG=srt*:7  gst-launch-1.0 -v pipeline. \( latency=10000000 srtsrc uri=srt://:3000?mode=listener latency=125 ! tsdemux ! h264parse ! avdec_h264 ! videoconvert ! glimagesink \)

After obs connects, there is a 30 second delay, then the warnings start to appear about "No room"

Logs:

0:00:00.069376961 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:199:gst_srt_object_new:<GstSRTSrc@0x55d9f88d0210> Starting up SRT
0:00:00.069794817 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:596:gst_srt_object_set_uri:<GstSRTSrc@0x55d9f88d0210> set uri to (host: 127.0.0.1, port: 7001) with 0 query strings
0:00:00.069899088 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:596:gst_srt_object_set_uri:<srtsrc0> set uri to (host: (null), port: 3000) with 1 query strings
Setting pipeline to PAUSED ...
0:00:00.140174370 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:1007:gst_srt_object_open_full:<srtsrc0> Given uri doesn't have hostname or address. Use any (0.0.0.0) and setting listener mode
0:00:00.140263211 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:1036:gst_srt_object_open_full:<srtsrc0> Opening SRT socket with parameters: application/x-srt-params, poll-timeout=(int)-1, latency=(int)125, mode=(GstSRTConnectionMode)listener, localaddress=(string)0.0.0.0, localport=(uint)3000;
0:00:00.140337785 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:780:gst_srt_object_wait_connect:<srtsrc0> Binding to 0.0.0.0 (port: 3000)
0:00:00.140450723 25102 0x55d9f88c6ec0 DEBUG              srtobject gstsrtobject.c:796:gst_srt_object_wait_connect:<srtsrc0> Starting to listen on bind socket
0:00:00.140499064 25102 0x55d9f89ccad0 DEBUG              srtobject gstsrtobject.c:661:thread_func:<srtsrc0> Waiting a request from caller
Pipeline is live and does not need PREROLL ...
Got context from element 'sink': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayX11\)\ gldisplayx11-0";
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
0:00:00.140751298 25102 0x55d9f89cca80 DEBUG              srtobject gstsrtobject.c:1118:gst_srt_object_wait_caller:<srtsrc0> Waiting connection from caller
0:00:21.807540849 25102 0x55d9f89ccad0 DEBUG              srtobject gstsrtobject.c:661:thread_func:<srtsrc0> Waiting a request from caller
10:57:50 AM.506313/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=0 avail=0 ack.seq=831268985 pkt.seq=831268985 rcv-remain=8191
10:57:50 AM.506521/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=1 avail=0 ack.seq=831268985 pkt.seq=831268986 rcv-remain=8191
10:57:51 AM.518354/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=2 avail=0 ack.seq=831268985 pkt.seq=831268987 rcv-remain=8191
10:57:51 AM.518409/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=3 avail=0 ack.seq=831268985 pkt.seq=831268988 rcv-remain=8191
10:57:51 AM.539552/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=4 avail=0 ack.seq=831268985 pkt.seq=831268989 rcv-remain=8191
10:57:51 AM.539613/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=5 avail=0 ack.seq=831268985 pkt.seq=831268990 rcv-remain=8191
10:57:51 AM.555658/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=6 avail=0 ack.seq=831268985 pkt.seq=831268991 rcv-remain=8191
10:57:51 AM.588401/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=21 avail=0 ack.seq=831268985 pkt.seq=831269006 rcv-remain=8191
10:57:51 AM.588437/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=22 avail=0 ack.seq=831268985 pkt.seq=831269007 rcv-remain=8191
10:57:51 AM.635428/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=38 avail=0 ack.seq=831268985 pkt.seq=831269023 rcv-remain=8191
10:57:51 AM.635490/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=39 avail=0 ack.seq=831268985 pkt.seq=831269024 rcv-remain=8191
10:57:51 AM.655372/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=41 avail=0 ack.seq=831268985 pkt.seq=831269026 rcv-remain=8191
10:57:51 AM.655419/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=42 avail=0 ack.seq=831268985 pkt.seq=831269027 rcv-remain=8191
10:57:51 AM.672967/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=43 avail=0 ack.seq=831268985 pkt.seq=831269028 rcv-remain=8191
10:57:51 AM.705875/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=58 avail=0 ack.seq=831268985 pkt.seq=831269043 rcv-remain=8191
10:57:51 AM.705956/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=59 avail=0 ack.seq=831268985 pkt.seq=831269044 rcv-remain=8191
10:57:51 AM.722861/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=62 avail=0 ack.seq=831268985 pkt.seq=831269047 rcv-remain=8191
10:57:51 AM.722916/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=63 avail=0 ack.seq=831268985 pkt.seq=831269048 rcv-remain=8191
10:57:51 AM.739156/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=64 avail=0 ack.seq=831268985 pkt.seq=831269049 rcv-remain=8191
10:57:51 AM.773001/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=88 avail=0 ack.seq=831268985 pkt.seq=831269073 rcv-remain=8191
10:57:51 AM.773075/SRT:RcvQ:w1*E:SRT.c: @203766597:No room to store incoming packet: offset=89 avail=0 ack.seq=831268985 pkt.seq=831269074 rcv-remain=8191

maxsharabayko commented 4 years ago

@boxerab Please increase receiver buffer size based on this recommendation: link. And this one: link.

boxerab commented 4 years ago

Thanks, @maxsharabayko . I will try that. Did the library behaviour change recently? Because this used to work without setting receiver buffer size.

ethouris commented 4 years ago

This problem appears when the receiver buffer isn't flushed fast enough. This can happen due to:

application problem (reads too slowly one packet after another)
SRT internal problem (possibly packets are signed off for reading too late sometimes - theoretically possible problem, we haven't seen any notion of this so far)
unfortunate thread layout (application thread is given too little time slices to be able to read all ready packets on time)

If this happens due to a temporary large burst of packets, which will slow down later, and the application can keep the right speed with reading packets, the relative late reading time will decrease as packets are read and the receiver buffer will be purged before it blows. But it may require increasing buffer size so that the application survives this temporary problem.

AlexandreLicinio commented 4 years ago

I confirm too with gstreamer app (from apt, ubuntu 20.04LTS) i still have: 02:45:03 AM.279387/SRT:RcvQ:worker*E:SRT.c: %460047763:No room to store incoming packet: offset=9966 avail=0 ack.seq=328449925 pkt.seq=328459891 rcv-remain=8191 randomly (after 2min or 3hours). The incoming feed is pushed from a Sencore Srt Gateway DMG 700 and original encoding service is from a Harmonic broadcast contribution encoder. The TS rate is 21Mb/s.

gst-launch-1.0 -v srtsrc 'uri=srt://sencore_gtw_ip:19916?mode=caller' ! queue ! udpsink host=239.127.0.1 port=6970

I tried to add &srt-recv=8192&fc=25600&maxbw=-1&overhead=25 but no success.

maxsharabayko commented 4 years ago

Does GStreamer allow to set the SRTO_RCVBUF socket option to change the receiver's buffer size? Struggling to find it here. Looks like it can't be set. @justinjoy could you consult on this?

AlexandreLicinio commented 4 years ago

See https://github.com/Haivision/srt/issues/445 but not sure of this if you said you couldn't find it ! But even with srt-recv:{INT, 0...} set, i get the error. With srt-live-transmit i don't get this error.

justinjoy commented 4 years ago

Does GStreamer allow to set the SRTO_RCVBUF socket option to change the receiver's buffer size?

Sorry about that. It doesn't support yet.

AlexandreLicinio commented 4 years ago

ok @justinjoy we are many having issues with gstreamer, when can we expect you support SRTO_RCVBUF please ?

justinjoy commented 4 years ago

ok @justinjoy we are many having issues with gstreamer, when can we expect you support SRTO_RCVBUF please ?

I have sent a patch[1] to GStreamer. Let's see what they say.

[1] https://gitlab.freedesktop.org/gstreamer/gst-plugins-bad/-/merge_requests/1334

AlexandreLicinio commented 4 years ago

thanks @justinjoy !

maxsharabayko commented 4 years ago

Status Update

The 1334 patch for GStreamer adding the possibility to set SRTO_RCVBUF is still waiting to be merged.
Log messages were extended in #1282 (SRT v1.4.2) to help identify the reason for the receiver buffer not having enough space. May be related to #1255. Please include all log messages you will have starting with "No room to store incoming packet: offset..." in full together with surrounding messages.
Bear in mind this recommendation.

Similar issue #1246.

maxsharabayko commented 3 years ago

PR #1909 further improves the log message. Note that the "no room to store" log message now has the level warning (since v1.4.2).

The following two reasons for this message to appear can now be distinguished from the log message.

1 App is not reading fast enough:

No room to store incoming packet seqno 1887365986, insert offset 1711. Space avail 190/849 pkts.
    Packets ACKed: 658 (TSBPD ready in -1680 : -1219 ms), not ACKed: 0, timespan 460 ms. STDCXX_STEADY drift 0 ms.

TSBPD ready in -1680 : -1219 ms indicates that there are 658 packets available for reading for already at least 1.6 seconds.

2. Too small buffer

Example log message when there is almost nothing for the app to read, and not enough receiver buffer. Knowing the configured SRT_RCVLATENCY is 1s, it can be seen the timestamp of the receiver buffer is less (593 ms). The first packet can be read only in 383 ms, which means the current target buffering delay is 593 + 383 = 976ms.

No room to store incoming packet seqno 2027222264, insert offset 0. Space avail 0/849 pkts.
    Packets ACKed: 848 (TSBPD ready in 383 : 977 ms), not ACKed: 0, timespan 593 ms. STDCXX_STEADY drift 0 ms.

Issue Status

Closing this issue due to the lack of activity (since Jun 11, 2020). Please feel free to reopen if further questions arise.

ioram-devi commented 3 years ago

Hello. The receiver buffer settings do not work according to your recommendations from: https://github.com/Haivision/srt/issues/409#issuecomment-496893657 and https://github.com/Haivision/srt/issues/700

Use case: 1) Publisher: ffmpeg -re -i "/home/my-videos/1920.mp4" -c copy -f mpegts "srt://localhost:9000?latency=200000&maxbw=12399073" 2) Receiver ffmpeg -i "srt://localhost:9000?mode=listener&latency=200000&maxbw=12399073&rcvbuf=48234496&fc=102400" -f mp4 "/home/my-videos/recorded-1920.mp4"

The result: No room to store incoming packet seqno.... and then recording process has been failed.

So, all your recommendations for receiver buffer settings are useless in my case.

I am currently considering using a message broker, please let me know if there is some other simple way to reliably write stream data to disk or wait HDD.

EDITED: SRT: latest version. FFmpeg: Latest version.

Thanks

maxsharabayko commented 3 years ago

Hi @yuri-devi Try this way (fc before rcvbuf):

ffmpeg -i "srt://localhost:9000?mode=listener&latency=200000&maxbw=12399073&fc=102400&rcvbuf=48234496"
       -f mp4 "/home/my-videos/recorded-1920.mp4"

It would further help if you could use the latest SRT master with the updated warning message.

ioram-devi commented 3 years ago

@maxsharabayko Thank you for the answer. I didn't know that the packet control window size property has priority over the receiver buffer parameter.

ioram-devi commented 3 years ago

This looks like a problem with receiver buffer size. The size should be at least Bufrcv >= bps × RTTsec / (8 × (1500 - 28)) + (latencysec × bps) Bear in mind #700.

Default receiver buffer size is 8192 × (1500-28) = 12058624 bytes or approximately 96 Mbits. Default flow control window size is 25600 packets or approximately 300 Mbits.

@maxsharabayko Could you please check me with my network values:

Setting up the receiver buffer:

Video bitrate: 6000Kbit/s RTT (Ping): 0.15 Latency: 0.6

The Result of rcvbuf: ((6000000 0.15) / (8 (1500 - 28))) + (0.6 * 6000000) ~ 3600076 bytes

Setting up the flow control window size:

My network bandwidth: 11140518 byte/s RTT: 0.15

The result of fc: ((((maxbw 8) (0.15) / 8 / 1472)) = ~ 1135 packets

Is it correct ?

Thanks

maxsharabayko commented 3 years ago

Hi @yuri-devi

I didn't know that the packet control window size property has priority over the receiver buffer parameter.

It is indeed not obvious at all and needs to be improved (#700).

Could you please check me with my network values: ...

The latest configuration guide can be found here.

Assuming 0.15 sec RTT and 0.6 sec latency you would roughly need to store your 6 Mbps stream for 0.6 seconds. So the buffer must around (0.6 s × 6 Mbps) = 450 000 bytes.

With the provided function I get target buffer size 565 248 bytes and FC = 384 packet.

CalculateTargetRBufSize(150, 6000000, 1316, 600, 1500);

With your environment the default configuration should be more than enough, unless you wold like to save memory.

ioram-devi commented 3 years ago

@maxsharabayko Thanks for your help. I tried CalculateTargetRBufSize logic by my side and it's not working. I still see errors like no room to store incoming packet...

According your recommendations and the result of calculate CalculateTargetRBufSize method it will be 565 248 bytes and FC = 384 packet but for my bitrate 6000Kbit/s isn't correct values because it's much less default values 12058624 and 25600 accordingly and it doesn't make the results better.

So, now I just increment the default rcvbuf and fc values the manual way but I still think what the control of these parameters can be user-friendly

maxsharabayko commented 3 years ago

@yuri-devi Could you share a network capture on the sender side at least up until the moment the receiver shows the warning? We could look at packet sending times and the bitrate curve to reproduce the behavior. If you enable encryption the payload would be totally secured.

ioram-devi commented 3 years ago

@maxsharabayko Sorry for the delay. Yes, I will do it when i have the opportunity. Thanks.

Delitants commented 1 year ago

Same problem in flussonic

Dec 26 21:41:59 localhost run[218599]: "21:41:59.274365/SRT:RcvQ:w45964!W:SRT.qr: @494418234:No room to store incoming packet: offset=3292 avail=3072 ack.seq=615021140 pkt.seq=615024432 rcv-remain=5119 drift=288\n"} Dec 26 21:41:59 localhost run[218599]: {'$srt_log',4,"/root/srt-1.4.2/srtcore/core.cpp",9621,"processData", Dec 26 21:41:59 localhost run[218599]: "21:41:59.274439/SRT:RcvQ:w45964!W:SRT.qr: @494418234:No room to store incoming packet: offset=3293 avail=3072 ack.seq=615021140 pkt.seq=615024433 rcv-remain=5119 drift=288\n"} Dec 26 21:41:59 localhost run[218599]: {'$srt_log',4,"/root/srt-1.4.2/srtcore/core.cpp",9621,"processData", Dec 26 21:41:59 localhost run[218599]: "21:41:59.274447/SRT:RcvQ:w45964!W:SRT.qr: @494418234:No room to store incoming packet: offset=3294 avail=3072 ack.seq=615021140 pkt.seq=615024434 rcv-remain=5119 drift=288\n"} Dec 26 21:41:59 localhost run[218599]: {'$srt_log',4,"/root/srt-1.4.2/srtcore/core.cpp",9621,"processData", Dec 26 21:41:59 localhost run[218599]: "21:41:59.274483/SRT:RcvQ:w45964!W:SRT.qr: @494418234:No room to store incoming packet: offset=3295 avail=3072 ack.seq=615021140 pkt.seq=615024435 rcv-remain=5119 drift=288\n"} Dec 26 21:41:59 localhost run[218599]: {'$srt_log',4,"/root/srt-1.4.2/srtcore/core.cpp",9621,"processData", Dec 26 21:41:59 localhost run[218599]: "21:41:59.274540/SRT:RcvQ:w45964!W:SRT.qr: @494418234:No room to store incoming packet: offset=3296 avail=3072 ack.seq=615021140 pkt.seq=615024436 rcv-remain=5119 drift=288\n"} Dec 26 21:41:59 localhost run[218599]: {'$srt_log',4,"/root/srt-1.4.2/srtcore/core.cpp",9621,"processData", Dec 26 21:41:59 localhost run[218599]: "21:41:59.274550/SRT:RcvQ:w45964!W:SRT.qr: @494418234:No room to store incoming packet: offset=3297 avail=3072 ack.seq=615021140 pkt.seq=615024437 rcv-remain=5119 drift=288\n"}

maxsharabayko commented 1 year ago

@Neolo please use a newer version of SRT library. The log message has been improved. https://github.com/Haivision/srt/issues/409#issuecomment-836463601 Usually, the issue is related to the app not reading the data from SRT. Therefore SRT has to store it and has no more room for newer packets.

Delitants commented 1 year ago

@Neolo please use a newer version of SRT library. The log message has been improved. #409 (comment) Usually, the issue is related to the app not reading the data from SRT. Therefore SRT has to store it and has no more room for newer packets.

App is Flussonic and it's latest version, log still floods with these messages. I see no reason why app wouldn't read data from SRT. Does not make any sense.

2023-01-12 03:41:46.712 <0.328.0> 03:41:46.712550/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3359 avail=3170 ack.seq=423736348 pkt.seq=423739707 rcv-remain=5021 drift=-422 2023-01-12 03:41:46.712 <0.328.0> 03:41:46.712607/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3360 avail=3170 ack.seq=423736348 pkt.seq=423739708 rcv-remain=5021 drift=-422 2023-01-12 03:41:46.713 <0.328.0> 03:41:46.712615/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3361 avail=3170 ack.seq=423736348 pkt.seq=423739709 rcv-remain=5021 drift=-422 2023-01-12 03:41:46.713 <0.328.0> 03:41:46.712679/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3362 avail=3170 ack.seq=423736348 pkt.seq=423739710 rcv-remain=5021 drift=-422 2023-01-12 03:41:46.713 <0.328.0> 03:41:46.712692/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3363 avail=3170 ack.seq=423736348 pkt.seq=423739711 rcv-remain=5021 drift=-422 2023-01-12 03:41:46.713 <0.328.0> 03:41:46.712698/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3364 avail=3170 ack.seq=423736348 pkt.seq=423739712 rcv-remain=5021 drift=-422 2023-01-12 03:41:46.713 <0.328.0> 03:41:46.712747/SRT:RcvQ:w12379!W:SRT.qr: @518511538:No room to store incoming packet: offset=3365 avail=3171 ack.seq=423736348 pkt.seq=423739713 rcv-remain=5020 drift=-422

ethouris commented 1 year ago

The latest release is 1.5.1, and in this version this message looks more-less like this:

No room to store incoming packet seqno 12345578789, insert offset 1234. Space avail 123/4096 pkts. (TSBPD ready in ...

What you have shown is the message from the older version, and the information provided by this message is too sparse to allow to investigate anything.

The reason could be the application's too slow reading, but it can be as well some rare internal problem in SRT (clock skew, unusual drift, bitrate spike etc.), at least in theory, in result of which the number of packets not yet ready to be delivered are suddenly occupying too big portion of the buffer. Only in the 1.5.1 version this message contains enough information to determine whether it was the case and then what might have caused it.

Ah, and one more thing - we have seen sometimes applications that do not exactly follow the required rules of SRT to read the packets all the time, and sometimes allow themselves to stop reading for a longer while (treating SRT as if it were UDP, which will at worst drop packets that can't be stored in the buffer, but you can always resume reading and everything's ok). Anyway, from the latest SRT's messages this will be known - how many packets are waiting for the right time (so it's SRT to keep them) and how many packets are waiting for the application to be picked up (so it's the application).

ggreco commented 1 year ago

Version 1.5.1 here, I'm getting something like this while startupping a stream with a huge probe buffer in ffmpeg since the keyframe are sparse:

[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] decode_slice_header error
[h264 @ 0x7fc71e86b400] no frame!
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] decode_slice_header error
[h264 @ 0x7fc71e86b400] no frame!
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] decode_slice_header error
[h264 @ 0x7fc71e86b400] no frame!
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] sps_id 0 out of range
[h264 @ 0x7fc71e86b400] non-existing PPS 0 referenced
[h264 @ 0x7fc71e86b400] decode_slice_header error
[h264 @ 0x7fc71e86b400] no frame!
[h264 @ 0x7fc71f88c000] co located POCs unavailable
[h264 @ 0x7fc71f88c000] co located POCs unavailable
15:10:32.011497/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580591, insert offset 0. Space avail 0/339 pkts. (TSBPD ready in -280ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:32.012617/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580592, insert offset 1. Space avail 0/339 pkts. (TSBPD ready in -281ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:32.998721/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580593, insert offset 2. Space avail 0/339 pkts. (TSBPD ready in -1267ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:32.998772/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580594, insert offset 3. Space avail 0/339 pkts. (TSBPD ready in -1267ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.008760/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580597, insert offset 6. Space avail 0/339 pkts. (TSBPD ready in -1277ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.008788/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580598, insert offset 7. Space avail 0/339 pkts. (TSBPD ready in -1277ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.018906/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580604, insert offset 13. Space avail 0/339 pkts. (TSBPD ready in -1287ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.018998/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580605, insert offset 14. Space avail 0/339 pkts. (TSBPD ready in -1287ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.028949/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580616, insert offset 25. Space avail 0/339 pkts. (TSBPD ready in -1297ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.029116/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580617, insert offset 26. Space avail 0/339 pkts. (TSBPD ready in -1297ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.038952/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580623, insert offset 32. Space avail 0/339 pkts. (TSBPD ready in -1307ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.039003/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580624, insert offset 33. Space avail 0/339 pkts. (TSBPD ready in -1307ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.049094/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580632, insert offset 41. Space avail 0/339 pkts. (TSBPD ready in -1317ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.049173/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580633, insert offset 42. Space avail 0/339 pkts. (TSBPD ready in -1317ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.059151/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580640, insert offset 49. Space avail 0/339 pkts. (TSBPD ready in -1327ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.059205/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580641, insert offset 50. Space avail 0/339 pkts. (TSBPD ready in -1327ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.069266/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580649, insert offset 58. Space avail 0/339 pkts. (TSBPD ready in -1338ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.069312/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580650, insert offset 59. Space avail 0/339 pkts. (TSBPD ready in -1338ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.079313/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580657, insert offset 66. Space avail 0/339 pkts. (TSBPD ready in -1348ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.079358/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580658, insert offset 67. Space avail 0/339 pkts. (TSBPD ready in -1348ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.089425/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580666, insert offset 75. Space avail 0/339 pkts. (TSBPD ready in -1358ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.089471/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580667, insert offset 76. Space avail 0/339 pkts. (TSBPD ready in -1358ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.
15:10:33.099408/!W:SRT.qr: @1021962991:No room to store incoming packet seqno 1115580675, insert offset 84. Space avail 0/339 pkts. (TSBPD ready in -1368ms, timespan 394 ms). MACH_ABSTIME drift 0 ms.

I tried raising rcvbuf but it seems the problem here is with the packet number, it's possible to raise that one?

ethouris commented 1 year ago

The time in "TSBPD ready in" is the time remaining for the earliest packet that is ready for extraction (that is, in non-blocking mode this long time should be waited until the call to srt_recv* function, and in blocking mode this call will block for that long time).

If this time is negative, it means that the application doesn't read packets from the SRT socket fast enough (not as fast as they come in, or by some reason it has stopped or paused doing it).

duffxp commented 11 months ago

Hello.

I'm using srt-live-transmit for an SRT in listener mode while generating a multicast from that source.

I already made the recommended change:

┌─[lab@debian]─[~/srt]─[13:04:38]
└──╼ $ cat /proc/sys/net/core/rmem_max 
26214400

But even so, I still get the following log after some running time (≃12 minutes):

SRT parameters specified:

        mode = 'listener'
Opening SRT source listener on 192.168.10.52:5070
Binding a server on 192.168.10.52:5070 ...
 listen...
Multicast: home address: 10.50.3.169:5070
Multicast(POSIX): will bind to IGMP address: 234.50.99.200
 accept...
 connected.
Accepted SRT source connection
12:13:01.256038/SRT:RcvQ:w1!W:SRT.qr: @183037812: No room to store incoming packet seqno 1321227993, insert offset 8191. iFirstUnackSeqNo=1321219802 m_iStartSeqNo=1321219802 m_iStartPos=6605 m_iMaxPosOff=8191. Space avail 8191/8192 pkts. GETTIME_MONOTONIC drift 0 ms.
12:13:01.257595/SRT:RcvQ:w1!W:SRT.qr: @183037812: No room to store incoming packet seqno 1321227994, insert offset 8192. iFirstUnackSeqNo=1321219802 m_iStartSeqNo=1321219802 m_iStartPos=6605 m_iMaxPosOff=8191. Space avail 8191/8192 pkts. GETTIME_MONOTONIC drift 0 ms.
12:13:01.259440/SRT:RcvQ:w1!W:SRT.qr: @183037812: No room to store incoming packet seqno 1321227995, insert offset 8193. iFirstUnackSeqNo=1321219802 m_iStartSeqNo=1321219802 m_iStartPos=6605 m_iMaxPosOff=8191. Space avail 8191/8192 pkts. GETTIME_MONOTONIC drift 0 ms.
12:13:01.261164/SRT:RcvQ:w1!W:SRT.qr: @183037812: No room to store incoming packet seqno 1321227996, insert offset 8194. iFirstUnackSeqNo=1321219802 m_iStartSeqNo=1321219802 m_iStartPos=6605 m_iMaxPosOff=8191. Space avail 8191/8192 pkts. GETTIME_MONOTONIC drift 0 ms.
12:13:01.262178/SRT:RcvQ:w1!W:SRT.qr: @183037812: No room to store incoming packet seqno 1321227997, insert offset 8195. iFirstUnackSeqNo=1321219802 m_iStartSeqNo=1321219802 m_iStartPos=6605 m_iMaxPosOff=8191. Space avail 8191/8192 pkts. GETTIME_MONOTONIC drift 0 ms.

The encoder that is generating and transmitting the stream (obviously configured in caller mode) is configured at a bitrate of 6 Mbp/s. So, this is well below what could possibly cause a problem.

I'm using v1.5.3 and using this script:

#!/bin/bash

log_file="$(date +%Y-%m-%d).log"

start_stream() {
    /home/lab/srt/srt-live-transmit "srt://192.168.10.52:5070?mode=listener" -buffering:4 -chunk:1456 "udp://234.50.99.200:5070?adapter=10.50.3.169&rcvbuf=67108864" -v >> "$log_file" 2>&1
}

start_stream

maxsharabayko commented 11 months ago

@quintanaplaca Please see Configuration Guidelines

ethouris commented 11 months ago

I'm taking a look at what should be in this log and this condition seems not to be satisfied (as the content of it isn't printed in the log):

    if (m_tsbpd.isEnabled() && m_iMaxPosOff > 0)
    {

As m_iMaxPosOff is shown above and it's greater than 0, it means that you have TSBPD turned off. This is weird because this option is turned on by default and not modified in this command line. Might be though that it can be off if one side modified it.

duffxp commented 11 months ago

This is my first real contact with this protocol, so I feel like I missed something. However, even though it has a higher limit than expected, I think it should work.

Anyway, I did a simple test, but reversing the request side; that is, now I am as caller and the encoder as listener, and this has been working for over an hour:


Input #0, mpegts, from 'srt://{IP}:5070?mode=caller&latency=200000&maxbw=12399073&fc=102400&rcvbuf=48234496':
...
frame=125614 fps= 33 q=-1.0 size= 2674911kB time=01:03:31.69 bitrate=5748.8kbits/s speed=   1x

So I suspect this is related to the listener ---> UDP or the lack of parameters on the receive (when I put it on the output instead). That is, something like:

srt://192.168.10.52:5070?mode=listener latency=200000&maxbw=12399073&fc=102400&rcvbuf=48234496" -buffering:4 -chunk:1316 "udp://234.50.99.200:5070?adapter=10.50.3 .169"

ethouris commented 11 months ago

The main reason for a receiver buffer overflow is that the application doesn't read packets as fast as the new ones come in. In live mode the situation is a bit specific because:

the sender can't stop sending just because the buffer is full (unlike in file mode)
some packets remain in the buffer as "latency compensation"

The latency compensation is simply the number of packets that represent the duration equal to the latency value - so it depends on the stream bitrate and the latency value. Might be that the default buffer size is not big enough for this - that should be checked with the guidelines, as Max showed you above.

Theoretically the latency compensation is the only reason for buffering, but for safety reasons the buffer should also have space for:

application compensation (the application delays with reading packets that should be extracted already)
flight improvement compensation (packets arrive from the network earlier than expected because network conditions have improved)

They should be normally empty, but they might temporarily grow and lead to buffer overflow if they grow too big.

We were suspecting many times problems with TSBPD calculation, which could result in that the latency compensation fragment of the buffer is temporarily too big. We have never detected for sure such a case so far, but then just in case this information about the TSBPD time span in the buffer is added to this log. As you didn't have it in your log, this is weird, but it must have resulted from some different settings set on the connection sides. But this information is vital to detect, what the reason was for this to happen.

duffxp commented 11 months ago

@ethouris, Thank you for your detailed explanation on the topic.

The flow has been working for almost a day, as I reported in the previous post. Anyway, I intend to debug that logic (receiving stream as listener and generating UDP) and share it with you.

I'm just a little worried because I'm using the latest version of the repository, and I did as per the guide, without removing any parameter that would imply hiding information about the TSBPD.

I may try to build this again.

ethouris commented 11 months ago

Note that settings set only on one side may influence the whole process, that is, apply to the peer, too. Therefore make sure what options are set on both connection sides.

Haivision / srt