1274653 - Mismatched input/output audio HW sample rates on mac cause delay in full_duplex

Status: RESOLVED FIXED

(Core :: Audio/Video: cubeb, defect, P1)

Description

[Justin Dolske [:Dolske]]

Attachment: aeclogs.tgz

Last week Jared and I tried using Hello and a 3rd party WebRTC site for our 1:1, but the lag was intolerable. We were both seeing 15+ seconds of delay between saying something and other side seeing or hearing it. We were able to work around the problem by using Chrome.

We did some more testing this morning, and were able to reproduce the problem again:

Test 1: Both of us on Nightly, Jared sharing with Hello. Terrible lag, and my audio was out of sync with my video.

Test 2: I switched to Chrome. Everything ok.

Test 3: Both of us on Nightly, I'm sharing my screen with Hello. Terrible lag.

Test 4: Jared switched to Chrome. Terrible lag.

So, looks like the problem is on my end. 


Did some testing with Nils, and we were also able to reproduce the problem.

When I used Nightly or DevEdition, there was terrible lag. When I used Firefox Release or Beta, it worked fine. 

Attached are the AEC logs from about:webrtc when Nils and I were testing in Nightly. (I have two sets, I wasn't sure if I had started the logging initially so did a start/stop again.)

Comment 1

[Nils Ohlmeier [:drno]]

Attachment: drno-dolske-aec.tar.bz2

AEC logs from drno's side of the call.

Comment 2

[Nils Ohlmeier [:drno]]

On my end:
- MacBook Pro with 10.11.5
- I was using head phones and the build in mic
- Justin was completely hands free

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

Note: flipping full_duplex didn't affect it apparently

Comment 4

[Justin Dolske [:Dolske]]

Attachment: whatever.txt.child-1.gz

NSPR logging from a separate session:

NSPR_LOG_MODULES=mediamanager:4,getusermedia:5,signaling:4,webrtc_trace:65535 WEBRTC_TRACE_FILE=nspr NSPR_LOG_FILE=whatever.txt

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

Ok.  Got to the bottom of this on IRC.  

It is full_duplex (on mac). The problem can be seen in https://mozilla.github.io/webrtc-landing/gum_test.html

The issue is that the default mic rate is 44100, and his default speakers were set to 48000.  Delay was growing at roughly 5 sec/minute, which matches  48000/44100.

https://support.apple.com/en-us/HT202968
http://www.macobserver.com/tmo/article/audio-midi-setup-your-macs-secret-sound-manager

shows how to monitor it and change it.  drno and I (and most macbookpro's I believe) default to 44100 for input and output.  If they don't match, bad things happen.  44100/44100 and 48000/48000 are both delay-free for me, 44100/48000 -> quickly increasing delay; 5s/m

Paul - perhaps the assumptions about full-duplex guaranteeing rate conversion on mac was wrong

Comment 6

[Paul Adenot (:padenot)]

It does guarantee rate conversion on output, not on input. We're using a resampler on input, but maybe there is a bug with that, Alex will know what to do I think.

Comment 7

[Alex Chronopoulos [:achronop]]

The problem is that input and output thread operate for different rate which cause more output requests than input. The way that we used to handle the input hole was to push some silent and that was added to the existing delay of the input. 

I will change the input hole handling and I am working with padenot to protect from increasing buffering inside the resampler.

Comment 8

[Alex Chronopoulos [:achronop]]

Attachment: mismatched-resampler-example.patch

This is an example that shows what info we need from resampler. It is a test patch not intended to be landed.

Comment 9

[Alex Chronopoulos [:achronop]]

Attachment: mismatched-gum-log.txt

This is the logs when gum test is executed with the patch above applied.

Comment 10

[Alex Chronopoulos [:achronop]]

I attached a patch showing and example of how we could change the resampler to provide info enough to handle this error. This is only an example and I am expecting more discussion on the approach that we should follow.

@jesup, @padenot. I need info just to ping you to have a look. Feel free to clear the flag without further explanation.

Comment 11

[Paul Adenot (:padenot)]

Comment on attachment 8755912 [details] [diff] [review]
mismatched-resampler-example.patch

Review of attachment 8755912 [details] [diff] [review]:
-----------------------------------------------------------------

Maybe it's just best to delay the input by one buffer and keep the resampler abstraction clean. Can you try this?

Comment 12

[Alex Chronopoulos [:achronop]]

I can but I am not sure if will solve the problem in long term. Imaging that you may have a long talk for many minutes or hours, the delayed input will be consumed very early in the call and after that buffering will continue, increasing the delay.

The problem I see is that as soon as we use the resampler it is impossible to tell if any buffered data exist, or how much it is, in order to consume it when you can. You can only call the fill method, hoping that your frame number is big enough not to hit the assert and small enough not to cause buffering. That's a limitation in general.

Comment 13

[Alex Chronopoulos [:achronop]]

Another idea is to supply resampler with input outside of fill method and to be able to call the resampler without providing input buffer. Something like

resampler_add_input(resampler, input_buffer, input_frame_count) <-- when input available
resampler_fill(resampler, output_buffer, output_frames_needed) <-- use existing input

Input will be taken internally by resampler in the same way that it already does it.

We can also keep the existing functionality and add the above in order to maintain compatibility with the existing implementations and offer two options on client.

One issue that remains is how to get inform that resampling failed. Right now we get informed about failure by hitting an assert. But resampling can fail for a number of valid scenarios like plugin/unplugin devices or due to in/out rate differences at the beginning of the call. Since there is no way to test it before fill method is called we need to provide an error able to be handled by the client.

Comment 14

[Paul Adenot (:padenot)]

This is now fixed on central, please check tomorrow's nightly !