936285 - [B2G][Poppit] App closes intermittently during gameplay

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[Sarah Parsons]

Description:
Poppit will intermittently close and take the user back to the homescreen during gameplay. This was seen while playing a level, changing the difficulty level, and starting a new game.

Repro Steps:
1) Updated Buri to BuildID: 20131107004003
2) Go to the Market Place and install Poppit.
3) Launch the App.
4) Play for a few minutes, change the difficulty level or start a new game.

Actual:
App closes, taking the user back to the homescreen. 

Expected:
App should remain open, until the user decides to close it.

Environmental Variables:
Device: Buri 1.2 
BuildID: 20131107004003
Gaia: 590eb598aacf1e2136b2b6aca5c3124557a365ca
Gecko: 26f1e160e696
Version: 26.0

Repro frequency: 3/8

Comment 1

[Sotaro Ikeda [:sotaro]]

From Bug 918978 Comment 39, it is not a problem on b2g v1.3.

Comment 2

[bhavana bajaj [:bajaj]]

Sotaro, might still be a blocker for 1.2 if this is reproducible. Do you happen to know if we are missing some uplifts to resolve this in 1.2 ? Or would logs from QA be helpful here to debug the issue?

Comment 3

[Sotaro Ikeda [:sotaro]]

I temporarily assigned myself to check Comment 2.

Comment 4

[Sotaro Ikeda [:sotaro]]

(In reply to bhavana bajaj [:bajaj] from comment #2)
> Sotaro, might still be a blocker for 1.2 if this is reproducible. Do you
> happen to know if we are missing some uplifts to resolve this in 1.2 ?

I do not know about it.

Comment 5

[Jason Smith [:jsmith]]

How exactly is a OOM issue not a memshrink issue?

Comment 6

[Andrew McCreight [:mccr8]]

There doesn't appear to be any evidence in this bug that it is actually an OOM bug.  We need some kind of memory log to see if that's actually the problem.

Comment 7

[Jason Smith [:jsmith]]

(In reply to Andrew McCreight [:mccr8] from comment #6)
> There doesn't appear to be any evidence in this bug that it is actually an
> OOM bug.  We need some kind of memory log to see if that's actually the
> problem.

I think there's quite clear evidence actually. If a process is abnormally killed during usage without a crash reporter dialog, it's likely an OOM. This is an already known followup bug to an OOM issue with Poppit & a bug that has reoccurred in past releases as an OOM. Poppit is also a memory intensive application that has hit this issue historically.

We can get an additional log here, but I'm pretty sure this is an OOM based on historical evidence of this reoccurring regression.

In the future - I think it would be wise to isolate something isn't a memory issue before removing the flag. Throwing it out too quickly is going to cost triage confusion on who can help investigate issues.

Comment 8

[Jason Smith [:jsmith]]

QA Wanted - Can someone get a logcat & a dmesg log by running adb shell dmesg when reproducing this bug?

Reference you'll want to use to diagnose this - https://wiki.mozilla.org/B2G/Debugging_OOMs#Step_1:_Verify_that_it.27s_actually_an_OOM.

Comment 9

[Nicholas Nethercote [inactive]]

> In the future - I think it would be wise to isolate something isn't a memory
> issue before removing the flag. Throwing it out too quickly is going to cost
> triage confusion on who can help investigate issues.

Sure.  But don't overestimate the power of a [MemShrink] tag.  It means we've looked at the bug at a MemShrink meeting and given a coarse estimate of its importance.  It doesn't mean that someone is actually going to look at it.

Comment 10

[Sarah Parsons]

Here is the dmesg log:

<6>[ 2275.650666] [adsp.c:msm_adsp_get] opening module AUDPPTASK
<6>[ 2275.651509] [adsp.c:msm_adsp_enable] enable 'AUDPPTASK'state[0] id[17227122]
<6>[ 2275.652281] [adsp.c:handle_adsp_rtos_mtoa_app] module AUDPPTASK: READY
<6>[ 2275.660114] [audpp.c:audpp_dsp_event] ENABLE
<6>[ 2282.358869] [audpp.c:audpp_dsp_event] DISABLE
<6>[ 2282.358923] [audpp.c:audpp_disable] Received CFG_MSG_DISABLE from ADSP
<6>[ 2282.358936] [adsp.c:msm_adsp_disable] disable 'AUDPPTASK'
<6>[ 2282.359778] [adsp.c:msm_adsp_put] closing module AUDPPTASK
<6>[ 2282.359816] [audmgr.c:audmgr_disable] session 0xc0949688
<6>[ 2282.361314] [audmgr.c:audmgr_rpc_thread] rpc_reply status 0
<3>[ 2282.371333] [audmgr.c:process_audmgr_callback] DISABLED
<4>[ 2290.902084] select 3417 (Poppit!"), adj 10, size 19650, to kill
<4>[ 2290.902103] send sigkill to 3417 (Poppit!"), adj 10, size 19650
<6>[ 2291.275769] [audio_mp3.c:audio_release] audio instance 0xc79d0c00 freeing
<6>[ 2291.275793] [adsp.c:msm_adsp_put] closing module AUDPLAY0TASK
<6>[ 2291.275829] [audpp.c:audpp_adec_free] free decid =0 

Also, see logcat attached.

Comment 11

[Sarah Parsons]

Attachment: Poppit_Logcat

Comment 12

[Jason Smith [:jsmith]]

This line:

<4>[ 2290.902103] send sigkill to 3417 (Poppit!"), adj 10, size 19650

Indicates this is an OOM.

Comment 13

[Jason Smith [:jsmith]]

QA Wanted - does this reproduce with the 1.2 Buri base image with the latest 1.2 gaia/gecko changes?

Comment 14

[Karen Ward [:kward]]

Nominated at koi+.  Yes this needs to work for V1.2.  Poppit (Electronic Arts) is premier partner that is preloaded by most Carriers and we have additional EA games in the pipeline that are likely to have similiar resource demands.

Comment 15

[Andrew McCreight [:mccr8]]

In order to figure out why it is OOMing, we need the memory reports, as described in step 2 of the link jsmith posted.  The memory reports should be captured before the app closes.  As close as possible to the failure would be nice, but we may be able to figure something out from any old report while it is running.

Comment 16

[Sarah Parsons]

This issue still reproduces on Buri 1.2 Build ID: 20131114004004
 
Gaia   3e67ddf7d2680d1ef01441641f4ca2e0e4006887
SourceStamp 948e30162eac
BuildID 20131114004004
Version 26.0
Base: 20131111

dmesg log: 

<6>[  291.581164] [adsp.c:handle_adsp_rtos_mtoa_app] module AUDPPTASK: READY
<6>[  291.588953] [audpp.c:audpp_dsp_event] ENABLE
<6>[  297.092558] [audpp.c:audpp_dsp_event] DISABLE
<6>[  297.092604] [audpp.c:audpp_disable] Received CFG_MSG_DISABLE from ADSP
<6>[  297.092618] [adsp.c:msm_adsp_disable] disable 'AUDPPTASK'
<6>[  297.093584] [adsp.c:msm_adsp_put] closing module AUDPPTASK
<6>[  297.093623] [audmgr.c:audmgr_disable] session 0xc0947688
<6>[  297.095558] [audmgr.c:audmgr_rpc_thread] rpc_reply status 0
<3>[  297.106059] [audmgr.c:process_audmgr_callback] DISABLED
<4>[  298.026668] select 574 (Poppit!"), adj 10, size 18907, to kill
<4>[  298.026688] send sigkill to 574 (Poppit!"), adj 10, size 18907
<6>[  298.437139] [audio_mp3.c:audio_release] audio instance 0xc26d5c00 freeing
<6>[  298.437163] [adsp.c:msm_adsp_put] closing module AUDPLAY0TASK

Comment 17

[Sotaro Ikeda [:sotaro]]

I updated to new partner built ROM that include pmem fallback. On the ROM, the poppit was easily crashed. I felt something is weird. I checked b2g.js in the ROM by the following command.

   > adb pull /system/b2g/omni.ja
   > unzip omni.ja 

b2g.js does not have following line. Bug 920160 seems not applied to the new partner built ROM.
  > pref("gfx.canvas.skiagl.dynamic-cache", true);

Comment 18

[Sotaro Ikeda [:sotaro]]

Around skia's cache Bug 927254 was fixed on master. But it is not applied to b2g 1.2. Bug 927254 seems to affect to the crash. It needs to uplift to b2g v1.2.

Comment 19

[Sotaro Ikeda [:sotaro]]

(In reply to Sotaro Ikeda [:sotaro] from comment #18)
> Around skia's cache Bug 927254 was fixed on master. But it is not applied to
> b2g 1.2. Bug 927254 seems to affect to the crash. It needs to uplift to b2g
> v1.2.

From Comment 0, the crash happens to load more resources. Bug 927254 is to purge cache during memory-pressure event. So, it could help the poppit is killed by low memory killer.

Comment 20

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

Snorp, how do you feel about uplifting bug 927254?

Comment 21

[Jason Smith [:jsmith]]

Fixed via uplift of bug 927524.

Comment 22

[Jason Smith [:jsmith]]

(In reply to Jason Smith [:jsmith] from comment #21)
> Fixed via uplift of bug 927524.

Meant to say bug 927254.

Comment 23

[Roland Kunkel [:RolandK]]

This issue is still occurring on the latest v1.2 Buri build. Opening the app and changing the difficulty will often result in the app freezing on the confirmation screen and /or the app closing out without the changes taking place.

Environmental Variables
Device: Buri v 1.2 COM RIL
Build ID: 20131203004002
Gecko: http://hg.mozilla.org/releases/mozilla-b2g26_v1_2/rev/244e98241b2c
Gaia: c8f14ad3950d59ba13d7639eff02d080060bb3ce
Platform Version: 26.0
RIL Version: 01.02.00.019.102 
Firmware Version: V1.2_US_20131115

Comment 24

[Jason Smith [:jsmith]]

(In reply to rkunkel from comment #23)
> This issue is still occurring on the latest v1.2 Buri build. Opening the app
> and changing the difficulty will often result in the app freezing on the
> confirmation screen and /or the app closing out without the changes taking
> place.
> 
> Environmental Variables
> Device: Buri v 1.2 COM RIL
> Build ID: 20131203004002
> Gecko: http://hg.mozilla.org/releases/mozilla-b2g26_v1_2/rev/244e98241b2c
> Gaia: c8f14ad3950d59ba13d7639eff02d080060bb3ce
> Platform Version: 26.0
> RIL Version: 01.02.00.019.102 
> Firmware Version: V1.2_US_20131115

The app freezing is still being worked on. Let's relook at this again after bug 933483 lands.

Comment 25

[Harvey]

Removing Verify me tag per comment 23.

Comment 26

[Jason Smith [:jsmith]]

(In reply to jharvey from comment #25)
> Removing Verify me tag per comment 23.

Nope - this still needs to be tested again as the bug we are waiting on has landed.

Comment 27

[Brogan Zumwalt [Inactive]]

Freezing still occurs on latest 1.2 through a combination of new games and difficulty changes after playing for a few minutes. Repros 100% of time, may need to repeat STR multiple times. As bug 933483 landed yesterday I'm reopening this bug.

Environmental Variables:
Device: Buri v1.2 COM RIL
BuildID: 20140128004004
Gaia: 539a25e1887b902b8b25038c547048e691bd97f6
Gecko: d10e1f965d0c
Ril: 01.02.00.019.102
Version: 26.0
Firmware Version: V1.2-device.cfg

Comment 28

[Ben Kelly [:bkelly, not reviewing]]

I'm not sure about the freezing, but in regards to poppit closing due to OOMs:

About half of poppit's 70MB working set is due to the app loading each of its various sound effects four times.

I'm currently working on bug 960873 to make our mp3 buffering more efficient.  This will save us around 12MB for poppit.  This moves us from 70MB to ~58MB.

The single most effective thing that could be done, however, would be for poppit to tune its audio loading or use web audio as described in bug 959603.  Tuning its sound channels from 4 to 2 would move the app under 50MB when combined with bug 960873.  Using web audio puts it at 40MB (regardless of bug 960873).

Whats more, it should be very easy for the app developer to move poppit to web audio.  The game is written on impactjs.  The git repository available to all impactjs license holders has a version of lib/impact/sound.js which implements web audio.  The author informs me this git version should be released in the next few weeks as impactjs v1.24.

Comment 29

[Jason Smith [:jsmith]]

Please file a new bug for the issue you found.

Comment 30

[Brogan Zumwalt [Inactive]]

New bug filed: https://bugzilla.mozilla.org/show_bug.cgi?id=965369