Closed Bug 1568058 Opened 1 year ago Closed 1 year ago

Long delay when using Phaser to load an audio sprite, works fine in Chrome

Categories

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

70 Branch
x86_64
Linux
defect

Tracking

()

VERIFIED FIXED
mozilla72
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox68 --- unaffected
firefox69 + wontfix
firefox70 + wontfix
firefox71 --- wontfix
firefox72 --- verified

People

(Reporter: mythmon, Assigned: mjf)

References

(Regression)

Details

(Keywords: regression, Whiteboard: [qf:p2:pageload])

Attachments

(5 files, 1 obsolete file)

While working with the Phaser JS game engine, I added background music to my loading step. This change caused the game to take over a minute to load. The actual network transfer of the audio file is over in a few seconds at most, and then something else happens for the rest of the minute that isn't network traffic, and doesn't seem to be CPU bound.

I've reproduced with three profiles and two computers, on both Firefox Nightly 70 and Release 67 running on Fedora 30. The problem does not reproduce on Nightly or Release on OSX. Chrome loads the site very quickly.

I've profiled the issue in a fresh profile: https://perfht.ml/2Lxw12C

Setting dom.timeout.defer_during_load to false had no effect.

STR

Open https://away-with-me-d0rw1z00p.now.sh/

Expected

The game should reach a menu page within a few seconds.

Actual

The game stays on a black screen (which is the loading screen) for about a minute.

Is there any chance of getting a page with the unminified JS? I know that it has source-maps, which is great, but if it's not too much work it'd be easier to see what is going on, and what's supposed to trigger the request and such.

Flags: needinfo?(mcooper)

Moving to Core since it's likely to be a Gecko issue rather than frontend or toolkit or what not.

Product: Firefox → Core

The source is here: https://github.com/away-with-me/Away-With-Me/tree/12135b91daa9ffbcc8b02a1f25bed420e99a09b1

From that you could run a development version of the page with npm install; npm start. That won't be minified, at least (though it is still built from many sources in to one file). I can also try and set up an unminified version somewhere, but that might take a bit longer.

Flags: needinfo?(mcooper)

That's probably good enough, but I'll let you know if I need more :)

So I was trying to figure if this was a regression, but builds older than this commit insta-crash locally... https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=9205d38f866cc1e50cb67c87fe2a02654cde8417&tochange=026130a68e7c9a54d0995a485cd941aad9a3c30c

I can run mozregression with MOZ_DISABLE_CONTENT_SANDBOX=1 MOZ_DISABLE_GMP_SANDBOX=1 though, and it seems 62 was "good".

[Tracking Requested - why for this release]: Bad regression that we don't seem to have shipped yet.

Mozregression gives me https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=be5b9ac813f5b515a1884fd2c5048e6b601da694&tochange=705ac184fb58d25c36736aa5fc8a3f844ae91f9a

And switching back media.rdd-vorbis.enabled to false makes it fast on Nightly.

Component: General → Audio/Video: Playback
Flags: needinfo?(mfroman)
Flags: needinfo?(drno)
Priority: -- → P2
Regressed by: 1550567

Well, good thing is that this looks like it's Linux-only. Yay?

I can confirm that setting media.rdd-vorbis.enable to false fixes the problem for me.

(Removing the priority field since I don't know how the media team triages stuff :))

Priority: P2 → --

I tried this on my Linux box with some debug logging in place, and what I see (either true or false for media.rdd-vorbis.enable) is that approxmately 40K calls are made to decode Vorbis content prior to the menu being shown. It appears that an entire audio file is decoded prior to showing the menu. It is overall slower with media.rdd-vorbis.enable set to true because each of those calls is forwarded to the RDD process (RemoteDataDecoder) process, and the decoded data is sent back.

It is not affecting macOS because Bug 1552643 accidentally turned Vorbis decoding for macOS off, and we haven't yet landed the patch to turn the pref back on.

Flags: needinfo?(mfroman)

I did some very rough timings on startup time (from first firefox window showing to the game menu showing) with Bug 1562910's ShmemPool impl:
Decode on Vorbis on tab 7s
Decode on Vorbis on RDD w/o ShmemPool 26s
Decode on Vorbis on RDD w/ ShmemPool 15s

Assignee: nobody → mfroman
Flags: needinfo?(drno)
Priority: -- → P2
Whiteboard: [qf] → [qf:p2:pageload]

Too late for 69 at this point with RC coming next week.

  • Adds DecodeBatch method to MediaDataDecoder.
  • Adds DecodeBatch method to IRemoteDecoderChild.h to match
    MediaDataDecoder.
  • AllocationPolicy and AudioTrimmer both implement DecodeBatch
    so we can pass this through the RemoteMediaDataDecoder (and
    thus to RemoteDecoderChild/RemoteDecoderParent).
  • MediaFormatReader now understands how to request multiple
    samples from the demuxer and if more than one is requested,
    call DecodeBatch rather than Decode.
  • MediaBufferDecoder will set a new option on MediaFormatReaderInit
    to set a batch size of 10 samples when creating MediaFormatReader.
    This only happens if we're decoding opus and RDD decoding of Opus
    is enabled.
Depends on: 1582353

Is this still in progress or is it now waiting for bug 1582353?

Flags: needinfo?(mfroman)

This is still in progress (but delayed while I finish importing the mp3 decoder from ffmpeg). I'll probably get back to this bug before jya will get to Bug 1582353. It is a bit of a race. ;-)

Flags: needinfo?(mfroman)

At this point I think it will likely wait for 71 as we are heading into beta 12 of 14.

Depends on: 1590475
Depends on: 1593301
Attachment #9091171 - Attachment description: Bug 1568058 - decode webaudio Opus in batches to reduce number of IPC calls to RDD. r?mattwoodrow → Bug 1568058 - pt 1 - Add DecoderTraits::CreateDemuxer and use it in CreateReader. r?jya!

In order to use the batch decoding abilities added in Bug 1590475,
we need to also add batch decoding to MediaDataDecoder. For now
only RemoteMediaDataDecoder (and AudioTrimmer as a wrapper) know
how to do batch, but this could be implemented more generically
later in MediaDataDecoder.

Depends on D45094

Stop using MediaFormatReader and use a demuxer and decoder directly in
MediaBufferDecoder. This will allow us to do batch decoding calls for
webaudio that will improve performance by reducing the number of IPC
calls to the RDD process.

Depends on D51452

  • Add a pref for controlling the batch size when doing webaudio decoding
    on RDD.
  • If batch size is greater than 1 and the decoder is capable of batch
    decoding, send raw sample batches to decoder.

Depends on D51453

Some rough timing for the webaudio decode of audiosprite.ogg (from the game in comment 3):

Linux (opt)
	run	|	1	| 	2	|	3	|	4	|	5	|	Avg	|
no rdd		|   5.31	|   5.03	|   5.41	|   5.19	|   5.20	|   5.228	|
w/ rdd		|  11.98	|  11.92	|  11.99	|  11.96	|  11.77	|  11.924	|
w/ rdd & batch	|   3.73	|   3.73	|   3.64	|   3.83	|   3.83	|   3.752	|


Win (deb)
	run	|	1	| 	2	|	3	|	4	|	5	|	Avg	|
no rdd		|   20.21	|   21.63	|   18.64	|   17.43	|   23.59	|  20.3		|
w/ rdd		|   x.xx	|   x.xx	|   x.xx	|   x.xx	|   x.xx	|   x.xx	|
w/ rdd & batch	|   14.52	|   14.20	|   16.27	|   14.02	|   16.41	|  15.084	|


macOS (opt)
	run	|	1	| 	2	|	3	|	4	|	5	|	Avg	|
no rdd		|   2.34	|   2.37	|   2.35	|   2.56	|   2.41	|   2.406	|
w/ rdd		|   5.08	|   5.08	|   5.14	|   5.11	|   5.33	|   5.148	|
w/ rdd & batch	|   2.34	|   2.11	|   2.08	|   2.09	|   2.09	|   2.142	|

I was unable to capture data for Windows in an opt build so I didn't bother capturing times for the "w/rdd" (no batch) case.

This looks like a clear win since averages for rdd w/ batch decoding are better across the board than before rdd.

Depends on: 1595657
Pushed by mfroman@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ff0b20be880b
pt 1 - Add DecoderTraits::CreateDemuxer and use it in CreateReader. r=jya
https://hg.mozilla.org/integration/autoland/rev/08c7f0dd63c8
pt 2 - Add batch decode methods to MediaDataDecoder. r=jya
https://hg.mozilla.org/integration/autoland/rev/53a35e1379d6
pt 3 - Remove MediaFormatReader from MediaBufferDecoder. r=jya
https://hg.mozilla.org/integration/autoland/rev/db32a8eb28a2
pt 4 - Use batch decoding in MediaBufferDecoder. r=jya
Flags: qe-verify+

In an attempt to verify the issue, I was not able to access the link or get the source files working(all I get is the blank page if trying to access the index file).
Any chance you could provide another link or some additional info regarding the setup for the game to work?

Flags: needinfo?(mcooper)

(In reply to Cristian Fogel, QA [:cfogel] from comment #23)

In an attempt to verify the issue, I was not able to access the link or get the source files working(all I get is the blank page if trying to access the index file).
Any chance you could provide another link or some additional info regarding the setup for the game to work?

Cristian, did you do the npm install; npm start as shown in Comment 3? After running npm start you should see a line something like:

Server running at http://localhost:1234

After going to that address in the browser you're trying to test, you will see a rectangle drawn with a white line on a black screen until the game's menu is drawn. This can be some number of seconds depending on your machine and whether the fix is active in the browser version you're testing.

Flags: needinfo?(cristian.fogel)

The best option is what Michael suggested in comment 24. If that's not viable, I can try and stand up a new, pinned version of the app.

Flags: needinfo?(mcooper)
Attached file npm-debug.log (obsolete) —

Thanks for the replies, and sorry for the delayed response.

Ran into some "difficulties" in trying to start up npm, attaching the debug log in case it would help with any ideas.
As I'm unfamiliar with it, I've tried some of the top replies in trying to solve the issues but to no success.
Would trying to set up xampp be acceptable for the test or need npm for it?

Flags: needinfo?(cristian.fogel)

(In reply to Cristian Fogel, QA [:cfogel] from comment #26)

Created attachment 9119046 [details]
npm-debug.log

Thanks for the replies, and sorry for the delayed response.

Ran into some "difficulties" in trying to start up npm, attaching the debug log in case it would help with any ideas.
As I'm unfamiliar with it, I've tried some of the top replies in trying to solve the issues but to no success.
Would trying to set up xampp be acceptable for the test or need npm for it?

What directory are you in when running the npm start command? The logs point to you being in your home directory rather than the directory for the game. You'll need to have done a git clone of the source repo :mythmon gave in Comment 3. The steps I used are:

cd ~
git clone https://github.com/away-with-me/Away-With-Me/
cd ~/Away-With-Me/
git checkout 12135b9
npm install
npm start
Flags: needinfo?(cristian.fogel)
Attached file npm-debug.log

Still running into some issue. Indeed I wasn't in the proper folder while trying to start it up.
Updated the log with the current report after redo-ing the setup on another workstation.

Attachment #9119046 - Attachment is obsolete: true
Flags: needinfo?(cristian.fogel)

(In reply to Cristian Fogel, QA [:cfogel] from comment #28)

Created attachment 9119713 [details]
npm-debug.log

Still running into some issue. Indeed I wasn't in the proper folder while trying to start it up.
Updated the log with the current report after redo-ing the setup on another workstation.

Make sure the versions of node and npm are update to date. From your log:

2 info using npm@3.5.2
3 info using node@v8.10.0
...
25 error Make sure you have the latest version of node.js and npm installed.

On my system the versions are:
npm@6.13.4
node@v8.17.0

Node v8 is rather old at this point. I'd recommend at least v10 or ideally v12.

That being said, I made a version of this pinned at the specific commit for verification: https://away-with-me-12135b9.glitch.me/

Thanks for the information and the new test-link.

Can confirm that with 70.0 the load timer was pretty long compared to 73.0b2/72.0.1 (~ 20seconds extra) .
Marking the bug as verified since it does in fact have fixed the reported issue.

However; after this loading_screen, a rectangle appears that seems to be the container for the game.
From the rectangle_screen, until the image/menu is displayed; compared to Chrome it appears to have an increase in load-time of an additional 15 seconds until the menu options are displayed.
Do we need to file a followup report for this?

Status: RESOLVED → VERIFIED
Flags: qe-verify+
Regressions: 1648309
No longer regressions: 1648309
See Also: → 1672311
You need to log in before you can comment on or make changes to this bug.