Srt: Drift calculation causes problems with a high latency/high jitter connection.

[oviano]

My sender transmits a live MPEG-TS stream. My payload size is 1338 as I have some extra data and latency is set to 2000ms.

It is all working correctly most of the time, but sometimes there is a delay in receiving the next message (i.e. it arrives much later than expected, in the example below 400ms) and subsequent messages are all delayed by the same amount. Then, a few minutes later, it recovers, or the delay changes to something else. In each case, the stream continues with the same delay for a while.

My expectation was that if a message was 400ms late it would be dropped, and not simply delay all subsequent messages. Is there some logic that is interfering with this? Could having quite a high latency of 2000ms be related? Or could this be a flaw in the algorithm - what happens if all messages are delayed by 400ms for some reason? How would SRT cope? Since they are still received in order, would this mean that none are dropped?

TLPKTDROP is enabled, packets are getting dropped in other situations.

Application log:

Here you can see at what point the expected receive time for a packet jumps to over 400ms and stays that way.

Specifically here:

<<<<

09/07/19 09:40:40 : SEND_TIME 67194444 RECV_TIME 67197760 DELTA -3316
09/07/19 09:40:40 : SEND_TIME 67200000 RECV_TIME 67197894 DELTA 2106
09/07/19 09:40:40 : SEND_TIME 67208333 RECV_TIME 67204741 DELTA 3592
09/07/19 09:40:41 : SEND_TIME 67216667 RECV_TIME 67620234 DELTA -403567
09/07/19 09:40:41 : SEND_TIME 67222222 RECV_TIME 67624992 DELTA -402770
09/07/19 09:40:41 : SEND_TIME 67227777 RECV_TIME 67630835 DELTA -403058

>

SEND_TIME is the offset in microseconds that each message was sent on the sender. So the first message was sent at SEND_TIME zero. RECV_TIME is the offset in microseconds that each message was received on the receiver. So the first message received has RECV_TIME zero. As you can see in the log, these are within a few milliseconds of each other up until the above. Then suddenly a message is delayed by over 400ms, as are all subsequent ones.

https://ovcollyer.synology.me:5001/d/f/497609639746085777

SRT Sender log (heavy logging enabled):

https://ovcollyer.synology.me:5001/d/f/497609135930483593

SRT Receiver log (heavy logging enabled):

https://ovcollyer.synology.me:5001/d/f/497610734981620627

[oviano]

So it looks like it relates to the drift adjustment. In the example below the drift has already risen to 3794us but it suddenly jumps to nearly 90ms, which of course delays all subsequent packets by that amount.

Now I will enable the drift debug to try and figure out the cause...

12:05:17.049133 D:SRT.c: getRcvReadyMsg: found packet, but not ready to play (only in 9.987ms)
12:05:17.049143 D:SRT.c: getRcvReadyMsg: m_pUnit[i]->m_Packet.getMsgTimeStamp()=87638136
12:05:17.049150 D:SRT.c: getRcvReadyMsg: getTsbPdTimeBase(m_pUnit[i]->m_Packet.getMsgTimeStamp())=358171133128
12:05:17.049158 D:SRT.c: getRcvReadyMsg: m_uTsbPdDelay=2000000
12:05:17.049166 D:SRT.c: getRcvReadyMsg: m_DriftTracer.drift()=3794
12:05:17.049173 D:SRT.t: %999793741:tsbpd: FUTURE PACKET seq=588094476 T=05:31:00.775058 - waiting 9.947ms
12:05:17.050762 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793743 CONTROL: keepalive size=4
12:05:17.050760 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 CONTROL: ackack size=4
12:05:17.050835 D:SRT.c: %999793741:incoming UMSG:6 (ackack) socket=%999793741
12:05:17.050850 D:SRT.c: updateCC: EVENT:ackack
12:05:17.050858 D:SRT.c: udpateCC: emitting signal for EVENT:ackack
12:05:17.050865 D:SRT.c: udpateCC: finished handling for EVENT:ackack
12:05:17.050809 D:SRT.c: %999793743:incoming UMSG:1 (keepalive) socket=%999793743
12:05:17.050899 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.050915 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.050874 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.050955 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.050978 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.050925 D:SRT.c: updateCC: updated values from smoother: interval=61728395tk (61728.4us) cgwindow=17.2
12:05:17.050997 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.051029 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.051081 D:SRT.c: CChannel::sendto: SENDING NOW DST=81.150.182.56:8091 target=%208672986 CONTROL size=28 cmd=ack arg=5785
12:05:17.051091 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.051119 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793743 pkt-payload-size=4
12:05:17.051133 D:SRT.c: sendCtrl: %999793741:ACK (1): 588094901
12:05:17.051148 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.051156 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=4
12:05:17.051173 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 DATA: msg=18938 seq=588094901 size=1338
12:05:17.051190 D:SRT.d: %999793741:processData: RECEIVED DATA: size=1338 seq=588094901
12:05:17.051202 D:SRT.c: updateCC: EVENT:receive
12:05:17.051210 D:SRT.c: udpateCC: emitting signal for EVENT:receive
12:05:17.051217 D:SRT.c: udpateCC: finished handling for EVENT:receive
12:05:17.051225 D:SRT.c: %999793741:RECEIVED: seq=588094901 offset=0 ACCEPTED (EXPECTED/ORIGINAL) FLAGS: PB_SOLO ORD_RELAXED EK_NOENC SN_ORIGINAL
12:05:17.051236 D:SRT.d: crypter: data not encrypted, returning as plain
12:05:17.051243 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.051250 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.051257 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.051268 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.051276 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.051283 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=1338
12:05:17.055468 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 DATA: msg=18939 seq=588094902 size=1338
12:05:17.055538 D:SRT.d: %999793741:processData: RECEIVED DATA: size=1338 seq=588094902
12:05:17.055550 D:SRT.c: updateCC: EVENT:receive
12:05:17.055558 D:SRT.c: udpateCC: emitting signal for EVENT:receive
12:05:17.055566 D:SRT.c: udpateCC: finished handling for EVENT:receive
12:05:17.055575 D:SRT.c: %999793741:RECEIVED: seq=588094902 offset=1 ACCEPTED (EXPECTED/ORIGINAL) FLAGS: PB_SOLO ORD_RELAXED EK_NOENC SN_ORIGINAL
12:05:17.055587 D:SRT.d: crypter: data not encrypted, returning as plain
12:05:17.055595 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.055603 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.055610 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.055626 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.055635 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.055643 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=1338
12:05:17.055667 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 DATA: msg=18940 seq=588094903 size=1338
12:05:17.055684 D:SRT.d: %999793741:processData: RECEIVED DATA: size=1338 seq=588094903
12:05:17.055692 D:SRT.c: updateCC: EVENT:receive
12:05:17.055699 D:SRT.c: udpateCC: emitting signal for EVENT:receive
12:05:17.055705 D:SRT.c: udpateCC: finished handling for EVENT:receive
12:05:17.055713 D:SRT.c: %999793741:RECEIVED: seq=588094903 offset=2 ACCEPTED (EXPECTED/ORIGINAL) FLAGS: PB_SOLO ORD_RELAXED EK_NOENC SN_ORIGINAL
12:05:17.055722 D:SRT.d: crypter: data not encrypted, returning as plain
12:05:17.055729 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.055736 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.055743 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.055752 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.055759 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.055766 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=1338
12:05:17.055779 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 CONTROL: ackack size=4
12:05:17.055793 D:SRT.c: %999793741:incoming UMSG:6 (ackack) socket=%999793741
12:05:17.055802 D:SRT.c: updateCC: EVENT:ackack
12:05:17.055809 D:SRT.c: udpateCC: emitting signal for EVENT:ackack
12:05:17.055816 D:SRT.c: udpateCC: finished handling for EVENT:ackack
12:05:17.055823 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.055829 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.055836 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.055845 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.055852 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.055859 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=4
12:05:17.055949 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 DATA: msg=18941 seq=588094904 size=1338
12:05:17.055992 D:SRT.d: %999793741:processData: RECEIVED DATA: size=1338 seq=588094904
12:05:17.056004 D:SRT.c: updateCC: EVENT:receive
12:05:17.056011 D:SRT.c: udpateCC: emitting signal for EVENT:receive
12:05:17.056018 D:SRT.c: udpateCC: finished handling for EVENT:receive
12:05:17.056026 D:SRT.c: %999793741:RECEIVED: seq=588094904 offset=3 ACCEPTED (EXPECTED/ORIGINAL) FLAGS: PB_SOLO ORD_RELAXED EK_NOENC SN_ORIGINAL
12:05:17.056037 D:SRT.d: crypter: data not encrypted, returning as plain
12:05:17.056045 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.056052 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.056059 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.056070 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.056078 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.056086 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=1338
12:05:17.057662 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 DATA: msg=18942 seq=588094905 size=1338
12:05:17.057733 D:SRT.d: %999793741:processData: RECEIVED DATA: size=1338 seq=588094905
12:05:17.057745 D:SRT.c: updateCC: EVENT:receive
12:05:17.057753 D:SRT.c: udpateCC: emitting signal for EVENT:receive
12:05:17.057760 D:SRT.c: udpateCC: finished handling for EVENT:receive
12:05:17.057768 D:SRT.c: %999793741:RECEIVED: seq=588094905 offset=4 ACCEPTED (EXPECTED/ORIGINAL) FLAGS: PB_SOLO ORD_RELAXED EK_NOENC SN_ORIGINAL
12:05:17.057780 D:SRT.d: crypter: data not encrypted, returning as plain
12:05:17.057788 D:SRT.c: updateCC: EVENT:checktimer
12:05:17.057795 D:SRT.c: udpateCC: emitting signal for EVENT:checktimer
12:05:17.057802 D:SRT.c: updateCC: updated values from smoother: interval=0tk (1.49469e-09us) cgwindow=1.64e+04
12:05:17.057814 D:SRT.c: udpateCC: finished handling for EVENT:checktimer
12:05:17.057822 D:SRT.c: worker: result for the unit: INDUCED/CONCLUDING
12:05:17.057830 D:SRT.c: worker: RECEIVED PACKET --> updateConnStatus. cst=INDUCED/CONCLUDING id=999793741 pkt-payload-size=1338
12:05:17.059198 D:SRT.c: INCOMING PACKET: BOUND=0.0.0.0:0 TARGET=999793741 DATA: msg=18943 seq=588094906 size=1338
12:05:17.059281 D:SRT.d: %999793741:processData: RECEIVED DATA: size=1338 seq=588094906
12:05:17.059299 D:SRT.c: updateCC: EVENT:receive
12:05:17.059309 D:SRT.c: udpateCC: emitting signal for EVENT:receive
12:05:17.059319 D:SRT.c: udpateCC: finished handling for EVENT:receive
12:05:17.059168 D:SRT.c: getRcvReadyMsg: found packet, but not ready to play (only in 90.898ms)
12:05:17.059357 D:SRT.c: getRcvReadyMsg: m_pUnit[i]->m_Packet.getMsgTimeStamp()=87638136
12:05:17.059378 D:SRT.c: getRcvReadyMsg: getTsbPdTimeBase(m_pUnit[i]->m_Packet.getMsgTimeStamp())=358171138128
12:05:17.059390 D:SRT.c: getRcvReadyMsg: m_uTsbPdDelay=2000000
12:05:17.059399 D:SRT.c: getRcvReadyMsg: m_DriftTracer.drift()=89738
12:05:17.059415 D:SRT.t: %999793741:tsbpd: FUTURE PACKET seq=588094476 T=05:31:00.866002 - waiting 90.648ms

[oviano]

In conclusion: I don't think the algorithm for calculating drift works very well when you have a large latency over a long distance connection.

I added some hacky trace to where it calculates the drift and because I have a large latency of 2000ms and this is a connection spanning Europe, it's quite common for packets (whether data or ACK, and I know the drift is based on ACK-ACK) to arrive quite late in the 2000ms Window. This is quite valid and normal and is why I need a latency of 2000ms in the first place. Mostly, packets are not being dropped, just not arriving exactly on schedule.

However, the trace shows that once enough packets have arrived late in the Window during the 1000 sample period, this then drastically affects the drift calculation. As in, it suddenly applies a 90ms, 200ms, 400ms...you name it delay on the receive as some sort of incorrect counter to drift, when it's not actually drift that is causing this.

I think the algorithm probably works very well for small latency and tight network conditions, but it falls apart in this scenario.

I'm not sure of the solution. Perhaps simply extend the number of samples proportionally to the latency? If we assume the current implementation has been tuned to 120ms latency (the default), then maybe in my example of 2000ms latency we would scale the number of samples the window to 1000 * 2000 / 120 = 16667. I'm not even sure this would work though, because it doesn't escape the reality that it's perfectly normal, and expected, for packets to arrive later than expected in a long-distance-high-latency scenario.

[oviano]

So since disabling the drift adjustment in my code things have been rock solid.

Two suggestions:

1. Add something to the heavy logging that outputs the drift calculation as it changes. At the moment it's a somewhat hidden factor in a packet being received later than expected and I only figured it out by adding additional trace.
2. Review how well this algorithm works for smaller latency settings. My guess is that any connection with sufficient jitter/RTT will be liable for larger than acceptable changes in the drift adjustment leading to unexplained delays in packet delivery. This might not be obvious without point 1. above.

[oviano]

Was this feedback useful? Do you think there is room for improvement in the drift algorithm? I’ve worked around this by disabling the drift code on SRT and dealing with this at a higher level in my application.

On the sender: I consider the first packet sent to be time zero, subsequent ones I write the elapsed time offset into the packet.
On the receiver: first packet received I reset a receive timer. Now for every packet I calculate the difference in the “send time offset” (which I sent in each packet) and the “receive time offset” (the time I was given the packet by SRT).
I then keep a rolling average of this difference over each minute (resetting each minute) and when it hits certain thresholds I trigger an adjustment in my video player presentation time calculation.

Maybe you could use something similarly internally - rather than look at the ACK-ACK times, look at the time each packet becomes “to play” versus what it should be given it’s send time offset and the time that has elapsed since the connection was opened.

[maxsharabayko]

Hi @oviano. For sure you observations are helpful!
I had a quick look at this. There are two points to check.

1. RTT is not taken into account by TSBPD base time, and thus RTT deviations may influence drift offset, instead the time should stay the same in that case.
2. Bearing in mind the inaccuracy of waiting timers, maybe the latency can be considered as the maximum latency, instead of fixed (minimum) latency. I mean a packet is better to be allowed to be read 10 ms earlier than 10 ms later. At least it should be better for a player, although it should adapt. So requires some further check.

This issue is on hold, as we need to make two more releases of SRT with some of the accumulated PRs in a short time.

[oviano]

Great. I don’t fully understand but let me know when you have changes to test and I’ll reproduce my test scenario. It’s not urgent as my workaround is fine but I’m ready to test when you are.

[oviano]

So has anything been improved with this algorithm since I reported this issue? I understand there might be an option to properly disable it, but at the moment my experience with SRT is when disabled and without any other workaround code, the packets gradually get delivered later and later and so the player buffer eventually runs out.

For example, my stream system built using srt 1.4.0 sends packets from a Windows server using SRT and plays back on an Apple TV, latency is specified as 200ms but after a few hours the time span of available packets to read has gone from 200ms initially to over 350ms over a period of a few hours. Clearly over a period of time packets are not given up quickly enough for some reason.

My workaround until now has been to slow down playback by a frame occasionally to keep the buffer intact, but clearly this is a sticking plaster.

[maxsharabayko]

Hi @oviano.
Sadly we have not improved the algorithm yet.
However, the latest version of SRT in the master can be built with C++11 steady timing (-DENABLE_STDCXX_SYNC=ON, see the build instructions) or POSIX monotonic clock (-DENABLE_MONOTONIC_CLOCK=ON).
Making use of a steady clock both on the sender and receiver should reduce the drift, especially on Windows platforms. Therefore you should not see this behavior with drift tracer disabled.
However, we have not confirmed this yet, and corresponding experiments are to be conducted.

[oviano]

Ok then I’ll give the master branch a go then. I was holding off until you made an official release but this seems like it would be a useful test for you so I’ll try it.

Is the master branch generally stable?

[maxsharabayko]

The latest master is stable.

[oviano]

Ok, so I upgraded my project to latest SRT master but I still see the issue.

Brief summary:

• Server is running on Windows 10. USE_BUSY_WAITING is enabled. ENABLE_STDCXX_SYNC is defined.
• Client is macOS (but I've also observed the issue on tvOS, maybe it's all platforms I just haven't checked)
• Configured latency is 200ms, although this test is over a LAN connection between server and client
• Driftracer is disabled using the socket option, for the reasons originally outlined in this issue.
• My packet size is a little larger than the usual 1316 as this is a custom streaming protocol not TS.
• I follow the example code structure set in rcvlive, that is a non-blocking socket, then using epoll (although I use srt_epoll_uwait) and when there is data I read all of it until I get SRT_EASYNCRCV. Then I go back to epoll, with a timeout of 50ms.
• Every time I have read all available data, I call into the stats to get the msRcvBuf and store a rolling average which I display every few seconds in my client.
• I observe initially the msRcvBuf settles at around 170ms, which seems logical as I've just read everything from the buffer so I would expect that it wouldn't be the full 200ms.
• Over a period of about 30 minutes, the msRcvBuf rises steadily to about 240ms. At this point I stop the experiment because I have enabled heavy logging and boy is it heavy! (the above example is around 8GB of data).
• My code splits the log file into 100000 line chunks. I have placed the first chunk, a middle chunk and the last chunks here:

https://ovcollyer-colebrooke.synology.me:5001/d/f/577601243919201955

• A brief observation is that the logging output (lines containing getRcvDataSize) is consistent with what the stats are also telling me, which makes sense.

So, is this kind of drift an expected amount? It seems pretty high for just 30 minutes streaming, but maybe it is to be expected?

I guess this could be caused by inaccuracy on the server, rather than the receiver? (EDIT: although thinking about it, surely it must be a client side issue, as if the receive buffer contains a span of messages of 240ms, then surely it is up to the client side timer to allow them to be released more quickly)

Worth noting that I had the same issue with version 1.4.0, so I don't think it relates to the steady clock changes (great changes by the way - so nice to remove the need to have pthreads on Windows).

[maxsharabayko]

Hi @oviano
Thank you for the experiment!
To confirm, your macOS client also uses steady clock, right? Built with -DENABLE_STDCXX_SYNC=ON.

[oviano]

Yes that’s correct.

[oviano]

So in this test scenario, re-enabling the drift trace appears to control/eliminate this issue.

So I think this all goes back to improving the drift algorithm so that it doesn't introduce large jumps in scenarios like that described originally in this issue:

To quote myself: "However, the trace shows that once enough packets have arrived late in the Window during the 1000 sample period, this then drastically affects the drift calculation. As in, it suddenly applies a 90ms, 200ms, 400ms...you name it delay on the receive as some sort of incorrect counter to drift, when it's not actually drift that is causing this."

I wonder if we could just ignore samples that are (by some measurement) too delayed? Maybe a proportion of the RTT or latency or something.

I will have a look at the code and see if I can come up with a reasonable solution.

[maxsharabayko]

@oviano I confirm that even steady clocks have notable drift one from another, and disabling the drift tracer is not an option.
Fixing drift tracer to take RTT changes into account is the only way to go.

[gou4shi1]

@oviano can you elaborate your workaround? Thanks!

[maxsharabayko]

Hi @oviano, @gou4shi1
PR #1965 provides an improvement of the drift tracing. It is under testing.
Would be extremely helpful to get your feedback and test results as well!

[oviano]

Thank you for this - I updated my project to 1.4.3 yesterday, now I'll also grab this change too.