1463001 - Streaming stutters (audio/video) on Linux with remoting enabled

Status: RESOLVED FIXED

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

Description

[Michele Ballabio]

On any web page with either audio/video streaming (for example: twitter, youtube...) the media is not playing fluently, but it stutters. It's not a caching problem and it happens even with audio-only and small media (mp3 and low-resolution videos), and even when the media is not playing full-screen. It happens on new profiles as well.

It happens in v60 and nightly, not in v59. I tried a bisection with mozregression, but I'm not sure I can trust the results since when I run:

mozregression --good 59 --bad 60

I test the first version and it's a bad one, so mozregression says:

**********
You should use a config file. Please use the --write-config command line flag to help you create one.
**********

0:00.76 INFO: Using date 2018-03-12 for release 60
0:00.76 INFO: Using date 2018-01-22 for release 59
0:04.82 INFO: Testing good and bad builds to ensure that they are really good and bad...
0:04.82 INFO: Downloading build from: https://archive.mozilla.org/pub/firefox/nightly/2018/01/2018-01-22-22-02-31-mozilla-central/firefox-60.0a1.en-US.linux-i686.tar.bz2
===== Downloaded 100% =====
2:27.28 INFO: Running mozilla-central build for 2018-01-22
3:15.48 INFO: Launching /tmp/tmpSXKnPn/firefox/firefox
3:15.48 INFO: Application command: /tmp/tmpSXKnPn/firefox/firefox -profile /tmp/tmpUxZGQs.mozrunner
3:15.48 INFO: application_buildid: 20180122220231
3:15.48 INFO: application_changeset: 20e194b34185de3009453b87f637daa5f432f74b
3:15.48 INFO: application_name: Firefox
3:15.48 INFO: application_repository: https://hg.mozilla.org/mozilla-central
3:15.48 INFO: application_version: 60.0a1
Was this nightly build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry' or 'exit' and press Enter): bad
5:46.66 ERROR: Build was expected to be good! The initial good/bad range seems incorrect.


... so I tried the bisection with older versions. I did:

mozregression --good 57 --bad 60

And it ended with:

40:56.16 INFO: Narrowed inbound regression window from [5cfc67d6, c5ee99a2] (3 builds) to [5cfc67d6, 64cecfd3] (2 builds) (~1 steps left)
40:56.16 INFO: No more inbound revisions, bisection finished.
40:56.16 INFO: Last good revision: 5cfc67d643e09d054856546a18414177f4dcab67
40:56.16 INFO: First bad revision: 64cecfd341a1ff9375316d3b3565124def78f257
40:56.16 INFO: Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=5cfc67d643e09d054856546a18414177f4dcab67&tochange=64cecfd341a1ff9375316d3b3565124def78f257


Then I tried reverse-applying those patches to firefox-60.0.1, but none applies anymore.
I tried firefox-nightly and the problem remains.
So to recap: firefox-59.0.3: good, but on mozregression v59 is bad. firefox-60 and nightly are bad.

'top' shows the firefox process uses 35% of cpu in v60 vs 8% of cpu in v59.

Comment 1

[Jean-Yves Avenard [:jya]]

mozregression tests nightly release, which had the audio ipc code enabled. But not on release.

Comment 2

[Karl Tomlinson (:karlt)]

(In reply to Jean-Yves Avenard [:jya] from comment #1)
> mozregression tests nightly release, which had the audio ipc code enabled.
> But not on release.

What is not on release?

https://hg.mozilla.org/releases/mozilla-release/annotate/FIREFOX_60_0_RELEASE/modules/libpref/init/all.js#l665

Comment 3

[Matthew Gregan [:kinetik]]

(In reply to Michele Ballabio from comment #0)
> On any web page with either audio/video streaming (for example: twitter,
> youtube...) the media is not playing fluently, but it stutters. It's not a
> caching problem and it happens even with audio-only and small media (mp3 and
> low-resolution videos), and even when the media is not playing full-screen.
> It happens on new profiles as well.

In a current nightly, do you hear this issue if you toggle the pref media.cubeb.sandbox to false?

> 'top' shows the firefox process uses 35% of cpu in v60 vs 8% of cpu in v59.

What CPU model do you have in the machine where you hear this issue?

Comment 4

[Jean-Yves Avenard [:jya]]

(In reply to Karl Tomlinson (:karlt) from comment #2)
> (In reply to Jean-Yves Avenard [:jya] from comment #1)
> > mozregression tests nightly release, which had the audio ipc code enabled.
> > But not on release.
> 
> What is not on release?
> 
> https://hg.mozilla.org/releases/mozilla-release/annotate/
> FIREFOX_60_0_RELEASE/modules/libpref/init/all.js#l665

Context, The OP talks about mozregression not showing the problem on 59, as such my comment is about 59

Comment 5

[Michele Ballabio]

(In reply to Matthew Gregan [:kinetik] from comment #3)
> (In reply to Michele Ballabio from comment #0)
> > On any web page with either audio/video streaming (for example: twitter,
> > youtube...) the media is not playing fluently, but it stutters. It's not a
> > caching problem and it happens even with audio-only and small media (mp3 and
> > low-resolution videos), and even when the media is not playing full-screen.
> > It happens on new profiles as well.
> 
> In a current nightly, do you hear this issue if you toggle the pref
> media.cubeb.sandbox to false?

I tried on 60.0.1 and it seemed to fix the issue for the currently streaming tab, but then the audio stopped completely. Then I tried to set media.cubeb.sandbox back to true, but it had no effect (still no audio). Then I closed and reopened Firefox, and the audio was back (as was the stuttering).

So now I tried setting media.cubeb.sandbox to false and then restart Firefox, and it seems to work fine, both on v60.0.1 and nightly.

> > 'top' shows the firefox process uses 35% of cpu in v60 vs 8% of cpu in v59.
> 
> What CPU model do you have in the machine where you hear this issue?

This is on an AMD Ryzen 5 1600 box, 32-bit Linux.

Comment 6

[Matthew Gregan [:kinetik]]

Thanks for testing that.  Sorry, I forgot to mention that you must restart Firefox when you change media.cubeb.sandbox.

35% CPU over 6 cores is just over 2 full cores at 100%, potentially.  If you run top with -H it'll show the individual threads.  I'd be curious to know which threads are showing high CPU use during the stuttering; I'm wondering if we're hitting a bug that's causing us to spin a thread at 100% CPU core.  Would you mind posting a screenshot of 'top -H'?

Could you also attach the result of running 'pacmd list' to dump the PulseAudio state.  It's best to run this command while reproducing the stuttering to capture the current state of PA.

Comment 7

[Michele Ballabio]

Attachment: top-pacmd.zip contains the outputs of 'top -H -b' and 'pacmd list' both with media.cubeb.sandbox enabled (i.e. with bug) and disabled (no bug)

Comment 8

[Michele Ballabio]

(In reply to Matthew Gregan [:kinetik] from comment #6)
> Thanks for testing that.  Sorry, I forgot to mention that you must restart
> Firefox when you change media.cubeb.sandbox.
> 
> 35% CPU over 6 cores is just over 2 full cores at 100%, potentially.

No, 35% is about 1/3 of a single core: I reported those numbers not as an
absolute measure, but as a comparison versus the status quo, just to give
a possible hint to discover the cause of the issue.

> If you
> run top with -H it'll show the individual threads.  I'd be curious to know
> which threads are showing high CPU use during the stuttering; I'm wondering
> if we're hitting a bug that's causing us to spin a thread at 100% CPU core. 
> Would you mind posting a screenshot of 'top -H'?
> 
> Could you also attach the result of running 'pacmd list' to dump the
> PulseAudio state.  It's best to run this command while reproducing the
> stuttering to capture the current state of PA.

I've attached the outputs of 'top -H -b' and 'pacmd list', with and without the
stuttering. I've opened only a youtube page and let it play for a while, so
the two outputs should be comparable. Both are on v60.0.1.

Comment 9

[Matthew Gregan [:kinetik]]

Thanks for that info and your help.  How long did you run top for?  It might need to sample for 10s or more to get a stable snapshot.  In the "bug" version, the Compositor is fairly high, which shouldn't be affected by the AudioIPC stuff at all, so just wondering if that's a random spike or a real clue.

I notice Firefox is requesting a latency of 25ms from PulseAudio.  The audio remoting should handle that, since we request values as low as 11ms for WebRTC related stuff and expect that to work.  But for playback streams, we default to 100ms, so that's a bit unusual to see 25ms.  Do you have any media/audio prefs set to non-default values?  Specifically, media.cubeb_latency_playback_ms, or any other media.cubeb* prefs?

From the top snapshots, I don't expect the audio threads to be starving.  A bit higher overhead for audio remoting is expected, for now.  So that suggests the audio threads could be waiting on a lock or something strange with process scheduling.

One more experiment I'd like you to try, please, is: in a current nightly is to create the integer pref media.audioipc.pool_size and set it to 6, then restart and see if the issue is reproducible.

Comment 10

[Michele Ballabio]

(In reply to Matthew Gregan [:kinetik] from comment #9)
> Thanks for that info and your help.  How long did you run top for?  It might
> need to sample for 10s or more to get a stable snapshot.  In the "bug"
> version, the Compositor is fairly high, which shouldn't be affected by the
> AudioIPC stuff at all, so just wondering if that's a random spike or a real
> clue.

The logs I attached yesterday are the result of
'top -H -b'>log.txt
and I let it run for about 1 minute each, so you should have about 20
'top -H' screens.

I should note that I did minimize Firefox while taking those logs, I thought
that would be better.

> I notice Firefox is requesting a latency of 25ms from PulseAudio.  The audio
> remoting should handle that, since we request values as low as 11ms for
> WebRTC related stuff and expect that to work.  But for playback streams, we
> default to 100ms, so that's a bit unusual to see 25ms.  Do you have any
> media/audio prefs set to non-default values?  Specifically,
> media.cubeb_latency_playback_ms, or any other media.cubeb* prefs?

I don't see any config option like those, nor in Firefox 60.0.1 nor Nightly,
there's only
media.cubeb.logging_level
media.cubeb.sandbox

> From the top snapshots, I don't expect the audio threads to be starving.  A
> bit higher overhead for audio remoting is expected, for now.  So that
> suggests the audio threads could be waiting on a lock or something strange
> with process scheduling.
> 
> One more experiment I'd like you to try, please, is: in a current nightly is
> to create the integer pref media.audioipc.pool_size and set it to 6, then
> restart and see if the issue is reproducible.

Yes, the isse is still there with
media.audioipc.pool_size 6
media.cubeb.sandbox true

Can't really say if it's better than before.

Comment 11

[Matthew Gregan [:kinetik]]

What Linux distribution and version are you running?  I'll see if I can reproduce this locally - if not I might ask you to run a special build with additional instrumentation.

It might also be good to attach a copy of your PulseAudio configuration files, unless you're certain they haven't been changed from the distro defaults - files will be in /etc/pulse and $HOME/.pulse/client.conf (latter may not exist).  The paths might be different if your distro has customized PulseAudio.

Comment 12

[Michele Ballabio]

OK, I've tried again today and the problem seems gone, but I'm going to test better in the following days. Maybe some library got updated in the meantime and solved it all?

(In reply to Matthew Gregan [:kinetik] from comment #11)
> What Linux distribution and version are you running?  I'll see if I can
> reproduce this locally - if not I might ask you to run a special build with
> additional instrumentation.

I'm on Slackware-current 32bit, it can be installed from
http://bear.alienbase.nl/mirrors/slackware/slackware-current-iso/slackware-current-install-dvd.iso

...but you may not reproduce the problem anymore, I guess.

I do have my own kernel and some additional packages installed.

The only relevant things upgraded in the meantime, to me, seem to be mozilla-nss and fftw:
http://www.slackware.com/changelog/current.php?cpu=i386

> It might also be good to attach a copy of your PulseAudio configuration
> files, unless you're certain they haven't been changed from the distro
> defaults - files will be in /etc/pulse and $HOME/.pulse/client.conf (latter
> may not exist).  The paths might be different if your distro has customized
> PulseAudio.

I don't have any $HOME/.pulse/client.conf, but I don't remember if I changed something in /etc, so I'll attach a tar.gz.

I'll try again with media.cubeb.sandbox = true and report back.

Comment 13

[Michele Ballabio]

Attachment: pulse.tar.gz: pulse configuration files

Comment 14

[Michele Ballabio]

Quick update: with media.cubeb.sandbox = true I still have the same problems: it seemed they were gone, but I was wrong.

Comment 15

[Jonathan Guerin]

I'm seeing similar behaviour today with the following setup:

1. https://www.di.fm/ in a pinned tab streaming audio in the background
2. Washington Post with a muted video playing in another tab

The DI.FM stream stutters (no skipping, so not buffer related), while the Washington Post video plays fine (as does audio if I unmute it). Happy to do any tracing that you need etc.

Name Firefox
Version 73.0b7
Build ID 20200118195856
Update Channel beta
User Agent Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:73.0) Gecko/20100101 Firefox/73.0
OS Darwin 19.2.0

Comment 16

[Matthew Gregan [:kinetik]]

(In reply to Jonathan Guerin from comment #15)

I'm seeing similar behaviour today with the following setup:

1. https://www.di.fm/ in a pinned tab streaming audio in the background
2. Washington Post with a muted video playing in another tab

The DI.FM stream stutters (no skipping, so not buffer related), while the Washington Post video plays fine (as does audio if I unmute it). Happy to do any tracing that you need etc.

Thanks for the bug report! This bug is specific to audio remoting, which is only enabled on Linux right now (macOS will be enabled via bug 1425788 - if you check about:config on your Mac, you'll see media.cubeb.sandbox is false), so your issue must be something different. Would you mind filing a new bug with these details so the appropriate people can investigate?

Comment 17

[Matthew Gregan [:kinetik]]

It's also possible this Linux issue was resolved or significantly improved by Paul's thread priority work in bug 1429847 and follow ups.

Comment 18

[Jonathan Guerin]

(In reply to Matthew Gregan [:kinetik] from comment #16)

(In reply to Jonathan Guerin from comment #15)

I'm seeing similar behaviour today with the following setup:

1. https://www.di.fm/ in a pinned tab streaming audio in the background
2. Washington Post with a muted video playing in another tab

The DI.FM stream stutters (no skipping, so not buffer related), while the Washington Post video plays fine (as does audio if I unmute it). Happy to do any tracing that you need etc.

Thanks for the bug report! This bug is specific to audio remoting, which is only enabled on Linux right now (macOS will be enabled via bug 1425788 - if you check about:config on your Mac, you'll see media.cubeb.sandbox is false), so your issue must be something different. Would you mind filing a new bug with these details so the appropriate people can investigate?

No worries, done:
https://bugzilla.mozilla.org/show_bug.cgi?id=1611503

Comment 19

[Matthew Gregan [:kinetik]]

I'll mark this as fixed, since the audio remoting code has been considerably reworked since then (primarily via bug 1726279 for Linux).