Adjust mixer time-keeping

[alexlivekit]

Here's how the mixer output looks like today. Look at the Delta column, which details how much time has passed since the last packet was sent out:

Edit: Changed PR, would generate the data again.

[alexlivekit]

A notable update here, wasn't in the OG review.

[biglittlebigben]

Can you comment on the logic? m.tickerDur / 4 seems arbitrary and if there is jitter in the timer servicing, we should catch up the next time we wake up.

[alexlivekit]

Sure, I'll add that in code.

To elaborate further here, lets look at a timeline:
t+001ms: First got delayed by some minor amount. Frame mixed, m.lastMixEndTs set.
t+021ms: n == 1, all is well.
t+040ms: n == 0, we count this as a zero-mix, m.lastMixEndTs is not updated, and we do not produce a frame.
t+061ms: n == 2, because it thinks we've waited 41ms since the last time. JumpMixes+=2, we release two frames.
t+080ms: n == 0, repeat.

This example is using ms jitter, but this can also happen on a nanosecond level as well.
We definitely want to have the mixer produce a steady stream of frames, and not bunch them up in pairs.

m.tickerDur / 4 is indeed arbitrary, but we need something that's 2ms < something < m.tickerDur / 2 so that makes sense to me.

[biglittlebigben]

This is not how I understand the code. lastMixEndTs is set by counting samples, not looking at the time we actually pushed the samples. So

t+000ms: first frame mixed, m.lastMixEndTs set.
t+021ms: n == 1, all is well.
t+040ms: n = (040-020) / 020 = 1
t+061ms: n == (061-040) / 020 = 1
t+080ms: n == (080-060) / 020 = 1

[alexlivekit]

Let me amend it then, just to re-frame this from the ticker's perspective:
t+000ms: (either first frame, or reset). Frame mixed, m.lastMixEndTs baseline set.
t+020ms: n == 1, all is well.
t+039ms: n == 0, we count this as a zero-mix, m.lastMixEndTs = m.lastMixEndTs.Add(time.Duration(n) * m.tickerDur) = m.lastMixEndTs.Add(0) - is not updated, and we do not produce a frame.
t+060ms: n == 2, because it thinks we've waited 40ms since the last time. JumpMixes+=2, we release two frames.
t+079ms: n == 0, repeat.

This happens on both start-of-stream and resets, and we can clearly see that in pcaps.
Furthermore, the time the ticker goroutine actually takes to start running depends on system load, go scheduler, k8s, etc. So the time between the internal tick and when actually get control and set m.lastMixEndTs is almost zero, but is never actually zero. That delta is enough to cause this, even if everything else functions like clockwork.

[biglittlebigben]

I'm ok with your approach if you can convince me that the extra leaway will never cause us to try to pull samples in the future that are not queued yet.

The ticker doesn't double-fire, and it's the only caller of this code. So what we have is this timeline: real tick deadline > delta (os/container/go scheduling + our own app code up to now := time.Now()) > dt check. We can't really fire before the deadline, so the only thing that changes is how big the delta is on any given tick. Since nextDeadling = lastDeadline + m.tickerDur, fuzzing it by 0.25 of m.tickerDur will not be siphoning frames from the future, it will actually be processing frames we should have processed already.

How about the case where delay in scheduling causes the ticker handler to run 58ms after the previous ticker?

[alexlivekit]

Well, if we reset the ticker due to n > m.inputBufferFrames (for example, caused by a large scheduling delay), we're then risking resetting the tick to an even weirder time.

How about the case where delay in scheduling causes the ticker handler to run 58ms after the previous ticker?

So the tick was queued at 20ms after, and we didn't receive control until 58ms after.
With this modification, dt == 60.5ms, n=3, m.lastMixEndTs += 60ms, and we attempt to pull three frames.
The next tick, assuming no crazy delay here, is in 2ms, wakes up, properly concludes that n=0, and does nothing.

Now, the we attempt to pull three frames part is hiding a quirk - if we have three frames, all is well. But if we only have two, we insert one silence frame in, and increase the buffered frames by one. This is less than ideal, but imo it is better than routinely oscillating between 0, 1, and 2 frames produced per tick which is what we routinely see with the usage in sip.

[dennwc]

A lot of discussion here, so please let me know if I missed something important.

I think the 0.25 approach might work well here, since the mixer intentionally delays the stream by 60 ms. We could take the buffered frame a bit earlier, which basically reduces this delay by 5 ms.

Having said that, we do really need to prevent oscillations. So the mixer reset must bump both inputBufferFrames and inputBufferMin (as well as associated buffers) by 1 frame. In this case, maybe we could start from a 2/4 instead of a 3/5 setup. This would cut 20 ms delay for fast streams and will revert to 60 ms or more for slower ones at a cost of a few resets.

[alexlivekit]

Yeah, sleeping on it some more I like Ben's point more and more. If we simply start measuring from before the ticker starts, we'd only need to take care of the almost 100% of m.tickerDur once we rest the baseline. That way we're not just moving the arbitrary cutoff.

[biglittlebigben]

The 60ms of delay in the input buffers was the missing piece. Adding the fudge factor should be fairly safe in that case

[dennwc]

It was intentional that n == 0 check is after all ifs - this would have caught case where dt <= 0 for whatever reason. In the new code, it only catches cases when dt > 0 && n == 0.

[alexlivekit]

Put it here since the existing tests do not even start the ticker. Synctest additions that actually test ticker behavior to follow this up afterwards (a little scared bumping go version to 1.25)

[alexlivekit]

A little defensive here, but will remove once we're happy this works as we want it to.

[alexlivekit]

Because we're setting the baseline at allocation (which would normally also start the ticker), calling m.mixUpdate() immediately would result in a zero-mix.