1497932 - air.mozilla.com real-time stream playback blips created by web content process consumption

Status: RESOLVED FIXED

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

Description

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

It's a common process for me to open an air.mozilla.org stream on my machine and then move over to another window/tab to continue working while I listen to the airmo session.

However, I've experienced issues in the past with playback using normal browsing behavior in another window/tab, which causes the airmo window/tab to blip and/or have issues with streaming.

Reproduction Steps:

1.) Join an airmo live meeting, it will create the stream in a new window
2.) Revisit origin browser tab group, and then just refresh the tabs every few secs
3.) You should see blips in audio stream from the streaming video

Suspicion:

I believe it's likely that Firefox is bound by only a specific set of web content processes (I understand that these help process and render web content) and if memory serves this is limited to 4 at a time.  If I want my activity monitor while refreshing tabs, if we can get it up to 4 web content processes, I can easily reproduce this on Nightly on my Mac.

Comment 1

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

Attachment: Screen_Shot_2018-10-22_at_2_15_24_PM.png

I opened console today and noticed the following AbortError messages that lined up with each blip, I tried expanding them, with no luck or additional context.

Comment 2

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

Another suggestion of possible source issue proposed by :atoll was maybe this is some sort of energy consumption or performance optimization type bug, and I wanted to throw that in there as a possible "what if".

Comment 3

[:Atoll]

I can reproduce this issue simply by opening a live video in a tab and then opening and using another tab and maybe leaving Firefox in the background. No addons or extensions are required.

Comment 4

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

Does anyone know of a means to provide more insight into where these DOM AbortError exceptions are sourcing from?  I'd be happy to provide that additional detail if it helps further the investigation of this issue.

Comment 5

[Nils Ohlmeier [:drno]]

(In reply to Jonathan Claudius [:claudijd] (use NEEDINFO) from comment #4)
> Does anyone know of a means to provide more insight into where these DOM
> AbortError exceptions are sourcing from?  I'd be happy to provide that
> additional detail if it helps further the investigation of this issue.

From searching in our code: https://searchfox.org/mozilla-central/search?q=symbol:E_%3CT_mozilla%3A%3ABaseMediaMgrError%3A%3AName%3E_AbortError&redirect=false

Assuming you are refreshing the air.mozilla.org tab then it seems most likely to me that the page for what ever reason calls EnumerateDevices and that gets interrupted through you page refreshes.

Jib: any thoughts on this?

Comment 6

[:Atoll]

I wasn't refreshing the tab, and was able to trigger audio/video hiccups with the same error message _exclusively_ when the tab was backgrounded. The hiccups self-resolved when the tab was brought to the foreground and resumed shortly (a minute or less) after the tab was sent to the background.

Looking at searchfox, we ought to have seen some log entries. Where would they have been logged?


https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#3111 —

    LOG(("GetUserMedia: post enumeration promse2 failure callback called!"));

I saw no such log in the Web Console, anyways, but maybe it's not written there?


https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#3260 —

Huh. This one is missing a log *and* specifically returns this _exact_ error _if_ the window is no longer active:

    if (!mgr->IsWindowStillActive(aWindowId)) {
      nsPIDOMWindowInner* window =
        nsGlobalWindowInner::GetInnerWindowWithId(aWindowId)->AsInner();
      return MediaDeviceSetPromise::CreateAndReject(
          MakeRefPtr<MediaStreamError>(window, MediaStreamError::Name::AbortError), __func__);
    }


https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#3281

And another one, where inactive window leads to AbortError without a LOG entry, along with an explicit comment indicating that it should halt if inactive:

      // Only run if window is still on our active list.
      MediaManager* mgr = MediaManager::GetIfExists();
      if (!mgr || !mgr->IsWindowStillActive(aWindowId)) {
        nsPIDOMWindowInner* window =
          nsGlobalWindowInner::GetInnerWindowWithId(aWindowId)->AsInner();
        return MediaDeviceSetPromise::CreateAndReject(
            MakeRefPtr<MediaStreamError>(window, MediaStreamError::Name::AbortError), __func__);
      }

https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#3305

And a third, again terminating inactive:

      if (!mgr->IsWindowStillActive(aWindowId)) {
        nsPIDOMWindowInner* window =
          nsGlobalWindowInner::GetInnerWindowWithId(aWindowId)->AsInner();
        return MediaDeviceSetPromise::CreateAndReject(
            MakeRefPtr<MediaStreamError>(window, MediaStreamError::Name::AbortError), __func__);
      }


https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#3320

This one cares about enumeration, but I can't say where NS_WARNING would be logged to in order to tell whether it's this line of code:

  [aWindowId](nsresult rs) {
    NS_WARNING("EnumerateDevicesImpl failed to get Principal Key. Enumeration will not continue.");
    nsPIDOMWindowInner* window =
      nsGlobalWindowInner::GetInnerWindowWithId(aWindowId)->AsInner();
    return MediaDeviceSetPromise::CreateAndReject(
        MakeRefPtr<MediaStreamError>(window, MediaStreamError::Name::AbortError), __func__);
  });


https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#3946

Seems unlikely that the task is shutting down, since it resumes working the instant you switch back to the tab. Where would NS_LITERAL_STRING end up being logged to verify whether it's present?

    if (sHasShutdown) {
      return task->Denied(MediaMgrError::Name::AbortError,
                          NS_LITERAL_STRING("In shutdown"));
    }

https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#4330

This one would write out "Starting audio failed" if that were the case, but I'm not sure where. That said, audio works fine when the tab is foreground, and resumes without a tab reload just by going back to it.

          log.AssignLiteral("Starting audio failed");
          aHolder.Reject(MakeRefPtr<MediaMgrError>(
                MediaMgrError::Name::AbortError, log), __func__);
          return;


https://searchfox.org/mozilla-central/source/dom/media/MediaManager.cpp#4348

This one would write out "Starting video failed", see also previous.

          log.AssignLiteral("Starting video failed");
          aHolder.Reject(MakeRefPtr<MediaMgrError>(MediaMgrError::Name::AbortError, log), __func__);


So just having tried to debug this, I immediately have a question:

What conditions lead to IsWindowStillActive being false?

Comment 7

[:Atoll]

The next time a stream is live, I will try fiddling with DOM budget settings, since that seems like exactly the sort of thing that would help cause this:

https://hg.mozilla.org/integration/mozilla-inbound/rev/0ee4714539c2

Comment 8

[Nils Ohlmeier [:drno]]

(In reply to Atoll R. Soderberg  [:atoll, :rsoderberg] from comment #7)
> The next time a stream is live, I will try fiddling with DOM budget
> settings, since that seems like exactly the sort of thing that would help
> cause this:
> 
> https://hg.mozilla.org/integration/mozilla-inbound/rev/0ee4714539c2

That is a very good idea.

We do have some code which is suppose to stop rendering video if the window is no longer visible AFAIK. But that should not affect the audio. So throttling background things appears very plausible.

BTW is this on certain platforms only or across all platforms?

Comment 9

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

(In reply to Nils Ohlmeier [:drno] from comment #8)
> BTW is this on certain platforms only or across all platforms?

I can confirm this on Nightly on MacOSX

Comment 10

[:Atoll]

Nightly on macOS 10.14.1 Beta for me.

Comment 11

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

(In reply to Nils Ohlmeier [:drno] from comment #5)
> Assuming you are refreshing the air.mozilla.org tab then it seems most
> likely to me that the page for what ever reason calls EnumerateDevices and
> that gets interrupted through you page refreshes.
> 
> Jib: any thoughts on this?

This might like fallout from bug 1088621. Alex, can you take a look?

Comment 12

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

(In reply to Atoll R. Soderberg  [:atoll, :rsoderberg] from comment #6)
> Looking at searchfox, we ought to have seen some log entries. Where would
> they have been logged?

These logs can be enabled by setting MediaManager:4 in MOZ_LOG or about:networking#logging 

> This one cares about enumeration, but I can't say where NS_WARNING would be
> logged to in order to tell whether it's this line of code:

NS_WARNING I believe goes to stderr? But with multiple content processes, who knows. I agree with Nils this is likely enumerateDevices. I'm assuming none of these air mozilla pages involve camera or mic?

Comment 13

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

(In reply to Jan-Ivar Bruaroey [:jib] (needinfo? me) from comment #12)
> ... I'm assuming
> none of these air mozilla pages involve camera or mic?

In my experience with this bug, it's always been viewing a weekly/monthly/quarterly AirMo meeting where I'm basically in read-only mode, with no active Mic/Camera.

Comment 14

[:Atoll]

Same. It’s never even asked for those permissions as a viewer.

Comment 15

[:Atoll]

(In reply to Jan-Ivar Bruaroey [:jib] (needinfo? me) from comment #12)
> These logs can be enabled by setting MediaManager:4 in MOZ_LOG or
> about:networking#logging 

https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging#Mac_OS_X will be invaluable for those of you trying to work out (like me) how MOZ_LOG works. I was not able to figure out how to use about:networking#logging for this purpose.

> > This one cares about enumeration, but I can't say where NS_WARNING would be
> > logged to in order to tell whether it's this line of code:
> 
> NS_WARNING I believe goes to stderr? But with multiple content processes,
> who knows. I agree with Nils this is likely enumerateDevices. I'm assuming
> none of these air mozilla pages involve camera or mic?

The above process (./firefox-bin) will also, coincidentally, make it possible to discover any NS_WARNING logs emitted here. This is a very clumsy set of steps — most users will not be able to participate in this diagnostic process. Hopefully I'll be able to find it myself during today's broadcast.

Comment 16

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

Attachment: Screen_Shot_2018-10-29_at_2_12_16_PM.png

Was able to trigger this reliably by viewing the project meeting, refreshing other pages while this page was backgrounded.  Each sound blip lined up with the AbortError.

Comment 17

[:Atoll]

:drno, :jib, :claudijd — are any/all of you available on Friday? The Airmo team can set up a diagnostics-testing live stream using the Project Meeting infrastructure, so that we can reproduce this problem with engineers available to help guide the diagnostics and confirm the issue, but I'm not sure who to invite for that (or if willingness exists at all).

Comment 18

[Alex Chronopoulos [:achronop]]

It would be nice to know how the read-only view is implemented in AirMozilla. Maybe we can extract some information by obtaining logs. In order to do that 

1. open the terminal
2. export MOZ_LOG="MediaManager:4,MediaDecoder:4,AudioStream:4"
3. navigate to the folder that the firefox binary lives, in my case this is /Applications/NightlyFirefox/Contents/MacOS
4. Run firefox from there

Logs will appear on the screen, please copy/paste to a file and attach.

Comment 19

[:Atoll]

I captured them to a file, and I also included nsHttp and sockets and such. No STDERR logs about devices were written, but there were hundreds of instances of the child thread reporting that it was trying to 'seek' (which is odd, since it doesn't need to when it's foreground), implying that somehow it fell behind the stream. So I looked in the main thread for throttling logs and found hundreds of instances of:

    Socket Thread]: V/nsHttp nsHttpTransaction::WriteSegments 0x12d53d000 response throttled

I set network.http.throttle.enable=false and restarted Nightly and am no longer having trouble viewing a stream with both the tab not focused and with Nightly in the background on my Mac.

Comment 20

[Alex Chronopoulos [:achronop]]

Attachment: bug1497932_MediaManager_MediaDecoder_AudioStream_logs.txt

I am attaching here the log I have obtained. I manage to repro when I navigate around in my personal gmail tab, especially when I press the refresh button. I haven't had a careful look at them yet but it looks like a playback case.

Comment 21

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

FYI, NS_WARNING is a no-op on non-debug builds: https://searchfox.org/mozilla-central/rev/fc3d974254660b34638b2af9d5431618b191b233/xpcom/base/nsDebug.h#128


As for content processes, today I was getting a lot of short audio cutouts with dom.ipc.processCount set to 64 (and I verified with about:memory that the onlinexperiences window wasn't sharing a process with anything besides the captioning), so this bug's summary may not be accurate.

But I also had some of those problems while the airmo popup window was focused; I don't know if that means I'm seeing a different problem from this one, or if that might reflect an earlier failure to download media, or something else.  (I didn't keep it focused, because I was also watching the backchannel.)  I did see a lot of AbortError messages in the console.

Comment 22

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

(In reply to Jed Davis [:jld] (⏰UTC-6) from comment #21)
> ...this bug's summary may not be accurate.

100% agree, was a starting point, though we've evolved the discussion/understanding since.  If someone with more detailed understanding of the probelm this could articulate a better subject I think that would be helpful.

Comment 23

[Jonathan Claudius [:claudijd] (use NEEDINFO)]

FWIW, this appears to affect both nightly and release, both of which seem to be using network.http.throttle.enable:true

Comment 25

[:Atoll]

To summarize the final disposition of this issue:

In bug 1503354 we disabled HTTP request throttling for Nightly and Beta channels. Anyone experiencing this specific issue — AirMozilla live streams in a backgrounded tab in Firefox stalls — should verify in about:config that network.http.throttle.enable is set to false.

If that config is _not yet_ set to false, then please set it to false and restart Firefox to resolve the known issue here.

If it is _already_ set to false, then this bug is not the cause of issue you're experiencing; please open a new bug.


n? :drno for final disposition triage (RESOLVED of some fashion).

Comment 26

[:Atoll]

Or.. BMO decided to apply RESO FIXE even though I reloaded the tab to clear that out, so never mind.

Comment 27

[Nils Ohlmeier [:drno]]

(In reply to :Atoll from comment #26)
> Or.. BMO decided to apply RESO FIXE even though I reloaded the tab to clear
> that out, so never mind.

Works for me :-)

Comment 28

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/treeherder/pull/6035

Comment 29

[Sarah Clements [:sclements] | PTO until Sept 15th]

Apologies - typo on the bug number so it was linked here. ^ I'm unable to mark it as obsolete.