getUserMedia with processing causes assertion in MediaEngineWebRTCAudio.cpp

RESOLVED FIXED in Firefox 63

Status

()

defect
P2
normal
RESOLVED FIXED
Last year
Last year

People

(Reporter: bryce, Assigned: pehrsons)

Tracking

unspecified
mozilla63
Unspecified
Linux
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox63 fixed)

Details

Attachments

(2 attachments)

After the changes in bug 1404977 I reliably hit an assertion[0] after calling getUserMedia with if any one or more of echoCancellation, autoGainControl, and noiseSuppression are enabled.

STR:
- Navigate to https://codepen.io/SingingTree/pen/yjaRzv
- Check 1 or more of the AEC, AGC, NC check boxes.
- Click the New gUM Request button and accept the gUM prompt
- The assert is immediately hit

The issue occurs in a VMWare VM, and happen if I select microphone or monitor of sound-card in gUM. Both these devices are being exposed to the VM by VMWare from the host computer (A Lenovo P51). If I select the 'Monitor of Null Output' device used by our tests the assertion is not hit.

If I enable logging it appear that I'm getting double appends of packetized audio, e.g. I see the following in the log:
>> V/MediaManager Appending 441 frames of packetized audio for allocation 0x7fb0f0954c00
>> V/MediaManager Appending 441 frames of packetized audio for allocation 0x7fb0f0954c00
>> V/MediaManager NotifyPull, desired = 2176
>> V/MediaManager Pulling 270 frames of silence for allocation 0x7fb0f0954c00

This seems odd, but I'm not so familiar with this area to be sure if this is related. Please see attached log for a more complete example.

[0]: https://searchfox.org/mozilla-central/rev/e52cd92858800a69b74cb97d26d9bdb960d611ca/dom/media/webrtc/MediaEngineWebRTCAudio.cpp#835
jib do you have any idea if what bryce sees here is harmless or a serious issue?
Flags: needinfo?(jib)
Priority: -- → P2
Hard to say. Andreas last touched this code, so lateraling the ni? to him.
Flags: needinfo?(jib) → needinfo?(apehrson)
When hitting it that early it's usually harmless and more of a flaw in the logic building up the assert than in the logic the assert is checking.

It has proven hard to get this assert stable, but it can detect serious buffering issues so we don't want to get rid of it either. As long as I can catch it in rr I can at least improve stability.


(In reply to Bryce Seager van Dyk (:bryce) from comment #0)
> If I enable logging it appear that I'm getting double appends of packetized
> audio, e.g. I see the following in the log:
> >> V/MediaManager Appending 441 frames of packetized audio for allocation 0x7fb0f0954c00
> >> V/MediaManager Appending 441 frames of packetized audio for allocation 0x7fb0f0954c00
> >> V/MediaManager NotifyPull, desired = 2176
> >> V/MediaManager Pulling 270 frames of silence for allocation 0x7fb0f0954c00
> 
> This seems odd, but I'm not so familiar with this area to be sure if this is
> related. Please see attached log for a more complete example.

The two pushes of packetized audio are most likely from two different callbacks. That wouldn't be odd.
Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Flags: needinfo?(apehrson)
See Also: → 1480161
I wasn't able to repro with any of my mics as input device, but I was able to repro using a monitor for input. Under rr too, so let me dig into it.
Ok so the logic accounting for an initial block of 128 frames is working, but we fail the assert once we've put more than 128 frames in the input packetizer. We need to allow for another 10ms of silence as that's how much the input packetizer can sit on before passing data on to processing and ultimately our input track to avoid another pull of silence.
(In reply to Andreas Pehrson [:pehrsons] from comment #3)
> When hitting it that early it's usually harmless and more of a flaw in the
> logic building up the assert than in the logic the assert is checking.
> 
> It has proven hard to get this assert stable, but it can detect serious
> buffering issues so we don't want to get rid of it either. As long as I can
> catch it in rr I can at least improve stability.
> 
> 
> (In reply to Bryce Seager van Dyk (:bryce) from comment #0)
> > If I enable logging it appear that I'm getting double appends of packetized
> > audio, e.g. I see the following in the log:
> > >> V/MediaManager Appending 441 frames of packetized audio for allocation 0x7fb0f0954c00
> > >> V/MediaManager Appending 441 frames of packetized audio for allocation 0x7fb0f0954c00
> > >> V/MediaManager NotifyPull, desired = 2176
> > >> V/MediaManager Pulling 270 frames of silence for allocation 0x7fb0f0954c00
> > 
> > This seems odd, but I'm not so familiar with this area to be sure if this is
> > related. Please see attached log for a more complete example.
> 
> The two pushes of packetized audio are most likely from two different
> callbacks. That wouldn't be odd.

When I was hitting this I got the same double-appends, and they turned out to be from the same callback. This was because I was getting callbacks of 896 frames at 44100Hz and processing happens in packets of 10ms. 896 frames is more than 20ms so we iterated over the PacketizeAndProcess code twice per callback until we came around with a full packet from all the spillover parts (every ~32 callbacks). Then we'd process three packets and before iterating the graph. Rinse and repeat..
Comment on attachment 8997893 [details]
Bug 1480856 - Allow for another 10ms of silence when processing audio input. r?achronop

Alex Chronopoulos [:achronop] has approved the revision.

https://phabricator.services.mozilla.com/D2786
Attachment #8997893 - Flags: review+
Tested applying the patch and am no longer hitting the assert.
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/b118b720b2c7
Allow for another 10ms of silence when processing audio input. r=achronop
https://hg.mozilla.org/mozilla-central/rev/b118b720b2c7
Status: ASSIGNED → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
Duplicate of this bug: 1478381
You need to log in before you can comment on or make changes to this bug.