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

Status: RESOLVED FIXED

(Core :: Audio/Video, defect, P1)

Description

[Chris Kreinbring [:CKreinbring]]

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

Comment 1

[Jason Smith [:jsmith]]

Pretty bad perf regression, but not a smoketest blocker.

Comment 2

[Marcia Knous [:marcia]]

Behavior sounds very similar to what I saw yesterday in Bug 914390.

Comment 3

[Natalya Kot [:nkot]]

agree with comment 2, must be a dup of bug 914390, can someone check logcats to confirm?

Comment 4

[Jason Smith [:jsmith]]

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

Comment 5

[Jason Smith [:jsmith]]

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

Comment 6

[Dominic Kuo [:dkuo]]

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

Comment 7

[Chris Kreinbring [:CKreinbring]]

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

Comment 8

[Natalya Kot [:nkot]]

(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

Comment 9

[Sotaro Ikeda [:sotaro]]

(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

Comment 10

[Benoit Jacob [:bjacob] (mostly away)]

Not reproducible in emulator, using:
 mozilla-central be1053dc223b
 gaia 753bed59566

Comment 11

[Milan Sreckovic [:milan] (needinfo for best results)]

So, to be clear, this is not a problem with HWC off?

Comment 12

[Benoit Jacob [:bjacob] (mostly away)]

Right. The main difference between emulator and device is that emulator doesn't have HWC, so this looks HWC related.

Comment 13

[Benoit Jacob [:bjacob] (mostly away)]

In fact, Sotaro's Comment 9 suggests the same.

Comment 15

[Milan Sreckovic [:milan] (needinfo for best results)]

Sotaro, with comment 9 - this is not running out of pmem? Nical, what do you think of comment 9?

Comment 16

[Sotaro Ikeda [:sotaro]]

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

Comment 17

[Sotaro Ikeda [:sotaro]]

Is it still happen in current v1.2/master?

Comment 18

[Jason Smith [:jsmith]]

QA Wanted for comment 17

Comment 19

[Natalya Kot [:nkot]]

- 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

Comment 20

[Nicolas Silva [:nical]]

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

Comment 21

[Milan Sreckovic [:milan] (needinfo for best results)]

How is the performance on Unagi?

Comment 22

[Sotaro Ikeda [:sotaro]]

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.

Comment 23

[Natalya Kot [:nkot]]

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

Comment 24

[Sotaro Ikeda [:sotaro]]

From comment 23, it seems clear that this bug is not graphics bug, but a bug around sd driver.

Comment 25

[Sotaro Ikeda [:sotaro]]

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

Comment 26

[Milan Sreckovic [:milan] (needinfo for best results)]

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?

Comment 27

[Jason Smith [:jsmith]]

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

Comment 28

[Milan Sreckovic [:milan] (needinfo for best results)]

Dave?

Comment 29

[Dave Hylands [: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.

Comment 30

[Sotaro Ikeda [:sotaro]]

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

Comment 31

[Natalya Kot [:nkot]]

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

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.

Comment 32

[Sotaro Ikeda [:sotaro]]

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

Comment 33

[Sotaro Ikeda [:sotaro]]

From the debugging, it seems that this bug is regression from the following.
 - Bug 831224 - [Music] Incorrect track length; Support variable-bitrate MP3s

Comment 34

[Thomas Zimmermann [:tzimmermann] [:tdz]]

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

Comment 35

[Sotaro Ikeda [:sotaro]]

Attachment: patch - Reduce mp3 parse chunk buffer size to 4KiB

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

Comment 36

[Milan Sreckovic [:milan] (needinfo for best results)]

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.

Comment 37

[Sotaro Ikeda [:sotaro]]

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

Comment 38

[Sotaro Ikeda [:sotaro]]

Attachment: patch v2 - Reduce mp3 parse chunk buffer size to 8KiB

Update comments.

Comment 39

[Thomas Zimmermann [:tzimmermann] [:tdz]]

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

Comment 40

[Sotaro Ikeda [:sotaro]]

https://tbpl.mozilla.org/?tree=Try&rev=1541cf26f9ef

Comment 41

[Sotaro Ikeda [:sotaro]]

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

Comment 42

[Sotaro Ikeda [:sotaro]]

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.

Comment 43

[Sotaro Ikeda [:sotaro]]

And if we want to increase buffer size more, we need to care about no regression like Bug 919793.

Comment 44

[Thomas Zimmermann [:tzimmermann] [:tdz]]

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

Comment 45

[Sotaro Ikeda [:sotaro]]

Attachment: patch v3 - Reduce mp3 parse chunk buffer size to 32KiB

Commitable patch. Change the buffer size from 8KiB to 32KiB. Carry 'chris.double: review+'

Comment 46

[Sotaro Ikeda [:sotaro]]

https://tbpl.mozilla.org/?tree=Try&rev=0280204cc789

Comment 47

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/8fb5ebe3b22a

Comment 48

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/8fb5ebe3b22a

Comment 49

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/e6472281dabf

Comment 50

[Jim Porter (:squib)]

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.

Comment 51

[Thomas Zimmermann [:tzimmermann] [:tdz]]

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.