1032638 - [b2g][tarako] after 16hr monkey test, processing speed of phone is slow

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::Music, defect, P3)

Description

[Wayne Chen [:xwaynec]]

1. execute monkey test for 16hr
2. each time of app launch is slow


use "adb shell top -m 10 -t" find that b2g cpu time is too high.


User 68%, System 30%, IOW 0%, IRQ 0%
User 218 + Nice 0 + Sys 98 + Idle 0 + IOW 0 + IRQ 0 + SIRQ 1 = 317

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
 9182 14827  0  47% R 155176K  44144K  fg root     StreamTrans #27 /system/b2g/b2g
 9182 13650  0  46% R 155176K  44144K  fg root     StreamTrans #20 /system/b2g/b2g
   63    63  0   3% S      0K      0K  fg root     mmcqd/0
15034 15034  0   1% R   1048K    456K  fg root     top             top
14737 14737  0   0% S      0K      0K  fg root     kworker/0:0



User 70%, System 27%, IOW 0%, IRQ 0%
User 226 + Nice 0 + Sys 89 + Idle 0 + IOW 3 + IRQ 0 + SIRQ 1 = 319

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
 9182 14827  0  47% R 155176K  44144K  fg root     StreamTrans #27 /system/b2g/b2g
 9182 13650  0  46% R 155176K  44144K  fg root     StreamTrans #20 /system/b2g/b2g
   63    63  0   3% R      0K      0K  fg root     mmcqd/0
15034 15034  0   1% R   1048K    456K  fg root     top             top
    7     7  0   0% S      0K      0K  fg root     suspend



User 66%, System 33%, IOW 0%, IRQ 0%
User 212 + Nice 0 + Sys 105 + Idle 0 + IOW 1 + IRQ 0 + SIRQ 0 = 318

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
 9182 14827  0  48% R 155176K  44144K  fg root     StreamTrans #27 /system/b2g/b2g
 9182 13650  0  46% R 155176K  44144K  fg root     StreamTrans #20 /system/b2g/b2g
   63    63  0   2% S      0K      0K  fg root     mmcqd/0
15034 15034  0   1% R   1048K    456K  fg root     top             top
  657   657  0   0% S   4464K    172K  fg root     adbd            /sbin/adbd

Comment 1

[Wayne Chen [:xwaynec]]

Attachment: mtlog-end-sp6821a_gonk-hudson-eng.dannyliang.20140626.173628-mozilla_BM6875_BM6675_BP6375-1407010820.tar.bz2

Comment 2

[Wayne Chen [:xwaynec]]

Hi Ethan,

Please have a look.
Thanks

Sincerely,
Wayne

Comment 3

[thomas tsai]

Hi Ethan: can you help to check if this is "necko" or network issue?
Hi Wayne : can you find the necko owner?

Comment 4

[Ethan Tseng [:ethan]]

(In reply to Wayne Chen [:xwaynec] from comment #2)
> Hi Ethan,
> Please have a look.
> Thanks

Sure. I will look into this issue to see what we can do.
(I carelessly cleared my needinfo by editing the CC list yesterday).

Comment 5

[Ethan Tseng [:ethan]]

(In reply to thomas tsai from comment #3)
> Hi Ef than: can you help to check ithis is "necko" or network issue?
> Hi Wayne : can you find the necko owner?

Thomas, I'll do some investigation on this bug.
Meanwhile, the necko owner is Patrick McManus. :)

Comment 6

[Wayne Chang [:wchang]]

Thanks Ethan.
cc'ing Patrick

Comment 7

[Henry Chang [:hchang]]

Possible infinite loop running in nsStreamTransportService::mPool:

http://dxr.mozilla.org/mozilla-central/source/xpcom/io/nsStreamUtils.cpp#290

If we can luckily gdb the device, we may check if it is at this point.

Comment 8

[Patrick McManus [:mcmanus]]

is this a recent regression? you should probably look at bug 1024027

Comment 9

[Wayne Chen [:xwaynec]]

There is another test result today. Not happened in StreamTransport, but CPU is still high because running b2g process. 

After debug by gdb, We found that b2g stuck in music app. 

0 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":246]
1 parseMoovAtom() ["app://music.gaiamobile.org/js/metadata_scripts.js":1049]
2 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":1009]
3 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":55]


Thanks for Ting-Yuan's help.

Comment 10

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

unless the overall stability test isn't pass, let's put this to backlog. thanks

Comment 11

[Danny Liang [:dliang]]

(In reply to Wayne Chen [:xwaynec] from comment #9)
> There is another test result today. Not happened in StreamTransport, but CPU
> is still high because running b2g process. 
> 
> After debug by gdb, We found that b2g stuck in music app. 
> 
> 0 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":246]
> 1 parseMoovAtom() ["app://music.gaiamobile.org/js/metadata_scripts.js":1049]
> 2 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":1009]
> 3 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":55]
> 
> 
> Thanks for Ting-Yuan's help.

Hi Dominic, could you help to check if any possibility to cause higher CPU usage of b2g. Thanks.

Comment 12

[Dominic Kuo [:dkuo]]

(In reply to Danny Liang [:dliang] from comment #11)
> Hi Dominic, could you help to check if any possibility to cause higher CPU
> usage of b2g. Thanks.

The metadata parser(metadata_scripts.js) is used when the media apps(in this case is Music) needed to parse some newly added files in the storages, it should cause some CPU when the first time we launch the media apps, because we need to scan then parse all the new files.

So this means it depends on how many files are in your storages, if the monkey test setup with large user collection, then it make sense that the media apps need to parse all the files which might use/occupy the CPU for a while, but that's necessary for the media apps' first time launch, or users won't be able to view their files.

Probably we could change the setup for the user collection of the monkey test, and see if the CPU usage changes, though I don't know  the details for monkey test, so just give what I think, let me know if you need more information, thanks.

Comment 13

[Danny Liang [:dliang]]

(In reply to Dominic Kuo [:dkuo] from comment #12)
> (In reply to Danny Liang [:dliang] from comment #11)
> > Hi Dominic, could you help to check if any possibility to cause higher CPU
> > usage of b2g. Thanks.
> 
> The metadata parser(metadata_scripts.js) is used when the media apps(in this
> case is Music) needed to parse some newly added files in the storages, it
> should cause some CPU when the first time we launch the media apps, because
> we need to scan then parse all the new files.
> 
> So this means it depends on how many files are in your storages, if the
> monkey test setup with large user collection, then it make sense that the
> media apps need to parse all the files which might use/occupy the CPU for a
> while, but that's necessary for the media apps' first time launch, or users
> won't be able to view their files.
> 
The media files in the storage is same as other devices, but only one device met this issue.

> Probably we could change the setup for the user collection of the monkey
> test, and see if the CPU usage changes, though I don't know  the details for
> monkey test, so just give what I think, let me know if you need more
> information, thanks.

It should be normal if metadata_script.js consume higher CPU usage at first launch. In this case, CPU always keep higher usage, so I wonder if there is endless loop in metadata_script.js.
Now I have a device w/ this situation (higher CPU usage) and gdb can be attached, is it helpful to address the problem?

Comment 14

[Danny Liang [:dliang]]

Hi Dominic, I uploaded the sdcard of device on google drive, please help to check it. Thanks
https://drive.google.com/a/mozilla.com/uc?id=0B_tUQnuek4vvVXlHellzTHN1dVk&export=download

Comment 15

[Dominic Kuo [:dkuo]]

Quick update:

With Danny's test data, I found there are some files which seems broken the metadata parser, but I need more time to investigate the root cause and probably come out some patch, will update tomorrow.

Comment 16

[Danny Liang [:dliang]]

I am wonder if music is the only possible reason to cause b2g was killed. I have setup 4 devices monkey test w/o music icon on homescreen to narrow down the issue. Let's see if any b2g kills in this test condition.

Comment 17

[Dominic Kuo [:dkuo]]

(In reply to Danny Liang [:dliang] from comment #16)
> I am wonder if music is the only possible reason to cause b2g was killed. I
> have setup 4 devices monkey test w/o music icon on homescreen to narrow down
> the issue. Let's see if any b2g kills in this test condition.

I think probably not because what I saw is the metadata parser stop parsing on some file, so the mediadb didn't successfully record all the files, and just showed the gray messages overlay. This should only occupy CPU but won't cause OOM I think, though currently b2g does not handle this case that some app using all the CPU resource but that shouldn't cause a b2g crash.

Comment 18

[Dominic Kuo [:dkuo]]

(In reply to Dominic Kuo [:dkuo] (Media Apps Work Week, July 14-18) from comment #15)
> Quick update:
> 
> With Danny's test data, I found there are some files which seems broken the
> metadata parser, but I need more time to investigate the root cause and
> probably come out some patch, will update tomorrow.

Apologize I didn't have much time to find the file that broke the metadata parser before I leave Taipei. But I am pretty sure one of the test files did cause this issue on the mediadb because I also tested on flame with master, it happened as well. That means we should probably fix it not just for 1.3t but also master, but this shouldn't be a blocker and won't be I guess, because I believe the broken file is also not playable on the other os/platform, and it make no sense the use that file in the monkey test. Could we have someone to help on finding that file? in case I am in the media work week and won't be available all the time to work on this issue, thanks.

Comment 19

[Tim Guan-tin Chien [:timdream] (please needinfo)]

Kinking the issue to Music since the issue is now identified there.

Hema, this bug need to be dealt with 1.3T priority if it's remain to be considered as a blocker. I understand Dominic and rest of the Music engineers is currently on a work week, can you organize people to help out this issue? Thanks.

Comment 20

[Danny Liang [:dliang]]

The file with bad metadata should be /extsdcard/DCIM/108MZLLA/VID_0161.3gp

05-14 22:59:08.710 E/GeckoConsole(   84): Content JS WARN at app://music.gaiamobile.org/js/metadata_scripts.js:452 in parseAudioMetadata: /extsdcard/DCIM/108MZLLA/VID_0161.3gp

JS call stack by GDB:
0 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":246]
1 parseMoovAtom() ["app://music.gaiamobile.org/js/metadata_scripts.js":1051]
2 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":1011]
3 anonymous() ["app://music.gaiamobile.org/js/metadata_scripts.js":55]

Top:
User 84%, System 15%, IOW 0%, IRQ 0%
User 97 + Nice 0 + Sys 18 + Idle 0 + IOW 0 + IRQ 0 + SIRQ 0 = 115

  PID PR CPU% S  #THR     VSS     RSS PCY UID      Name
   84  0  85% R    42 152348K  62072K  fg root     /system/b2g/b2g
 4199  0   4% R     1   1004K    412K  fg shell    top
  108  0   2% S     7   6516K    208K  fg shell    /sbin/adbd
   57  0   1% S     1      0K      0K  fg root     kworker/u:1
  438  0   0% S     1      0K      0K  fg root     kworker/0:2

Comment 21

[Danny Liang [:dliang]]

Attachment: VID_0161.3gp

the file will cause CPU busy in metadata_script.js

Comment 22

[Vincent Liu[:vliu]]

(In reply to Danny Liang [:dliang] from comment #21)
> Created attachment 8455220 [details]
> VID_0161.3gp
> 
> the file will cause CPU busy in metadata_script.js

Basically this file has parsing problem and can't play it even using VLC in PC. The below message is the fail message when I parsed it by MP4Box.

[iso file] Box "stsz" size 3436 invalid (read 3437)

Comment 23

[Dominic Kuo [:dkuo]]

Attachment: patch

Here is the wip, I still need to check if my patch breaks the other iso based(MP4, 3GP...) formats.

Comment 24

[Hema Koka [:hema]]

Dominic is looking into this.

Comment 25

[Dominic Kuo [:dkuo]]

Comment on attachment 8455272 [details] [review]
patch

Jim,

As we discussed offline, after I removed the two unnecessary lines, the patch works for me, would you please review it first while I am still testing the other iso based files? thanks.

Comment 26

[Jim Porter (:squib)]

Comment on attachment 8455272 [details] [review]
patch

Assuming this fixes things, this looks good to me!

Comment 27

[Dominic Kuo [:dkuo]]

(In reply to Jim Porter (:squib) from comment #26)
> Comment on attachment 8455272 [details] [review]
> patch
> 
> Assuming this fixes things, this looks good to me!

Thanks Jim, I have tested the patch and it dose identify the broken VID_0161.3gp in attachment 8455220 [details], also successfully parsed the other iso base files.

master: 968c5d2df7b5416fc18b852fa1cb372d366d8c75

Comment 28

[Dominic Kuo [:dkuo]]

Thomas, this should be uplifted to 1.3t, right? thanks.

Comment 29

[Wayne Chang [:wchang]]

a leak to fix.

Thanks Dominic.

Comment 30

[Dominic Kuo [:dkuo]]

1.3t: 917df2408cae1ada82e3cf127620cad2eef24c91

Comment 31

[Tim Guan-tin Chien [:timdream] (please needinfo)]

Dominic, thanks for the quick turnaround. Do we have any tests in metadata parser to cover this?

Comment 32

[Dominic Kuo [:dkuo]]

(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) (please ni?) from comment #31)
> Dominic, thanks for the quick turnaround. Do we have any tests in metadata
> parser to cover this?

No, we should but currently we don't. ISO base media files contains lots of formats, like m4a, mp4, 3gp..., we should study the spec then try to fix the leaks of the metadata parser then have some test plans to cover it, because I believe we still missing several logic to parse the iso base files, and that's why this kind of broken file is able to mess up our parser.

This sounds like something we should have and probably Jim or I can help on this, or mentor someone if he/she is interested in it, I will try to bring up this topic in the media apps work week, let's discuss after I went back to Taipei :)

Anyway, I do test with some real m4a and 3gp songs to make sure it broke nothing, the other formats like mp3 or ogg are not affected.

Comment 33

[Ryan VanderMeulen [:RyanVM]]

(In reply to Wayne Chang [:wchang] from comment #29)
> a leak to fix.
> 
> Thanks Dominic.

Did you intend to mark this as 1.3+ or 1.3T+? Assuming 1.3T+ was the intent, are we going to want approval requests for v1.4 and v2.0 uplift as well?

Comment 34

[Wayne Chang [:wchang]]

it was meant for 1.3t+.

as for 1.4 and 2.0 approval i'll ask dominic to see if they are applicable and needed.

Comment 35

[Wayne Chang [:wchang]]

oops, wrong flag was set. apologies

Comment 36

[yaoyao.wu]

Hi Dominic,

In the monkey test of 1.4 ,there occurs error:

***********************************************************************************
08-03 13:43:50.290   778   778 E GeckoConsole: [JavaScript Error: "AbortError"]
08-03 13:43:50.290   778 30078 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]
08-03 13:43:50.340 30190 30190 I Gecko   : ############################### browserElementPanning.js loaded
08-03 13:43:50.390   778   778 E GeckoConsole: [JavaScript Error: "AbortError"]
08-03 13:43:50.400   778 30088 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]
08-03 13:43:50.400   778   778 E GeckoConsole: [JavaScript Error: "AbortError"]
08-03 13:43:50.400   778 30064 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]
08-03 13:43:50.400   778   778 E GeckoConsole: [JavaScript Error: "AbortError"]
08-03 13:43:50.400   778 30078 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]
08-03 13:43:50.400   778   778 E GeckoConsole: [JavaScript Error: "AbortError"]
08-03 13:43:50.400   778 30219 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]
08-03 13:43:50.400   778   778 E GeckoConsole: [JavaScript Error: "AbortError"]
08-03 13:43:50.400   778 30220 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]
*********************************************************************************************

I think the patch of the bug isn't add to v1.4.
Would you please help to check if the error is related to your patch.
If it is ,would you please help to land it on v1.4.
Thanks a lot.

Comment 37

[Dominic Kuo [:dkuo]]

What I saw(before applying the patch) in this bug is, the music app will enter an infinite loop while parsing the metadata, but I didn't see those errors while I was testing my patch. The errors looks like the indexedDB errors but shows unknown errors(maybe it's timeout), so I couldn't make sure my patch for v1.3t does fix it for v1.4.

But if v1.4 also setup the monkey test, then we should uplift this to v1.4 or the monkey test will also failed with the same result.(v2.0 is also affected so probably we should uplift it as well)

Comment 38

[Dominic Kuo [:dkuo]]

Comment on attachment 8455272 [details] [review]
patch

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): first time occur.
[User impact] if declined: monkey test will be failed and the user could be blocked by some corrupted audio files.
[Testing completed]: no test case included but pass the monkey test on v1.3t.
[Risk to taking this patch] (and alternatives if risky): low.
[String changes made]: none.

Thanks.

Comment 39

[bhavana bajaj [:bajaj]]

wayne, can you confirm you are able to reproduce this on flame or a production device running 2.0  for us to consider the uplift in 2.0 ?

Comment 40

[Wayne Chang [:wchang]]

(In reply to bhavana bajaj [:bajaj] from comment #39)
> wayne, can you confirm you are able to reproduce this on flame or a
> production device running 2.0  for us to consider the uplift in 2.0 ?

Yes I have confirmed this with :dkuo and also the code logic is there.

Comment 41

[Ryan VanderMeulen [:RyanVM]]

v2.0: https://github.com/mozilla-b2g/gaia/commit/00298284078b0595826df485dd7aa79820bae1fc
v1.4: https://github.com/mozilla-b2g/gaia/commit/2b2849a61cd38e909ed1c3e4586d104bc96f7001