[B2G] [Buri] [1.2] [Music] Long delay experienced when a song is selected

RESOLVED FIXED in Firefox 26

Status

()

defect
P1
normal
RESOLVED FIXED
6 years ago
6 years ago

People

(Reporter: ckreinbring, Assigned: sotaro)

Tracking

({perf, regression})

unspecified
mozilla27
ARM
Gonk (Firefox OS)
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(blocking-b2g:koi+, firefox25 wontfix, firefox26 fixed, firefox27 fixed, b2g-v1.2 fixed)

Details

(Whiteboard: burirun1 [c=progress p= s= u=1.2])

Attachments

(3 attachments, 2 obsolete attachments)

Posted file Log of song lag
Description:
Attempting to play a song in the Music app causes a long delay before the song begins.  The device seems unresponsive before the song starts playing, but all inputs performed during the delay go off at once when the song starts playing.

Repro Steps:
1) Update Buri to Build ID: 20130910040201
2) Launch the Music app.
3) Select a song to play, how doesn't matter.
4) Observe the screen as the song loads.

Actual:
There is a delay of over 20 seconds before the song begins to play.

Expected:
The song being playing immediately.

Environmental Variables
Occurs on Buri 1.2 mozilla RIL
Build ID: 20130910040201
Gecko: http://hg.mozilla.org/mozilla-central/rev/be1053dc223b
Gaia: 6deda9d7c51f278443f704217eaed722044a03e7
Platform Version: 26.0a1

Notes:
Repro frequency: 85%
Test Suite Name: Music
UCID: music-008
Link to failed test case: https://moztrap.mozilla.org/manage/cases/?filter-id=3753
See attached logcat logs
Pretty bad perf regression, but not a smoketest blocker.
blocking-b2g: --- → koi?
Behavior sounds very similar to what I saw yesterday in Bug 914390.
agree with comment 2, must be a dup of bug 914390, can someone check logcats to confirm?
(In reply to nkot from comment #3)
> agree with comment 2, must be a dup of bug 914390, can someone check logcats
> to confirm?

It isn't a dupe. This bug doesn't have genlock errors, where as bug 914390 does (genlock errors commonly lead to hangs). It might be another graphics performance bug, however.

Sotoro - What do you think?
Flags: needinfo?(sotaro.ikeda.g)
(In reply to Jason Smith [:jsmith] from comment #4)
> (In reply to nkot from comment #3)
> > agree with comment 2, must be a dup of bug 914390, can someone check logcats
> > to confirm?
> 
> It isn't a dupe. This bug doesn't have genlock errors, where as bug 914390
> does (genlock errors commonly lead to hangs). It might be another graphics
> performance bug, however.
> 
> Sotoro - What do you think?

Misspelled name by accident - meant to say Sotaro.
(In reply to ckreinbring from comment #0)
> Actual:
> There is a delay of over 20 seconds before the song begins to play.

Did music app switch to the player page already then wait for 20 seconds begin to play?
(In reply to Dominic Kuo [:dkuo] from comment #6)
> (In reply to ckreinbring from comment #0)
> > Actual:
> > There is a delay of over 20 seconds before the song begins to play.
> 
> Did music app switch to the player page already then wait for 20 seconds
> begin to play?

Yes.  The player page appears but there's no end time shown (it appears as --:--).
(In reply to Jason Smith [:jsmith] from comment #4)
> It isn't a dupe. This bug doesn't have genlock errors, where as bug 914390
> does (genlock errors commonly lead to hangs). It might be another graphics
> performance bug, however.

Thank you for clarification, 
then, the regression range here:

Build ID: 20130906040204 - Does NOT Reproduce
Gecko: http://hg.mozilla.org/mozilla-central/rev/ab5f29823236
Gaia: 94e5f269874b02ac0ea796b64ab995fce9efa4b3
Platform Version: 26.0a1

Build ID: 20130909114657 - Reproduces
Gecko: http://hg.mozilla.org/mozilla-central/rev/218d4334d29e
Gaia: aa4180e9286d385fa6b62d236f30fb24cd8b93e9
Platform Version: 26.0a1

*don't have any release builds to get a deeper regression range
Assignee

Comment 9

6 years ago
(In reply to Jason Smith [:jsmith] from comment #4)
> (In reply to nkot from comment #3)
> It isn't a dupe. This bug doesn't have genlock errors, where as bug 914390
> does (genlock errors commonly lead to hangs). It might be another graphics
> performance bug, however.
> 
> Sotoro - What do you think?

master's layers seems to have 2 type of regressions. "genlock failure in client side" and "slow gpu rendering". From investigation in Bug 912134. They seems to be caused by different defects. During the investigation, it becomes clear that gpu & drivers are already too busy for rendering. From the following log, some rendering buffers seems not to use gralloc buffers. It could add more task to the gpu and the driver. By this fallback, I suspect the gpu and drivers are come into congestion state and stop rendering.

------------------------------------
09-10 14:53:57.889: D/HWComposer(140): Render aborted. Nothing was drawn to the screen
09-10 14:53:57.919: D/HWComposer(140): ImageLayer Layer doesn't have a gralloc buffer
Flags: needinfo?(sotaro.ikeda.g)
Blocks: GFXB2G1.2
Component: Gaia::Music → Graphics: Layers
Product: Boot2Gecko → Core
Version: unspecified → Trunk
Not reproducible in emulator, using:
 mozilla-central be1053dc223b
 gaia 753bed59566
So, to be clear, this is not a problem with HWC off?
Right. The main difference between emulator and device is that emulator doesn't have HWC, so this looks HWC related.
In fact, Sotaro's Comment 9 suggests the same.
Duplicate of this bug: 914390
Sotaro, with comment 9 - this is not running out of pmem? Nical, what do you think of comment 9?
blocking-b2g: koi? → koi+
Flags: needinfo?(sotaro.ikeda.g)
Flags: needinfo?(nical.bugzilla)
Assignee

Comment 16

6 years ago
(In reply to Milan Sreckovic [:milan] from comment #15)
> Sotaro, with comment 9 - this is not running out of pmem? Nical, what do you
> think of comment 9?

attachment 802615 [details] says that some Image Layer does not have gralloc buffer and rendering fallback from HwComposer to OpenGL. From it, system is running out of pmem.
Flags: needinfo?(sotaro.ikeda.g)
Assignee

Comment 17

6 years ago
Is it still happen in current v1.2/master?
QA Wanted for comment 17
Keywords: qawanted
- Reproduces on Buri v1.2 (aurora)
Build ID: 20130922004001
Gecko: http://hg.mozilla.org/releases/mozilla-aurora/rev/63a505ec015c
Gaia: 7b6147372cbf560744a02be50e0a862a825caef6
Platform Version: 26.0a2

- Reproduces on Buri v1.3 (master)
Build ID: 20130923040214
Gecko: http://hg.mozilla.org/mozilla-central/rev/f97307cb4c95
Gaia: 3408cc3f6b190c8cd31832fbb8cd2ae571041f29
Platform Version: 27.0a1
Keywords: qawanted
(In reply to Milan Sreckovic [:milan] from comment #15)
> Sotaro, with comment 9 - this is not running out of pmem? Nical, what do you
> think of comment 9?

I have never been able to reproduce this bug on unagi (which doesn't run out of pmem as fast as buri does).
I am a bit surprised that we run into this issue specifically here. Music shouldn't be more "graphically-intensive" than other apps like, say, gallery. Especially if this is happenning in a screen where there's no scrolling or anything fancier than a semi-transparent layer.
Flags: needinfo?(nical.bugzilla)
How is the performance on Unagi?
Assignee: nobody → nical.bugzilla
Assignee

Comment 22

6 years ago
Hmm, I tried to reproduce it on master hamachi built from source by myself(2013/09/23), but I can not reproduce it on my device.
(In reply to Sotaro Ikeda [:sotaro] from comment #22)
> Hmm, I tried to reproduce it on master hamachi built from source by
> myself(2013/09/23), but I can not reproduce it on my device.

I retested it on two different Buri devices having SD-1, SD-2, and SD-3 cards. 
The issue constantly reproduces with SD-1 and SD-2, does not reproduce with SD-3. 
Same results for both devices.

I cannot reproduce the issue on Leo v1.1 using any of these three SDs.
Assignee

Comment 24

6 years ago
From comment 23, it seems clear that this bug is not graphics bug, but a bug around sd driver.
Component: Graphics: Layers → General
Product: Core → Boot2Gecko
Version: Trunk → unspecified
Assignee

Comment 25

6 years ago
(In reply to Sotaro Ikeda [:sotaro] from comment #22)
> Hmm, I tried to reproduce it on master hamachi built from source by
> myself(2013/09/23), but I can not reproduce it on my device.

I tried also on v1.2 hamachi built from source by myself(2013/09/24), but I can not reproduce it on my hamachi device.
We're trying to get some "slow" SD cards locally, to confirm the behaviour from in Comment 23, but this does not look like graphics - it does need attention though, Preeti, what is the right component to set or the right team to look at this, if it is SD driver related?
Assignee: nical.bugzilla → nobody
No longer blocks: GFXB2G1.2
Flags: needinfo?(praghunath)
(In reply to Milan Sreckovic [:milan] from comment #26)
> We're trying to get some "slow" SD cards locally, to confirm the behaviour
> from in Comment 23, but this does not look like graphics - it does need
> attention though, Preeti, what is the right component to set or the right
> team to look at this, if it is SD driver related?

Maybe Dave Hylands?

Updated

6 years ago
Priority: -- → P1

Updated

6 years ago
Whiteboard: burirun1 → burirun1 [c=progress p= s= u=1.2]
Dave?
Flags: needinfo?(praghunath) → needinfo?(dhylands)
If the problem is SD card driver related, then that's a vendor issue (we just use the driver we get - it comes with the kernel).

It would be pretty easy to write some test scripts which could evaluate the speed of reading/writing to the cards.

There are actually several things that could be affecting the performance. One is the speed rating of the cards. But the second is the hardware itself.
Flags: needinfo?(dhylands)
Assignee

Comment 30

6 years ago
(In reply to nkot from comment #23)
> (In reply to Sotaro Ikeda [:sotaro] from comment #22)
> > Hmm, I tried to reproduce it on master hamachi built from source by
> > myself(2013/09/23), but I can not reproduce it on my device.
> 
> I retested it on two different Buri devices having SD-1, SD-2, and SD-3
> cards. 
> The issue constantly reproduces with SD-1 and SD-2, does not reproduce with
> SD-3. 
> Same results for both devices.

Can we have information of the SD cards?
Flags: needinfo?(nkot)
Sotaro,
I attached one of the songs from "affected" SD card, can you try it on your device? if you can get it to repro?

I used class 2 (2GB) SD card and class 4 (4 and 8 GB) SD cards, was able to reproduce the issue on any of them.
Flags: needinfo?(nkot)
Assignee

Comment 32

6 years ago
(In reply to nkot from comment #31)
> Created attachment 810271 [details]
> 02 Beautiful Morning.mp3
> 
> Sotaro,
> I attached one of the songs from "affected" SD card, can you try it on your
> device? if you can get it to repro?

Thanks for the attachment! I can reproduce the symptom. I am going to investigate about it.
Assignee

Comment 33

6 years ago
From the debugging, it seems that this bug is regression from the following.
 - Bug 831224 - [Music] Incorrect track length; Support variable-bitrate MP3s
Blocks: 831224
Component: General → Video/Audio
Product: Boot2Gecko → Core
(In reply to Sotaro Ikeda [:sotaro] from comment #33)
> From the debugging, it seems that this bug is regression from the following.
>  - Bug 831224 - [Music] Incorrect track length; Support variable-bitrate MP3s

The mp3 files are read in chunks of 8MiB. Lowering this value might already fix the problem. See sReadSize in OmxDecoder::ProcessCachedData.
Assignee

Comment 35

6 years ago
This patch reduce the buffer size from 8MiB max to 8Kib max. It seems to solve the problem. I confirmed on master hamachi.
Assignee

Updated

6 years ago
Assignee: nobody → sotaro.ikeda.g
Assignee

Updated

6 years ago
Attachment #810624 - Flags: review?(chris.double)
Comment on attachment 810624 [details] [diff] [review]
patch - Reduce mp3 parse chunk buffer size to 4KiB

Review of attachment 810624 [details] [diff] [review]:
-----------------------------------------------------------------

The comment says 4KiB, the code says 8KiB.

::: content/media/omx/OmxDecoder.cpp
@@ +1003,1 @@
>    // value if media, such as sdcards, is too slow.

It's probably worth mentioning in the comment that we did try 8MiB before, but ran into a problem with variable rate and mention this bug.
Assignee

Comment 37

6 years ago
(In reply to Milan Sreckovic [:milan] from comment #36)
> ::: content/media/omx/OmxDecoder.cpp
> @@ +1003,1 @@
> >    // value if media, such as sdcards, is too slow.
> 
> It's probably worth mentioning in the comment that we did try 8MiB before,
> but ran into a problem with variable rate and mention this bug.

Thanks for the comment. I will update the patch soon.
Assignee

Updated

6 years ago
Attachment #810624 - Attachment is obsolete: true
Attachment #810624 - Flags: review?(chris.double)
Assignee

Comment 38

6 years ago
Update comments.
Assignee

Updated

6 years ago
Attachment #810767 - Flags: review?(chris.double)

Updated

6 years ago
Attachment #810767 - Flags: review?(chris.double) → review+
(In reply to Sotaro Ikeda [:sotaro] from comment #38)
> Created attachment 810767 [details] [diff] [review]
> patch v2 - Reduce mp3 parse chunk buffer size to 8KiB

8KiB seems quite low to me. Have you tried larger values? I'd suggest to increase the read size to the maximum acceptable value to minimize the overhead of the parsing process. 

Read data is send from the I/O thread to the main thread for parsing, and the next read is scheduled on the I/O thread. This means that data structures (tasks, runnables) are constantly allocated and free'd during the process. The more data we read per round-trip the better.
Assignee

Comment 41

6 years ago
The reason I changed the buffer size 8KiB is "ProcessCachedData(0, true)" in OmxDecoder::TryLoad() is synchronous. This blocking time should be minimized.
Assignee

Comment 42

6 years ago
I quickly tested by some buffer sizes(8KiB, 16KiB, 32KiB, 64KiB, 128KiB). Until 32KiB, The spent time for "ProcessCachedData(0, true)" were almost same(typically less than 5ms). But 64KiB and 128Kib cases typically spended more than 5ms. From the result, the buffer size seems to be increased to 32KiB without start up time regression.
Assignee

Comment 43

6 years ago
And if we want to increase buffer size more, we need to care about no regression like Bug 919793.
(In reply to Sotaro Ikeda [:sotaro] from comment #42)
> I quickly tested by some buffer sizes(8KiB, 16KiB, 32KiB, 64KiB, 128KiB).
> Until 32KiB, The spent time for "ProcessCachedData(0, true)" were almost
> same(typically less than 5ms). But 64KiB and 128Kib cases typically spended
> more than 5ms. From the result, the buffer size seems to be increased to
> 32KiB without start up time regression.

Thanks for taking a look. :)
Assignee

Comment 45

6 years ago
Commitable patch. Change the buffer size from 8KiB to 32KiB. Carry 'chris.double: review+'
Attachment #810767 - Attachment is obsolete: true
Attachment #812283 - Flags: review+
Assignee

Updated

6 years ago
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/8fb5ebe3b22a
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla27
I think this regressed calculating the duration of VBR mp3s in the music app. Previously, the duration showed properly, but now it changes rapidly for a few seconds, presumably as we're loading the mp3 and calculating the length of each frame.
That the duration changes a bit is expected. When we read chunks of 8MiBs we probably got enough information to give a good estimate for the overall duration. With the smaller chunks, probably not. Ideally the DeviceStorage system would tell us the performance of the SD card, so we could adapt the chunk size accordingly.
Assignee

Updated

6 years ago
Blocks: 927884
You need to log in before you can comment on or make changes to this bug.