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

Status: VERIFIED FIXED

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

Description

[Michael Cooper [:mythmon]]

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.

Comment 1

[Emilio Cobos Álvarez (:emilio)]

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.

Comment 2

[Emilio Cobos Álvarez (:emilio)]

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

Comment 3

[Michael Cooper [:mythmon]]

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.

Comment 4

[Emilio Cobos Álvarez (:emilio)]

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

Comment 5

[Emilio Cobos Álvarez (:emilio)]

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".

Comment 6

[Emilio Cobos Álvarez (:emilio)]

[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.

Comment 7

[Emilio Cobos Álvarez (:emilio)]

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

Comment 8

[Michael Cooper [:mythmon]]

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

Comment 9

[Emilio Cobos Álvarez (:emilio)]

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

Comment 10

[Michael Froman [:mjf]]

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.

Comment 11

[Michael Froman [:mjf]]

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

Comment 12

[Ryan VanderMeulen [:RyanVM]]

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

Comment 13

[Michael Froman [:mjf]]

Attachment: Bug 1568058 - pt 1 - Add DecoderTraits::CreateDemuxer and use it in CreateReader. r?jya!

• 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.

Comment 14

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

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

Comment 15

[Michael Froman [:mjf]]

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. ;-)

Comment 16

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

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

Comment 17

[Michael Froman [:mjf]]

Attachment: Bug 1568058 - pt 2 - Add batch decode methods to MediaDataDecoder. 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

Comment 18

[Michael Froman [:mjf]]

Attachment: Bug 1568058 - pt 3 - Remove MediaFormatReader from MediaBufferDecoder. r?jya!

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

Comment 19

[Michael Froman [:mjf]]

Attachment: Bug 1568058 - pt 4 - Use batch decoding in MediaBufferDecoder. r?jya!

• 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

Comment 20

[Michael Froman [:mjf]]

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.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
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

Comment 22

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/ff0b20be880b
https://hg.mozilla.org/mozilla-central/rev/08c7f0dd63c8
https://hg.mozilla.org/mozilla-central/rev/53a35e1379d6
https://hg.mozilla.org/mozilla-central/rev/db32a8eb28a2

Comment 23

[Cristian Fogel [:cfogel]]

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?

Comment 24

[Michael Froman [:mjf]]

(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.

Comment 25

[Michael Cooper [:mythmon]]

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.

Comment 26

[Cristian Fogel [:cfogel]]

Attachment: 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?

Comment 27

[Michael Froman [:mjf]]

(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

Comment 28

[Cristian Fogel [:cfogel]]

Attachment: 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.

Comment 29

[Michael Froman [:mjf]]

(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

Comment 30

[Michael Cooper [:mythmon]]

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/

Comment 31

[Cristian Fogel [:cfogel]]

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?