[core] Improved 'no room to store' log message

[maxsharabayko]

Problem Statement

The current "no room to store incoming packet" log message format does not provide enough hints to define the reason.

SRT.qr: @246279816:No room to store incoming packet: offset=1 avail=1
        ack.seq=864548218 pkt.seq=864548219 rcv-remain=25598 drift=-768

Proposed Log Message

Log level: warning (as before).

1. Example log message when the 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. 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.

Related issue #409

Possible Reasons for Not Enough Room

Possible reasons for not having enough room for an incoming packet are the following.

1. Receiving Application Is Not Reading

Data is available to be read from SRT socket, but the application is not reading or not reading fast enough. Excessive data is accumulated in the receiver buffer (above the buffering latency).

Need a way to tell how many packets are available for reading (including TSBPD readiness).

2. TSBPD-related:

SRT receiving application is reading fast enough, but there is not enough space to apply the buffering latency for the incoming bitrate.

Possible reasons:

1. Wrong configuration of the receiver buffer size. Must be at least (latency_ms + rtt_ms / 2) * bps / 1000 / 8.
2. RTT on the link has decreased -> buffering more than SRTO_RCVLATENCY.
3. DriftTracer changed the TSBPD base time, thus changing the buffering delay.

The actual receiver buffer timespan (stats.msRcvBuf + 10ms of unACKed packets) should roughly correspond to the SRTO_RCVLATENCY.
Need a way to tell how many packets (in ms timespan) are not yet available for reading.

[ethouris]

I've been always suspecting here the TSBPD thread that does not sign off packets early enough, but this could as well look like the application isn't being given enough time slice to read all packets that are ready to play. Might be as well due to that suddenly by some reason (likely drift changes) there have been "signed off" a large number of packets and the application could not extract them fast enough. Could be, however, that the drift change has caused that many packets being previously ready to play became not ready to play after the change, this state has lasted for some longer time due to a temporary high burst of packets being sent, and then later the drift returned to previous value, signing off this way a large number of packets, still after the previous change has caused the receiver buffer to get full.

Nevertheless, I'd start with displaying the number of packets ready to play at the moment when the application is reading them, as well as regarding the TSBPD thread changing the read-readiness on the socket (and the packet reading function as well, it does it basing on the same check). Also the first and last packet in the range together with its play time.

[maxsharabayko]

Updated format:

No room to store incoming packet: insert offset 312, space avail 312 (pkt.seq=608322614, ack.seq=608322302).
    Packets ACKed: 1 (TSBPD ready in 1961 : 1961 ms), not ACKed: 312, timespan 32 ms. STDCXX_STEADY drift=0

No room to store incoming packet: insert offset 1, space avail 0 (pkt.seq=608322615, ack.seq=608322614).
    Packets ACKed: 313 (TSBPD ready in 1395 : 1428 ms), not ACKed: 0, timespan n/a. STDCXX_STEADY drift=0