852043 - [Buri][Music Player] an audio file (wma file) with wrong extension (set to mp3) causes device to become painfully slow

Status: VERIFIED FIXED

(Firefox OS Graveyard :: General, defect, P1)

Description

[sync-1]

Firefox os  v1.0.1
 Mozilla build ID: 20130310070203.
 
 +++ This bug was initially created as a clone of Bug #420465 +++
 
 DEFECT DESCRIPTION:
 (1)Insert one SD card with about 520 music files
 (2)Go to Music, it start scanning. After a while, light the screen, unlock the screen, you will see a white screen for more than 10 seconds before the music screen is shown --- NOK1
 (3)The scanning will be blocked at 116th song, never going on --- NOK2
 (4)Try to go back to home by home key, need to wait for 5 mins to see home screen displayed ---- NOK3
 (5)All the NOKs are always there before you kill the music player.
 (6)try to launch the Music player again, it will start scanning again, but it will stopped at about 300th...same NOKs appear again.
 
 And we can see the Music player process nearly always occupy above 90% CPU. Never rest if you don't kill it.
 
 
 REPRODUCING PROCEDURES:
 
 EXPECTED BEHAVIOUR:
 
 ASSOCIATE SPECIFICATION:
 
 TEST PLAN REFERENCE:
 
 TOOLS AND PLATFORMS USED:
 
 USER IMPACT:
 Serious, the music player nearly useless, if user want to listen to some music in this case, the phone will totally slow for other functions.
 
 REPRODUCING RATE:
 100%(with the dedicated SD card)
 
 For FT PR, Please list reference mobile's behavior:
 
 ++++++++++ end of initial bug #420465 description ++++++++++

Comment 1

[buri.blff]

Attachment: wma.mp3

this it the music file , which causes the problem.

Comment 2

[sync-1]

Defect analysis:
 ===============
 
 Its

Comment 3

[buri.blff]

Defect analysis:
===============

It's not really a performance problem. One thread of the Music app runs into an
infinite loop, taking all the CPU.

You can find which thread with a "cat /proc/<pid>/task/*/stat". All the threads
are sleeping, except one: "764 (Media Decode) R 146 146 0 0 -1 ..."

---

By using GDB and checking the callstack of this thread many times, one can find
the root of the infinite loop (i.e. the frames common to all callstacks):

#10 DecodeToFirstData<AudioData>()
#11 nsBuiltinDecoderReader::FindStartTime()
#12 nsBuiltinDecoderStateMachine::FindStartTime()
#13 nsBuiltinDecoderStateMachine::DecodeMetadata()
#14 nsBuiltinDecoderStateMachine::DecodeThreadRun()
#15 nsRunnableMethodImpl<void (nsPACMan::*)(), true>::Run()
#16 nsThread::ProcessNextEvent()
#17 NS_ProcessNextEvent_P()
#18 nsThread::ThreadFunc()
#19 _pt_root()
#20 __thread_entry()
#21 pthread_create()

---

Still with GDB, one can notice the infinite loop performs some file system
operations, and information about related file handle can be found in
/proc/<pid>/fd:
"lrwx------ app_688 57 -> /mnt/sdcard/李佳璐 -  无法原谅 .mp3"

---

I renamed it with Latin characters, but there is still an infinite loop, so it
doesn't come from the Chinese name. Please find this file in attachment.

The file is actually a WMA file, wrongfully using the "mp3" extension. If I
rename it to WMA, the problem disappears (probably because WMA is not
supported...). However, anybody can use a wrong extension, it's not a reason to
accept infinite loops...

---

I would tend to think there are two bugs to fix:
1. Analyze the error codes reported when decoding this fake MP3, and fix the
infinite loop.
2. Check magic numbers at the beginning of media files before handling a file
to the wrong codec.

Comment 4

[Dominic Kuo [:dkuo]]

Thanks [e-mail] to clarify this, sounds like it's not a performance issue but cause by a wrong file extension, changing the scary title to fit the fact of this bug.

Comment 5

[Daniel Coloma:dcoloma]

I cannot reproduce it, I have put wma.mp3 in the SDCard together with more than 100 other valid mp3 songs. I have reflashed the device with a recent 1.0.1 version (Gecko:1babdce Gaia:b34e726) and music player loads normally. 

qawanted added for trying to reproduce this.

Comment 6

[William Hsu [:whsu]]

Hi, all,

Sorry to jump in.
As I tested, I cannot reproduce this case.
The problem file(wma.mp3) you attached will be skipped during scanning.
But I found the performance of loading play list decreased while play list had many items.

The following are my test environment.
* Hardware: unagi
* Firefox OS: mozilla-b2g18_v1_0_1-unagi-eng
* Mercurial-Information:
  Gecko revision="a0eb57759a92"
  Gaia revision="72a2e37d17f6"
* Git:
  Gecko revision="f42cd79f6036df3f102fcdb59ff1ab6944305000"
  Gaia revision="b4d644dd5ea79070479a9aa1b57e2e05a6442eee"
* Test file: 574 MP3 files
If I have free time, I will try to reproduce this problem again.
Thanks!


Best Regards,
William

Comment 7

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

FYI, QA note : I will be taking a look at this bug today.

Comment 8

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

I cannot reproduce on v1 train 3/19 build nor on the 3/13 build of v1.0.1 on unagi; can you attach a logcat of the issue please?  This might be a buri only issue?

Comment 9

[Daniel Coloma:dcoloma]

Can you try to test with a recent version? Minusing until we check it is not a Buri specific issue.

Comment 10

[buri.blff]

Attachment: logcat

Here, on our latest version, it still can be reproduced 100%.

Comment 11

[Amelie Kong]

Change back for tef?, for further discussion.

Comment 12

[Daniel Coloma:dcoloma]

This bug can only be reproduced with buri hardware and we do not have buri hardware yet. Can you please at least attached the logcat as requested in comment 8? Without that we are working blind.

Comment 13

[Daniel Coloma:dcoloma]

sorry, just saw the logcat, clearing the needinfo flag...

Comment 14

[Joe Cheng [:jcheng] (please needinfo)]

dkuo: can you take a look at the logs?

Comment 15

[Joe Cheng [:jcheng] (please needinfo)]

triage: tef+ as the end user impact is severe. from partner, if the attach file is in the SD card and if the music player is scanning for the music files in SD card, the device will become very slow as music app will be occupying the CPU a lot

Comment 16

[William Hsu [:whsu]]

Hi, all,

Sorry for my jump in. Attaching the further information
I tried to reproduce this case on unagi platform with latest build again, I still can not reproduce this case. The CPU usage shows as normal(50%~60%, as CUP_USAGE log).
By the way, the file with wrong extension name was recognized as "unplayable music file" and the process didn't hang there(As LOGCAT show).
Do it relate to process handling of android kernel of buri hardware?
We had a buri test device on Taiwan side, but we still don't have time to make a correct build and flash it. So, if someone can help this on different buri devices, we would appreciate greatly.
Thanks! Have a nice day!

Build info.: 2013-03-25-07-02-01 (releases/mozilla-b2g18_v1_0_1)
Mercurial-Information: 
Gecko revision="4931ec89ebbe"
Gaia revision="5ebbe58853e5"
Git-info.:
Gecko revision="353867e8450799957646541e04470da57701ba66"
Gaia revision="701b594c3e320030c538aa19f702764b29a6cc1c"

------------------------CUP_USAGE-------------------------------
[e-mail]:~/TempData$ grep "User" CPU_USAGE
[5] 11761
User 1%, System 3%, IOW 0%, IRQ 0%
User 2%, System 3%, IOW 0%, IRQ 0%
User 3%, System 3%, IOW 0%, IRQ 0%
User 8%, System 3%, IOW 0%, IRQ 0%
User 37%, System 52%, IOW 10%, IRQ 0%
User 14%, System 67%, IOW 18%, IRQ 0%
User 33%, System 66%, IOW 0%, IRQ 0%
User 29%, System 48%, IOW 21%, IRQ 0%
User 69%, System 22%, IOW 6%, IRQ 0%
User 65%, System 26%, IOW 8%, IRQ 0%
User 58%, System 31%, IOW 9%, IRQ 0%
User 61%, System 28%, IOW 9%, IRQ 0%
User 63%, System 27%, IOW 7%, IRQ 0%
User 65%, System 21%, IOW 10%, IRQ 0%
User 56%, System 21%, IOW 20%, IRQ 0%
User 48%, System 26%, IOW 23%, IRQ 0%
User 49%, System 24%, IOW 25%, IRQ 0%
User 53%, System 21%, IOW 24%, IRQ 0%
User 50%, System 23%, IOW 25%, IRQ 0%
User 46%, System 24%, IOW 27%, IRQ 0%
User 53%, System 25%, IOW 21%, IRQ 0%
User 51%, System 23%, IOW 24%, IRQ 0%
User 46%, System 28%, IOW 25%, IRQ 0%
User 48%, System 26%, IOW 23%, IRQ 0%
User 52%, System 21%, IOW 24%, IRQ 0%
User 47%, System 23%, IOW 28%, IRQ 0%
User 44%, System 29%, IOW 25%, IRQ 0%
User 50%, System 18%, IOW 29%, IRQ 0%
User 45%, System 18%, IOW 33%, IRQ 0%
User 46%, System 15%, IOW 36%, IRQ 0%
User 41%, System 16%, IOW 38%, IRQ 0%
User 60%, System 18%, IOW 20%, IRQ 0%
User 60%, System 22%, IOW 17%, IRQ 0%
User 60%, System 19%, IOW 19%, IRQ 0%
User 40%, System 23%, IOW 35%, IRQ 0%
User 21%, System 16%, IOW 57%, IRQ 0%
User 14%, System 16%, IOW 65%, IRQ 0%
User 26%, System 16%, IOW 52%, IRQ 0%
User 14%, System 17%, IOW 64%, IRQ 0%
User 18%, System 16%, IOW 61%, IRQ 0%
User 16%, System 14%, IOW 65%, IRQ 0%
User 16%, System 19%, IOW 60%, IRQ 0%
User 25%, System 18%, IOW 54%, IRQ 0%
User 14%, System 16%, IOW 64%, IRQ 0%
User 13%, System 21%, IOW 61%, IRQ 0%
User 18%, System 16%, IOW 61%, IRQ 0%
User 16%, System 16%, IOW 64%, IRQ 0%
User 13%, System 20%, IOW 61%, IRQ 0%
User 14%, System 18%, IOW 63%, IRQ 0%
User 13%, System 16%, IOW 66%, IRQ 0%
User 14%, System 18%, IOW 63%, IRQ 0%
User 13%, System 17%, IOW 64%, IRQ 0%
User 37%, System 16%, IOW 43%, IRQ 0%

-------------------------LOGCAT--------------------------------------
[e-mail]:~/TempData$ grep "mp3" ADB_LOGCAT
E/GeckoConsole(  424): Content JS WARN at app://music.gaiamobile.org/gaia_build_defer_index.js:242 in metadataError: MediaDB: error parsing metadata for media/audio/Test_MP3/wma.mp3 : Unplayable music file
E/GeckoConsole(  424): Content JS WARN at app://music.gaiamobile.org/gaia_build_defer_index.js:242 in metadataError: MediaDB: error parsing metadata for media/audio/Test_MP3/wma (copy).mp3 : Unplayable music file
E/GeckoConsole(  424): Content JS WARN at app://music.gaiamobile.org/gaia_build_defer_index.js:242 in metadataError: MediaDB: error parsing metadata for media/audio/Test_MP3/wma (another copy).mp3 : Unplayable music file
E/GeckoConsole(  424): Content JS WARN at app://music.gaiamobile.org/gaia_build_defer_index.js:242 in metadataError: MediaDB: error parsing metadata for media/audio/Test_MP3/wma (3rd copy).mp3 : Unplayable music file
---------------------------------------------------------------------------

Comment 17

[Marco Chen [:mchen]]

Attachment: LogFromUnagi

Hi all,

After I put libmmparser.so/libDivxDrm.so/libmmosal.so into device, I can see the similar result of libstagefright.so tried to parse the file's metadata. But the difference is that this log show the normal termination of extract process and mediaDB still show it's unplayable file.

In partner's log, it seems the abnormal messages is came for libmmosal.so. So could partner help to identify the loop is happened inside the libXX.so because our media decoder is using OMX to decode mp3 extention?

Thanks.

Comment 18

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Attachment: Music app very high CPU Usage

I kept only one music file wma.mp3 in sd card and launched Music App. Music app playing loading animation continuously . Music App CPU usage is >75% always. The animation does not end even after 5 mins.

Comment 19

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Attachment: Music App logcat output

I kept only one music file wma.mp3 in sd card and launched Music App. Music app playing loading animation continuously . Music App CPU usage is >75% always. The animation does not end even after 5 mins. I attached logcat for this use case.

Comment 20

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

I used 1.0.1 latest images for above use case (comments 19 and 18)

Comment 21

[Marco Chen [:mchen]]

(In reply to Tapas Kumar Kundu from comment #20)
> I used 1.0.1 latest images for above use case (comments 19 and 18)

Hi, May I know the ICS version in codeaurora is strawberry or choclate?
Thanks.

Comment 22

[Michael Vines [:m1] [:evilmachines]]

Buri is using strawberry

Comment 23

[Dominic Kuo [:dkuo]]

(In reply to Tapas Kumar Kundu from comment #20)
> I used 1.0.1 latest images for above use case (comments 19 and 18)

Can anyone tell me what's the exact gaia commit we are using and encountered this peoblem?
I hope it's not because of the uplift leak, casue it seems fine on unagi device.

Comment 24

[Marco Chen [:mchen]]

(In reply to Dominic Kuo [:dkuo] from comment #23)
> Can anyone tell me what's the exact gaia commit we are using and encountered
> this peoblem?
> I hope it's not because of the uplift leak, casue it seems fine on unagi
> device.

I suspect this bug is caused by libmmosal.so on ICS strawberry version. That is why we can't see this issue on unagi because it is ICS Choclate version.

Comment 25

[Michael Vines [:m1] [:evilmachines]]

Dominic, I'm not sure exactly what gaia SHA1 Tapas used but it absolutely was a recent v1.0.1 SHA1, so I think we can probably discount any missing uplifts.   It could very well be a chocolate vs. strawberry issue.  

Tapas, since you can duplicate it here can you please try to debug this a little more.   Also please try on an Inari device as well.

Comment 26

[Michael Vines [:m1] [:evilmachines]]

Assigning to Tapas as this doesn't look like Gaia at the moment either, and Tapas is in a better position to dig into libmmosal.so than Dominic.

Comment 27

[Dominic Kuo [:dkuo]]

Thanks, Michael. And I finally got my buri device worked and realized what's happening here.

If the metadata of an audio file is not parseable, the metadata parser of music will try to use an audio element to test that file is playable or not, by assigning src to it and listening to the oncanplay and onerror event.

When the oncanplay/onerror event fires, music can know it's playable/unplayable and then the parser will use removeAttribute('src') then load() to release the test audio.

But on buri device, looks like oncanplay/onerror event does not fire and that "test" audio is always in decoding process and occupys CPU. Then If I try to force the test audio to release the source(removeAttribute then load), the CPU usage will become normal again. I guess it might be using a wrong decoder because of the wrong extension and broken the decoding process.

So the possible solution might need gecko to deal with files like these. If we can still decode the files with wrong extensions, the CPU will not be occupied, the oncanplay/onerror event will also fire and the metadata parser can parse normally.

Comment 28

[(no longer active)]

Seems like this is just a bug in our decoder.  Chris, can you please take a look?

Thanks!

Comment 29

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

We can't reproduce this on the QRD device with AU AU_LINUX_GECKO_ICS_STRAWBERRY.01.01.00.19.045-33-g462abdc , but it does reproduce when the Gecko/Gaia from AU AU_LINUX_GECKO_ICS_STRAWBERRY.01.01.00.19.045-33-g462abdc is placed on the Buri device.

Comment 30

[Michael Vines [:m1] [:evilmachines]]

(Just to add to comment 29, we'll be examining the differences between the QRD and Buri builds beneath Gecko to see if we can spot the issue.  At this point it's not looking very much like a Gecko bug)

Comment 31

[Alex Keybl [:akeybl]]

Tentatively marking as NPOTB given comment 30.

Comment 32

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to :Ehsan Akhgari (needinfo? me!) from comment #28)
> Seems like this is just a bug in our decoder.  Chris, can you please take a
> look?

This is more Edwin's purview than mine.

Comment 33

[Edwin Flores [inactive from 2016-12-01] [:eflores] [:edwin]]

Looks like it's sniffing it as WMA correctly. I find in the majority of funny little cases like this, the decoder just sucks.

WMA is out of scope anyway. Try deleting /system/lib/*{wma,Wma,WMA}*.so and it should skip the file.

Comment 34

[Edwin Flores [inactive from 2016-12-01] [:eflores] [:edwin]]

(I would try from here, but we don't have a Buri in the New Zealand office and I can't reproduce this on my Otoro)

Comment 35

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Does not sounds like a Gaia bug. Moving to General to reflect this.

Comment 36

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

AU_LINUX_GECKO_ICS_STRAWBERRY_V1.01.00.01.019.073 contains fixes for it.

Comment 37

[Michael Vines [:m1] [:evilmachines]]

Updated tracking flags to fixed, nothing to uplift here.

Comment 38

[Carlos Martínez Toral [:carlosmartinez]]

Tested on ikura device with more than 500 songs and is working fine. 

Gecko 
Gaia   715de4016b63d417c8fdc20b1ae8b15b666e1afb
BuildID 20130416092518
Version 18.0