Audio/video de-sync with 1080p@30 (reproducible)

mediasoup libraries
1

I found a reproducible way to cause audio and video to de-sync with mediasoup.
More specifically audio remains low-latency, but video will lag behind (a second or more), how far depends on conditions.

I don’t know if there is something that can/should be done in mediasoup to resolve this since it shouldn’t buffer video to cause issues like that (and worker consumes very little memory), but I hope there is.

I’m testing on Macbook Pro 15 2017 (quad core core i7) running macOS Catalina 10.15.7.

Here is how I reproduce it:

  1. On the server create 1 worker and 1 router in it
  2. Open Chrome stable, connect with 3-layer simulcast with 1080p@30 as the highest layer (VP8)
  3. Open another Chrome tab, do the same
  4. On the other machine consume as a preview
  5. Back to Macbook, open another empty tab in Chrome, leave it
  6. Open Activity Monitor with 1 second refresh time (causes additional load)
  7. Open empty Safari browser (make sure it doesn’t fully cover Chrome and Activity Monitor)

Result: often preview client will hear audio in real time, but video will significantly lag behind.

Additional notes:

  • there is Coturn in front of mediasoup
  • I have https://github.com/versatica/mediasoup/pull/447 applied on top of Mediasoup because otherwise there are artifacts
  • key frames make things re-sync
  • 2 Chrome clients from different tabs can lag or not lag independently
  • when focusing Chrome window again video starts moving faster until it re-syncs
  • snippet of the log where de-sync happened for ssrc 943728671:
Summary 
2020-11-13T12:47:34.852Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:36.144Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:0827e170-fc06-4f09-9890-e0844f15d93b]
2020-11-13T12:47:36.860Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:36.871Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:36.874Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:38.168Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:0, consumerId:0827e170-fc06-4f09-9890-e0844f15d93b]
2020-11-13T12:47:40.818Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:b9492849-c070-4ab5-925f-b6363c983090]
2020-11-13T12:47:42.190Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:0827e170-fc06-4f09-9890-e0844f15d93b]
2020-11-13T12:47:47.283Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:3285333, before:4423172]
2020-11-13T12:47:52.906Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:52.966Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:5726000, before:8696238]
2020-11-13T12:47:53.023Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.026Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.034Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.040Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.042Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.045Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.048Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:53.051Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:47:54.975Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:0, consumerId:b9492849-c070-4ab5-925f-b6363c983090]
2020-11-13T12:47:56.999Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:b9492849-c070-4ab5-925f-b6363c983090]
2020-11-13T12:47:57.102Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:04.253Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:3053684, before:5267733]
2020-11-13T12:48:04.303Z mediasoup:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value increase detected, notifying the listener [now:5503568, before:3298979]
2020-11-13T12:48:13.104Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:19.208Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:25.777Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:28.426Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:2818449, before:4007089]
2020-11-13T12:48:33.541Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:2219953, before:5469202]
2020-11-13T12:48:33.541Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:0, consumerId:057732bc-8e40-44a7-af0d-8060f7315a46]
2020-11-13T12:48:33.599Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::OnNackGeneratorNackRequired() | triggering NACK [ssrc:943728671, first seq:50501, num packets:8]
2020-11-13T12:48:33.672Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::OnNackGeneratorNackRequired() | triggering NACK [ssrc:943728671, first seq:50501, num packets:8]
2020-11-13T12:48:33.751Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::OnNackGeneratorNackRequired() | triggering NACK [ssrc:943728671, first seq:50501, num packets:8]
2020-11-13T12:48:33.831Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::OnNackGeneratorNackRequired() | triggering NACK [ssrc:943728671, first seq:50505, num packets:4]
2020-11-13T12:48:34.083Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:1592550, before:3458337]
2020-11-13T12:48:34.083Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:1, temporal:1, consumerId:0827e170-fc06-4f09-9890-e0844f15d93b]
2020-11-13T12:48:34.083Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::RequestKeyFrame() | sending PLI [ssrc:740353432]
2020-11-13T12:48:34.302Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]
2020-11-13T12:48:34.433Z mediasoup:Channel [pid:64] RTC::Producer::ReceiveRtpPacket() | key frame received [ssrc:3109400966, seq:55691]
2020-11-13T12:48:34.434Z mediasoup:Channel [pid:64] RTC::Producer::ReceiveRtpPacket() | key frame received [ssrc:740353432, seq:17982]
2020-11-13T12:48:34.434Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::SendRtpPacket() | sync key frame received
2020-11-13T12:48:34.434Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::SendRtpPacket() | sending sync packet [ssrc:488876568, seq:17815, ts:108336651] from original [ssrc:608486876, seq:17982, ts:108336651]
2020-11-13T12:48:34.435Z mediasoup:Channel [pid:64] RTC::Producer::ReceiveRtpPacket() | key frame received [ssrc:2934111749, seq:32636]
2020-11-13T12:48:35.055Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]
2020-11-13T12:48:35.618Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659400, now_ms:18908659411]
2020-11-13T12:48:35.643Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659402, now_ms:18908659436]
2020-11-13T12:48:35.669Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659404, now_ms:18908659462]
2020-11-13T12:48:35.694Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659406, now_ms:18908659486]
2020-11-13T12:48:35.739Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::GetRtcpReceiverReport() | using worst remote fraction lost:1
2020-11-13T12:48:35.787Z mediasoup:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value increase detected, notifying the listener [now:4883200, before:2256327]
2020-11-13T12:48:35.787Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:057732bc-8e40-44a7-af0d-8060f7315a46]
2020-11-13T12:48:35.816Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:35.816Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659600, now_ms:18908659609]
2020-11-13T12:48:35.818Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:6387200, before:8751233]
2020-11-13T12:48:35.842Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659602, now_ms:18908659634]
2020-11-13T12:48:35.860Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]
2020-11-13T12:48:35.868Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659604, now_ms:18908659661]
2020-11-13T12:48:35.892Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659606, now_ms:18908659685]
2020-11-13T12:48:35.902Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:35.914Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Feedback packet [sender ssrc:3225465067, media ssrc:1234]
2020-11-13T12:48:35.917Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:3372235, before:6411332]
2020-11-13T12:48:35.918Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:0, consumerId:2f558f7c-ee12-47bb-b7ea-f20179e2d23c]
2020-11-13T12:48:35.918Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:1, temporal:1, consumerId:b9492849-c070-4ab5-925f-b6363c983090]
2020-11-13T12:48:35.918Z mediasoup:Channel [pid:64] RTC::RtpStreamRecv::RequestKeyFrame() | sending PLI [ssrc:4144548465]
2020-11-13T12:48:35.918Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659608, now_ms:18908659711]
2020-11-13T12:48:35.944Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659610, now_ms:18908659737]
2020-11-13T12:48:35.984Z mediasoup:WARN:Channel [pid:64] webrtc::BitrateProber::TimeUntilNextProbe() | probe delay too high [next_ms:18908659612, now_ms:18908659776]
2020-11-13T12:48:35.996Z mediasoup:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value increase detected, notifying the listener [now:6646347, before:3643014]
2020-11-13T12:48:35.996Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:2f558f7c-ee12-47bb-b7ea-f20179e2d23c]
2020-11-13T12:48:35.996Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:b9492849-c070-4ab5-925f-b6363c983090]
2020-11-13T12:48:36.159Z mediasoup:Channel [pid:64] RTC::Producer::ReceiveRtpPacket() | key frame received [ssrc:4032244796, seq:31933]
2020-11-13T12:48:36.159Z mediasoup:Channel [pid:64] RTC::Producer::ReceiveRtpPacket() | key frame received [ssrc:4144548465, seq:19736]
2020-11-13T12:48:36.159Z mediasoup:Channel [pid:64] RTC::Producer::ReceiveRtpPacket() | key frame received [ssrc:943728671, seq:51023]
2020-11-13T12:48:36.176Z mediasoup:WARN:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value decrease detected, notifying the listener [now:2501578, before:4883200]
2020-11-13T12:48:36.176Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:0, consumerId:057732bc-8e40-44a7-af0d-8060f7315a46]
2020-11-13T12:48:36.179Z mediasoup:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value increase detected, notifying the listener [now:2982000, before:1860797]
2020-11-13T12:48:36.276Z mediasoup:Channel [pid:64] RTC::TransportCongestionControlClient::MayEmitAvailableBitrateEvent() | high BWE value increase detected, notifying the listener [now:5160008, before:2502192]
2020-11-13T12:48:36.276Z mediasoup:Channel [pid:64] RTC::SimulcastConsumer::UpdateTargetLayers() | target layers changed [spatial:2, temporal:1, consumerId:057732bc-8e40-44a7-af0d-8060f7315a46]
2020-11-13T12:48:36.837Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]
2020-11-13T12:48:37.875Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]
2020-11-13T12:48:39.281Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]
2020-11-13T12:48:40.329Z mediasoup:Channel [pid:64] RTC::Transport::HandleRtcpPacket() | no Consumer found for received Receiver Report [ssrc:615232409]

I have very little experience with Macs, hopefully this info is useful. If there is something else I can debug here and provide as an additional info I’m more than happy to do so. I believe it also happens on Windows, but I’m primarily on Linux, so this are the reproduction steps I have so far.

With one client being simulcast and another non-simulcast it still lags on both, so not simulcast-specific.

2

Try the same without simulcast, please.

3

Already tried without simulcast and got the same issue. Then I noticed that new Safari consumes a ton of GPU doing nothing (probably its nice transparency) and that seems to cause preview to lag even in browser window where it is captured (WTF, macOS?).

Closing for now, clearly nothing we can do about this. I still have an issue, but it must be elsewhere.

4

Sometimes rendering process in the browser can be a pain and, indeed, produce delay in video rendering. And it’s not related to RTP arriving later than expected.

5

Hi @nazar-pc,

Feel free to share your findings on this regard here. Definitely rendering GPU over consumption is a common concern.

6

I am running the same MacOS version and my Safari does not consume a lot of GPU as far as I can see in Activity Monitor. But then again I don’t have a lot of transparency and it’s a Macbook Air from 2017. I do experience the de-sync problem from time to time but we have not been able to find a way to reproduce it yet in our testing. We do not use simulcast. We suspect it happens when the producer is temporarily a bit overloaded. It fixes itself after a while but it can definitely take quite a bit, in the order of 1 minute or so.

Is there a way to programatically detect this de-sync situation? We’ll try to add a button to our debug UI to request a keyframe and see if that causes a re-sync.

@nazar-pc have you tried to see if it happens with h264 as well? We’ve seen quite different behavior of browsers depending on the codec. For example with h264 we sometimes get weird green blocking for short periods of times while with VP8 we haven’t seen that so far.

7

I plan to try H264 (which is hardware accelerated on macOS, so I guess should not be an issue, but we’ll see) and also will try to test similarly in Firefox to figure out if this this browser/OS/codec-specific or not.

The key for reproduction seems to be to not have browser window focused, as long as it is focused, I was not able to reproduce significant de-sync, but that was just the scenario that I was able to reproduce myself.

Requesting key frames changes nothing from my testing (with VP8).

Either way this is not something mediasoup can possibly solve as video is sent delayed and is delayed in preview already.