751262 - Dalvik VM aborts and Fennec dies sometimes after Fennec and Android device are idle

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Aaron Train [:aaronmt]]

Attachment: Raw log (Nightly 05/02)

In the past two days I have seen Fennec randomly die twice with a Dalvik VM abort after Fennec and my Android device are completely idle. Both times, Fennec was the foreground application and not on about:home.

See attached log 

W/dalvikvm(21970): JNI WARNING: too many PopLocalFrame calls
W/System.err(21970): java.lang.OutOfMemoryError: out of stack in JNI PushLocalFrame
W/System.err(21970): 	at org.mozilla.gecko.GeckoAppShell.nativeRun(Native Method)
W/System.err(21970): 	at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:488)
W/System.err(21970): 	at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:112)

bp-94d1af8c-5f67-41f1-bb85-ae3122120502

https://crash-stats.mozilla.com/report/index/bp-94d1af8c-5f67-41f1-bb85-ae3122120502


-
Samsung Galaxy Nexus (Android 4.0.4)
Nightly (05/02)
Aurora (05/02)

Comment 1

[Brad Lassey [:blassey] (use needinfo?)]

qawanted to try to get STR

Comment 2

[Martijn Wargers (dead)]

https://crash-stats.mozilla.com/report/index/bp-94d1af8c-5f67-41f1-bb85-ae3122120502
0 	libdvm.so 	libdvm.so@0x5098e

I guess related to bug 730890, bug 750965 and bug 751343.

Comment 3

[Aaron Train [:aaronmt]]

Attachment: Full raw log (Nightly 05/03)

I can reproduce this visiting http://www.iex.nl/ (after the Android app message), and leaving my phone idle for about five minutes.

When my screen turns off GeckoAppShell continues to taking whole-screen screenshots, is that right?

Comment 4

[Kartikaya Gupta (email:[e-mail])]

Last log line before crashing is:

W/Surface ( 1781): Surface.finalize() has work. You should have called release() (4347488, 0)

Sounds like a case for super-snorp!

Comment 5

[Aaron Train [:aaronmt]]

Attachment: Another full raw log (Nighty 05/05)

Another full raw log (Nightly 05/05) - idling on a mobile Gizmodo article for about 15 minutes.

Comment 6

[Kartikaya Gupta (email:[e-mail])]

The new log indicates a dependency on bug 748531. The nightly from the 5th didn't have the patches from that bug; an updated log with a newer nightly might be useful in pinpointing the problem.

Comment 7

[Brad Lassey [:blassey] (use needinfo?)]

Attachment: patch

this is a speculative fix based on what cpeterson described the bug to be on irc

Comment 8

[Chris Peterson [:cpeterson]]

Attachment: PushLocalFrame.log (Aurora 05/08)

Yet another raw log with some "JNI WARNING: too many PopLocalFrame calls" proceeding a crash.

Comment 9

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 622225 [details] [diff] [review]
patch

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

The patch itself is fine, but it won't fix anything except remove a bunch of JNI warnings from the log. The root cause is still us running out of memory somewhere and causing the PushLocalFrame to fail.

::: widget/android/AndroidBridge.h
@@ +569,3 @@
>      // any local refs that you need to keep around in global refs!
>      void Purge() {
>          if (mJNIEnv) {

Do we even use Purge anywhere? Can we just axe it?

Comment 10

[Kartikaya Gupta (email:[e-mail])]

Looking around for other people's use of NewDirectByteBuffer, I found this example:

http://svn.apache.org/repos/asf/tomcat/native/trunk/native/src/bb.c

Note how they call NewDirectByteBuffer and if it returns null, they free the memory they passed in. This could leak massively in our case (looking at AndroidBridge::TakeScreenshot as an example) because Java_org_mozilla_gecko_GeckoAppShell_allocateDirectBuffer does a malloc and directly passes the result to NewDirectByteBuffer. If the malloc succeeds but the NewDirectByteBuffer fails, the malloc'd memory will be leaked.

Thoughts?

Comment 11

[James Willcox (:snorp) ([e-mail]) (he/him)]

(In reply to Kartikaya Gupta (:kats) from comment #10)
> Looking around for other people's use of NewDirectByteBuffer, I found this
> example:
> 
> http://svn.apache.org/repos/asf/tomcat/native/trunk/native/src/bb.c
> 
> Note how they call NewDirectByteBuffer and if it returns null, they free the
> memory they passed in. This could leak massively in our case (looking at
> AndroidBridge::TakeScreenshot as an example) because
> Java_org_mozilla_gecko_GeckoAppShell_allocateDirectBuffer does a malloc and
> directly passes the result to NewDirectByteBuffer. If the malloc succeeds
> but the NewDirectByteBuffer fails, the malloc'd memory will be leaked.
> 
> Thoughts?

You are correct, it would leak. But do we know that's actually happening in practice very often? Also, this would not have any impact on the Java heap.

Comment 12

[Kartikaya Gupta (email:[e-mail])]

I have no idea what's actually happening in practice :)

Comment 13

[Kartikaya Gupta (email:[e-mail])]

Attachment: moar patch

Comment 14

[Kartikaya Gupta (email:[e-mail])]

https://hg.mozilla.org/integration/mozilla-inbound/rev/111174836d83
https://hg.mozilla.org/integration/mozilla-inbound/rev/a439eb29c5eb

Comment 15

[James Willcox (:snorp) ([e-mail]) (he/him)]

In the top log, the following gets dumped:

W/dalvikvm(21970): JNI local reference table (0xfcd580) dump:
W/dalvikvm(21970):   Last 10 entries (of 512):
W/dalvikvm(21970):       511: 0x416ac280 java.lang.String "System.err"
W/dalvikvm(21970):       510: 0x40a6e478 java.lang.Class<android.util.Log>
W/dalvikvm(21970):       509: 0x416a6e68 java.lang.OutOfMemoryError
W/dalvikvm(21970):       508: 0x4195e530 java.lang.OutOfMemoryError
W/dalvikvm(21970):       507: 0x41b7a658 java.lang.OutOfMemoryError
W/dalvikvm(21970):       506: 0x41823a70 java.lang.OutOfMemoryError
W/dalvikvm(21970):       505: 0x41a2c358 java.lang.OutOfMemoryError
W/dalvikvm(21970):       504: 0x41a2bc60 java.lang.OutOfMemoryError
W/dalvikvm(21970):       503: 0x4195ea38 java.lang.OutOfMemoryError
W/dalvikvm(21970):       502: 0x417ac950 java.lang.OutOfMemoryError
W/dalvikvm(21970):   Summary:
W/dalvikvm(21970):         2 of java.lang.Class (2 unique instances)
W/dalvikvm(21970):         2 of java.lang.String (2 unique instances)
W/dalvikvm(21970):       126 of java.lang.OutOfMemoryError (126 unique instances)
W/dalvikvm(21970):       382 of java.nio.ReadWriteDirectByteBuffer (382 unique instances)

I'd say the likely cause for actually running out of memory is the 382 instances of ReadWriteDirectByteBuffer. We need to find out where those are coming from.

Comment 16

[Kartikaya Gupta (email:[e-mail])]

(In reply to James Willcox (:snorp) ([e-mail]) from comment #15)
> I'd say the likely cause for actually running out of memory is the 382
> instances of ReadWriteDirectByteBuffer. We need to find out where those are
> coming from.

I don't think the ReadWriteDirectByteBuffers are taking up a significant amount of space, I think those are just local refs left behind in the JNI table from us not handling the OOMs properly. That is, the OOM happens first and then we start leaking those refs in the local ref table, and then we crash when the table fills up, rather than the buffers being leaked and causing the OOMs.

Comment 17

[Kartikaya Gupta (email:[e-mail])]

Also, if you want the bug to stay open you should take it and put a whiteboard annotation, rather than changing the target milestone.

Comment 18

[Joe Drew (not getting mail)]

https://hg.mozilla.org/mozilla-central/rev/a439eb29c5eb

Comment 19

[Joe Drew (not getting mail)]

https://hg.mozilla.org/mozilla-central/rev/111174836d83

Comment 20

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 622225 [details] [diff] [review]
patch

[Approval Request Comment]
Regression caused by (bug #): 
User impact if declined: possibly crashes? not really sure if this actually helps or not.
Testing completed (on m-c, etc.): on m-c
Risk to taking this patch (and alternatives if risky): android-only, fairly low risk
String changes made by this patch: none

Comment 21

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 622396 [details] [diff] [review]
moar patch

[Approval Request Comment]
Regression caused by (bug #): 
User impact if declined: potential memory leak
Testing completed (on m-c, etc.): on m-c
Risk to taking this patch (and alternatives if risky): android-only, fairly low risk
String changes made by this patch: none

Comment 22

[Aaron Train [:aaronmt]]

Verified Fixed via (Nightly 05/14), Galaxy Nexus (4.0.4)

Comment 23

[Kartikaya Gupta (email:[e-mail])]

https://hg.mozilla.org/releases/mozilla-aurora/rev/ff46c92d32e6
https://hg.mozilla.org/releases/mozilla-aurora/rev/6b1cf014bfd5

Comment 24

[Adrian Tamas (:AdrianT)]

The issue has been fixed and uplifted to Aurora. Removing regression-wanted.