High delay observed in ScriptProcessorNode

RESOLVED FIXED in Firefox 40

Status

()

Core
Web Audio
RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: pehrsons, Assigned: pehrsons)

Tracking

39 Branch
mozilla40
Points:
---

Firefox Tracking Flags

(firefox40 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

3 years ago
I have seen cases when ScriptProcessorNode is causing delays of several (2-3 is quite typical) seconds.

To trigger this behavior I set up a ScriptProcessorNode early on in the lifetime of a page, while there's still a lot of other stuff going on on the main thread.

I put in some logging in my build to analyse this (logging just before mLatency is increased at [1]):

First we see the huge delay that causes us to start dropping frames.
> ##### 0x120ef8700 mLatency=0,00000, latency=0,00039 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,00542, latency=2,23579 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=2,22457, latency=0,00068 bufferDuration=0,00580

It starts to catch up.
> ##### 0x120ef8700 mLatency=2,21944, latency=0,00122 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=2,21485, latency=0,00059 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=2,20964, latency=0,00046 bufferDuration=0,00580

Eventually we finish dropping frames, but it is prematurely; mLatency is at ~0.5. 
> ##### 0x120ef8700 mLatency=0,50814, latency=0,00047 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=0,50281, latency=0,00047 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=0,00000, latency=0,00050 bufferDuration=0,00580

We're still catching up with the original latency after the reset.
> ##### 0x120ef8700 mLatency=-0,00531, latency=0,00047 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,01064, latency=0,00962 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,00683, latency=0,00050 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,01213, latency=0,00053 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,01740, latency=0,00060 bufferDuration=0,00580

And stabilize at ~ -0.45. This means ~ 0.45 seconds delay for the user.
> ##### 0x120ef8700 mLatency=-0,44514, latency=0,00049 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,45045, latency=0,01121 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,44505, latency=0,00048 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,45037, latency=0,01132 bufferDuration=0,00580
> ##### 0x120ef8700 mLatency=-0,44485, latency=0,00051 bufferDuration=0,00580

What happens is:
* Huge delay on main thread
* Start dropping frames in ScriptProcessorNode.cpp since mLatency > MAX_LATENCY_S
* The change from bug 932621 is trigger happy and makes us stop dropping frames prematurely.
* The input keeps catching up (causing a delay since we're not dropping the output anymore), but mLatency was reset so mLatency is now going negative - putting the frame dropping logic out of play.


[1] https://dxr.mozilla.org/mozilla-central/source/dom/media/webaudio/ScriptProcessorNode.cpp#145
(Assignee)

Comment 1

3 years ago
Do you have any clever ideas on how to fix this Paul?

Could we perhaps see in the output queue how much has (not) been consumed and thus more reliably know how big the latency is?
Flags: needinfo?(padenot)
(Assignee)

Comment 2

3 years ago
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #1)
> Could we perhaps see in the output queue how much has (not) been consumed
> and thus more reliably know how big the latency is?

We could. I have a patch that simplifies the fram-dropping-algorithm a whole lot. I hope there are no holes in it ;-)
(Assignee)

Comment 3

3 years ago
Created attachment 8595901 [details]
MozReview Request: bz://1157137/pehrsons

/r/7425 - Bug 1157137 - Fix WebAudio ScriptProcessorNode sometimes gaining high latency. r=padenot

Pull down this commit:

hg pull -r d183fc9db2a5712cc452c341507058ceaf5fa6b5 https://reviewboard-hg.mozilla.org/gecko/
Attachment #8595901 - Flags: review?(padenot)
(Assignee)

Comment 4

3 years ago
There. Anyone else that should review as well?
Flags: needinfo?(padenot)
(Assignee)

Comment 6

3 years ago
Try is happy. Some unexpected Android M-6 failures caused me some confusion but they're for 4.3 which is apparently not tested on m-i or m-c.
(Assignee)

Updated

3 years ago
Assignee: nobody → pehrsons
Status: NEW → ASSIGNED
(Assignee)

Updated

3 years ago
Blocks: 1156733
Comment on attachment 8595901 [details]
MozReview Request: bz://1157137/pehrsons

https://reviewboard.mozilla.org/r/7423/#review6257
Attachment #8595901 - Flags: review?(padenot) → review+

Comment 8

3 years ago
This has been an issue for me for over a year in Firefox on Mac OS X 

Test url would be my js gba emulator: http://jsemu.github.io/gba/
Pick a game and you'll notice the delay can sometimes be up to a full second, and it's unstable on what buffer level it softens to.
(Assignee)

Comment 9

3 years ago
(In reply to Grant Galitz from comment #8)
> This has been an issue for me for over a year in Firefox on Mac OS X 
> 
> Test url would be my js gba emulator: http://jsemu.github.io/gba/
> Pick a game and you'll notice the delay can sometimes be up to a full
> second, and it's unstable on what buffer level it softens to.

I tried on my local build of nightly debug with the patch. There were so many things going on on main thread that it was like playing in slow motion more or less (and audio constantly breaking up to that). That could be in part due my debug build perhaps. But good news, no delay! :-)
(Assignee)

Updated

3 years ago
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/86a8fc4c1fae
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox40: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
(Assignee)

Updated

3 years ago
Duplicate of this bug: 1156733
(Assignee)

Comment 13

3 years ago
Comment on attachment 8595901 [details]
MozReview Request: bz://1157137/pehrsons
Attachment #8595901 - Attachment is obsolete: true
Attachment #8620108 - Flags: review+
(Assignee)

Comment 14

3 years ago
Created attachment 8620108 [details]
MozReview Request: Bug 1157137 - Fix WebAudio ScriptProcessorNode sometimes gaining high latency. r=padenot
You need to log in before you can comment on or make changes to this bug.