1434353 - Pronounced audio stutter (under-run) in WebRTC calls under load from camera downscaling

Status: RESOLVED DUPLICATE of bug 1434538

(Core :: WebRTC: Audio/Video, defect, P2)

Description

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

STRs:
 1. Establish a WebRTC 1-1 call on https://appear.in/someroom345234 or similar
 2. In a separate (process) tab, open a google doc with something meaty to scroll.
 3. Scroll google doc up and down continuously while talking.

Expected result:
 - Other caller hears you fine (no difference whether scrolling or not).

Actual result:
 - Other caller hears continuous audio stuttering only while scrolling.

Basically, audio is under-running consistently while scrolling a random tab.

Profiling content process for 30-40 seconds shows we're waiting for a Monitor in MediaEngineRemoteVideoSource::NotifyPull for about ~75% of the audio callback (*)

Weight    Self Weight        Symbol Name
26.13 s    1.5%    0 s         plugin-container (40821)
22.13 s    1.2%    0 s          nsThread::ThreadFunc  0x566699
22.13 s    1.2%    0 s           thread_start
22.13 s    1.2%    0 s            _pthread_start
22.13 s    1.2%    0 s             _pthread_body
22.13 s    1.2%    0 s              _pt_root
22.13 s    1.2%    0 s               nsThread::ThreadFunc(void*)
22.13 s    1.2%    0 s                MessageLoop::Run()
22.13 s    1.2%    0 s                 mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)
22.13 s    1.2%    0 s                  NS_ProcessNextEvent(nsIThread*, bool)
22.13 s    1.2%    0 s                   nsThread::ProcessNextEvent(bool, bool*)
22.13 s    1.2%    0 s                    mozilla::ipc::MessageChannel::MessageTask::Run()
22.13 s    1.2%    0 s                     mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&)
22.13 s    1.2%    0 s                      mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&)
22.13 s    1.2%    70.00 ms                       mozilla::camera::PCamerasChild::OnMessageReceived(IPC::Message const&)
22.06 s    1.2%    0 s                        mozilla::camera::CamerasChild::RecvDeliverFrame(mozilla::camera::CaptureEngine const&, int const&, mozilla::ipc::Shmem&&, mozilla::camera::VideoFrameProperties const&)
22.06 s    1.2%    10.00 ms                         non-virtual thunk to mozilla::MediaEngineRemoteVideoSource::DeliverFrame(unsigned char*, mozilla::camera::VideoFrameProperties const&)
22.05 s    1.2%    60.00 ms                          mozilla::MediaEngineRemoteVideoSource::DeliverFrame(unsigned char*, mozilla::camera::VideoFrameProperties const&)
9.60 s    0.5%    0 s                           webrtc::I420Buffer::CropAndScaleFrom(webrtc::VideoFrameBuffer const&, int, int, int, int)
9.60 s    0.5%    0 s                            I420Scale
9.60 s    0.5%    30.00 ms                             ScalePlane
9.57 s    0.5%    150.00 ms                              ScalePlaneBilinearDown
6.24 s    0.3%    6.24 s                               ScaleFilterCols_SSSE3
3.18 s    0.1%    3.18 s                               InterpolateRow_AVX2
4.51 s    0.2%    0 s                           webrtc::ConvertToI420(webrtc::VideoType, unsigned char const*, int, int, int, int, unsigned long,

The code around this lock changed to be held open during the meat of DeliverFrame() in bug 1388219 in 59, which we believe is the regression. That said, I haven't run mozregression yet, but this looks like the problem.

Andreas to take since he's basically fixes this already in bug 1299515, but we need a patch to uplift to 59, hence this issue.

*) Assuming we're reading the seconds column right (the %s are a bit off). I'll attach the profile.
   This was with ☑ Recording Waiting Threads in OSX's Instruments Time Profiler.

Comment 1

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Sorry I had a filter on when doing that dump. Here's the part showing the lock:

Weight	Self Weight		Symbol Name
20.16 s    1.1%	60.00 ms	 	        AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)
19.42 s    1.1%	20.00 ms	 	         AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)
19.40 s    1.1%	10.00 ms	 	          AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)
19.32 s    1.1%	20.00 ms	 	           AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)
19.26 s    1.1%	50.00 ms	 	            audiounit_output_callback(void*, unsigned int*, AudioTimeStamp const*, unsigned int, unsigned int, AudioBufferList*)
19.13 s    1.1%	10.00 ms	 	             passthrough_resampler<float>::fill(void*, long*, void*, long)
19.07 s    1.1%	10.00 ms	 	              mozilla::AudioCallbackDriver::DataCallback(float const*, float*, long)
11.37 s    0.6%	10.00 ms	 	               mozilla::MediaStreamGraphImpl::OneIteration(long long)
9.10 s    0.5%	60.00 ms	 	                mozilla::MediaStreamGraphImpl::UpdateGraph(long long)
4.63 s    0.2%	20.00 ms	 	                 mozilla::SourceMediaStream::PullNewData(long long, nsTArray<RefPtr<mozilla::MozPromise<bool, bool, true> > >&)
4.27 s    0.2%	20.00 ms	 	                  mozilla::MediaStreamListener::AsyncNotifyPull(mozilla::MediaStreamGraph*, long long)
3.62 s    0.2%	10.00 ms	 	                   mozilla::MediaEngineRemoteVideoSource::NotifyPull(mozilla::MediaStreamGraph*, mozilla::SourceMediaStream*, int, long long, nsMainThreadPtrHandle<nsIPrincipal> const&)
2.90 s    0.1%	0 s	 	                    mozilla::detail::MutexImpl::lock()
2.90 s    0.1%	0 s	 	                     _pthread_mutex_lock_wait
2.90 s    0.1%	2.90 s	 	                      __psynch_mutexwait

The numbers are less significant than at first assumed, but 3 seconds waiting on a lock in 30 second run is still bad.

Comment 2

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Updated STRs:
 1. First, open https://jsfiddle.net/jib1/m9gbqqfz/ in a new tab, share cam, and leave it running.
 2. In a second tab, open https://jsfiddle.net/yxbLvjm6/ and share cam; Use headset and talk to hear yourself.
 3. In third tab, open a google doc with something meaty to scroll.
 4. Scroll google doc up and down continuously while talking.

Expected: no audio stutter, actual: audio stutter.

After I had trouble reproing comment 0 in a new Firefox instance, I noticed DeliverFrame in comment 0 was calling CropAndScaleFrom() [1], which it shouldn't be doing. That code-path should only run when there's concurrent simultaneous camera access. It's downscaling every camera frame from the camera resolution to a lower requested resolution, so that's a significant difference in overhead.

I've verified on a clean (different profile) instance this doesn't happen normally:

Weight	Self Weight		Symbol Name
119.00 ms    0.5%	1.00 ms	 	                non-virtual thunk to mozilla::MediaEngineRemoteVideoSource::DeliverFrame(unsigned char*, mozilla::camera::VideoFrameProperties const&)
118.00 ms    0.5%	0 s	 	                 mozilla::MediaEngineRemoteVideoSource::DeliverFrame(unsigned char*, mozilla::camera::VideoFrameProperties const&)
114.00 ms    0.4%	1.00 ms	 	                  mozilla::layers::SharedPlanarYCbCrImage::CopyData(mozilla::layers::PlanarYCbCrData const&)

This suggests something is broken in CamerasParent's logic around what different-constraint camera requests are outstanding (it appears stuck in downscale mode).

Anyway, the new STRs above adds a second fiddle that opens the camera in two different resolutions, forcing downscaling, which seems to add enough load to trigger the audio stutter, and I can repro it now.

[1] https://searchfox.org/mozilla-central/rev/97cb0aa64ae51adcabff76fb3b5eb18368f5f8ab/dom/media/webrtc/MediaEngineRemoteVideoSource.cpp#489,515

Comment 3

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Much simpler STRs: https://jsfiddle.net/jib1/nhpy67as/

Comment 4

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Regression range from comment 3 points to a more recent regression for the stutter: bug 1370598.

106:23.72 INFO: Last good revision: f77e243145f2c08e6f7ba4f086400e874aad9463
106:23.72 INFO: First bad revision: f745765d92c46e5b257ea48470bf02fcf691a7da
106:23.72 INFO: Pushlog:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=f77e243145f2c08e6f7ba4f086400e874aad9463&tochange=f745765d92c46e5b257ea48470bf02fcf691a7da

I've opened bug 1434439 about the unnecessary camera downscaling in comment 2 and earlier.

Comment 5

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Andreas, this noise turned out to be OSX related. Please open a new bug if you still think it's important to uplift your fix in bug 1299515, for the DeliverFrame mutex regression.

I know I heard noise from your end this morning, but I replicated it in another 1-1 today and noticed it was tied to me moving things on my end, not the other persons end, so I don't think this was happening on your end (linux) after all.

Comment 6

[Andreas Pehrson [:pehrsons]]

(In reply to Jan-Ivar Bruaroey [:jib] (needinfo? me) from comment #4)
> Regression range from comment 3 points to a more recent regression for the
> stutter: bug 1370598.
> 
> 106:23.72 INFO: Last good revision: f77e243145f2c08e6f7ba4f086400e874aad9463
> 106:23.72 INFO: First bad revision: f745765d92c46e5b257ea48470bf02fcf691a7da
> 106:23.72 INFO: Pushlog:
> https://hg.mozilla.org/integration/autoland/
> pushloghtml?fromchange=f77e243145f2c08e6f7ba4f086400e874aad9463&tochange=f745
> 765d92c46e5b257ea48470bf02fcf691a7da
> 
> I've opened bug 1434439 about the unnecessary camera downscaling in comment
> 2 and earlier.

Your STR is clearly pointing to video as being the reason for this stutter.

The regression find looks like something that would have made a machine more susceptible to hitting the path causing the stutter. But there are many variables involved there, including sampling frequency and macbook model. I wouldn't have expected your Macbook Pro to be affected by that change.

Comment 7

[Paul Adenot (:padenot)]

jib, as Andreas says, my patch makes the bug more obvious, and is the right thing to do, in any case. If we lack time to patch 59, I can uplift a backout.

We should work on a fix for this webcam madness as soon as possible, it should not have gone in in the first place.

Comment 9

[Liz Henry (:lizzard) (relman/hg->git project)]

Fixed in 59/60 in the duplicate.