757468 - OutOfMemory exception on createBitmap after 330+ page loads

Status: RESOLVED DUPLICATE of bug 774797

(Firefox for Android Graveyard :: General, defect)

Description

[Geoff Brown [:gbrown]]

After about 330 +/- 20 page loads, Fennec crashes on an OutOfMemory exception, during Bitmap.createBitmap. The sites loaded can be anything: they can all be unique, or 225 loads of the same page.

Typical logcat:

D/dalvikvm(  290): GC_FOR_ALLOC freed 615K, 5% free 58513K/61127K, paused 80ms
I/dalvikvm-heap(  290): Grow heap (frag case) to 57.359MB for 124216-byte allocation
D/dalvikvm(  290): GC_FOR_ALLOC freed 0K, 5% free 58635K/61255K, paused 80ms
D/HierarchicalStateMachine(  290): handleMessage: E msg.what=83
D/HierarchicalStateMachine(  290): processMsg: ConnectedState
D/WifiStateMachine(  290): ConnectedState{ what=83 when=-167ms arg1=1 }
D/HierarchicalStateMachine(  290): handleMessage: X
D/dalvikvm( 9962): GC_FOR_ALLOC freed 1536K, 8% free 59334K/64327K, paused 335ms
D/BatteryService(  290): update start
I/dalvikvm-heap( 9962): Forcing collection of SoftReferences for 2097168-byte allocation
D/dalvikvm( 9962): GC_BEFORE_OOM freed 36K, 8% free 59297K/64327K, paused 339ms
E/dalvikvm-heap( 9962): Out of memory on a 2097168-byte allocation.
I/dalvikvm( 9962): "GeckoBackgroundThread" prio=5 tid=10 RUNNABLE
I/dalvikvm( 9962):   | group="main" sCount=0 dsCount=0 obj=0x40873ae8 self=0x19e858
I/dalvikvm( 9962):   | sysTid=9971 nice=0 sched=0/0 cgrp=default handle=1698992
I/dalvikvm( 9962):   | schedstat=( 209844764000 22966225000 67252 ) utm=20498 stm=486 core=1
I/dalvikvm( 9962):   at android.graphics.Bitmap.nativeCreate(Native Method)
I/dalvikvm( 9962):   at android.graphics.Bitmap.createBitmap(Bitmap.java:604)
I/dalvikvm( 9962):   at android.graphics.Bitmap.createBitmap(Bitmap.java:584)
I/dalvikvm( 9962):   at org.mozilla.gecko.GeckoAppShell$3.run(GeckoAppShell.java:576)
I/dalvikvm( 9962):   at android.os.Handler.handleCallback(Handler.java:587)
I/dalvikvm( 9962):   at android.os.Handler.dispatchMessage(Handler.java:92)
I/dalvikvm( 9962):   at android.os.Looper.loop(Looper.java:132)
I/dalvikvm( 9962):   at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
I/dalvikvm( 9962): 
W/dalvikvm( 9962): threadid=10: thread exiting with uncaught exception (group=0x4020e760)
E/GeckoAppShell( 9962): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 11 ("GeckoBackgroundThread")
E/GeckoAppShell( 9962): java.lang.OutOfMemoryError

It's easy to reproduce with Robocop:

+        for (int i = 0; i < 500; i++) {
+            loadUrl("http://www.mozilla.org/");
+            mSolo.sleep(3000);
+        }

Comment 1

[Geoff Brown [:gbrown]]

I tried disabling the screenshot (via sDisableScreenshot), and survived about 360 page loads, but then hit the exception, again on createBitmap (but for a much smaller bitmap/alloc now):

I/dalvikvm-heap( 1095): Clamp target GC heap from 65.595MB to 64.000MB
D/dalvikvm( 1095): GC_FOR_ALLOC freed 281K, 1% free 65031K/65543K, paused 422ms
I/dalvikvm-heap( 1095): Clamp target GC heap from 65.592MB to 64.000MB
D/dalvikvm( 1095): GC_FOR_ALLOC freed 26K, 1% free 65028K/65543K, paused 368ms
I/dalvikvm-heap( 1095): Forcing collection of SoftReferences for 21232-byte allocation
D/HierarchicalStateMachine(29662): handleMessage: E msg.what=83
D/HierarchicalStateMachine(29662): processMsg: ConnectedState
D/WifiStateMachine(29662): ConnectedState{ what=83 when=-3ms arg1=2 }
D/HierarchicalStateMachine(29662): handleMessage: X
I/dalvikvm-heap( 1095): Clamp target GC heap from 65.590MB to 64.000MB
D/dalvikvm( 1095): GC_BEFORE_OOM freed 1K, 1% free 65026K/65543K, paused 391ms
E/dalvikvm-heap( 1095): Out of memory on a 21232-byte allocation.
I/dalvikvm( 1095): "GeckoBackgroundThread" prio=5 tid=10 RUNNABLE
I/dalvikvm( 1095):   | group="main" sCount=0 dsCount=0 obj=0x4083b3d8 self=0x19fed0
I/dalvikvm( 1095):   | sysTid=1104 nice=0 sched=0/0 cgrp=default handle=1708640
I/dalvikvm( 1095):   | schedstat=( 8867444000 3715126000 16228 ) utm=675 stm=211 core=0
I/dalvikvm( 1095):   at android.graphics.Bitmap.nativeCreate(Native Method)
I/dalvikvm( 1095):   at android.graphics.Bitmap.createBitmap(Bitmap.java:604)
I/dalvikvm( 1095):   at android.graphics.Bitmap.createBitmap(Bitmap.java:584)
I/dalvikvm( 1095):   at org.mozilla.gecko.GeckoAppShell$3.run(GeckoAppShell.java:543)
I/dalvikvm( 1095):   at android.os.Handler.handleCallback(Handler.java:587)
I/dalvikvm( 1095):   at android.os.Handler.dispatchMessage(Handler.java:92)
I/dalvikvm( 1095):   at android.os.Looper.loop(Looper.java:132)
I/dalvikvm( 1095):   at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
I/dalvikvm( 1095): 
W/dalvikvm( 1095): threadid=10: thread exiting with uncaught exception (group=0x401d6760)
D/GeckoFavicons( 1095): LoadFaviconTask finished for URL = file:///mnt/sdcard/50K.txt (357)
E/GeckoAppShell( 1095): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 11 ("GeckoBackgroundThread")
E/GeckoAppShell( 1095): java.lang.OutOfMemoryError

Comment 2

[Geoff Brown [:gbrown]]

There are numerous postings about out of memory problems using createBitmap. For example, http://stackoverflow.com/questions/477572/android-strange-out-of-memory-issue-while-loading-an-image-to-a-bitmap-object/823966#823966

Comment 3

[Geoff Brown [:gbrown]]

We are now noticing a lot of out of memory errors in mochitest runs, often encountered during screenshots.

Comment 4

[Geoff Brown [:gbrown]]

http://code.google.com/p/android/issues/detail?id=8488#c80 argues that there may be a significant delay before a finalizer is called, allowing the bulk of a bitmap's memory to remain allocated longer than expected. That might fit with the cases reported in this bug, where tests are running in quick succession...delays in finalization might accumulate until we run out of memory.

The suggested solution is to call recycle() as soon as a bitmap is no longer needed. Have we tried that?

Comment 5

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

Do you know which bitmap creation is causing the problem? I don't see the code in the stack trace in comment #1. (It has probably moved since then).

Comment 6

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

I talked to Geoff about this yesterday. All of the bitmap creating code involved with screenshots is now in fallback code paths and can probably just be dropped (if we hit a fall back path, just show the background color and/or stale screenshot). So, it would be surprising to me if this is still occurring and it still related to screenshots.

Geoff said he'd retest and get a new stack if it is still occurring.

Comment 7

[Geoff Brown [:gbrown]]

I re-tested and found we still get OOM after about 300 page loads:

I/ActivityManager( 3098): Starting activity: Intent { flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has
 extras) }
D/GeckoAwesomeBar( 1433): creating awesomebar
I/GeckoViewsFactory( 1433): Creating custom Gecko view: CustomEditText
I/GeckoViewsFactory( 1433): Creating custom Gecko view: AwesomeBarTabs
D/GeckoAwesomeBarTabs( 1433): Creating AwesomeBarTabs
I/ActivityManager( 3098): Displayed activity org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar: 249 ms (total 249 ms)
E/AxT9IME ( 3243): WordSymbInit: 1
E/dalvikvm-heap( 1433): 4096-byte external allocation too large for this process.
E/GraphicsJNI( 1433): VM won't let us allocate 4096 bytes
D/skia    ( 1433): --- decoder->decode returned false
D/AndroidRuntime( 1433): Shutting down VM
W/dalvikvm( 1433): threadid=1: thread exiting with uncaught exception (group=0x4001d7d0)
E/GeckoAppShell( 1433): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 1 ("main")
E/GeckoAppShell( 1433): java.lang.OutOfMemoryError: bitmap size exceeds VM budget
E/GeckoAppShell( 1433): 	at android.graphics.BitmapFactory.nativeDecodeStream(Native Method)
E/GeckoAppShell( 1433): 	at android.graphics.BitmapFactory.decodeStream(BitmapFactory.java:562)
E/GeckoAppShell( 1433): 	at android.graphics.BitmapFactory.decodeResourceStream(BitmapFactory.java:426)
E/GeckoAppShell( 1433): 	at android.graphics.drawable.Drawable.createFromResourceStream(Drawable.java:697)
E/GeckoAppShell( 1433): 	at android.graphics.drawable.Drawable.createFromStream(Drawable.java:657)
E/GeckoAppShell( 1433): 	at org.mozilla.gecko.AllPagesTab.getDrawableFromDataURI(AllPagesTab.java:486)
E/GeckoAppShell( 1433): 	at org.mozilla.gecko.AllPagesTab.setSearchEngines(AllPagesTab.java:464)
E/GeckoAppShell( 1433): 	at org.mozilla.gecko.AllPagesTab$4.run(AllPagesTab.java:498)
E/GeckoAppShell( 1433): 	at android.os.Handler.handleCallback(Handler.java:587)
E/GeckoAppShell( 1433): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/GeckoAppShell( 1433): 	at android.os.Looper.loop(Looper.java:123)
E/GeckoAppShell( 1433): 	at android.app.ActivityThread.main(ActivityThread.java:4627)
E/GeckoAppShell( 1433): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/GeckoAppShell( 1433): 	at java.lang.reflect.Method.invoke(Method.java:521)
E/GeckoAppShell( 1433): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
E/GeckoAppShell( 1433): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
E/GeckoAppShell( 1433): 	at dalvik.system.NativeStart.main(Native Method)
I/ALL_PAGES( 1433): Got cursor in 163ms

Comment 8

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

That's interesting, its failing in the Awesomebar now (obviously the memory could be eaten up elsewhere). Could you try a script that just opens and closes the awesomebar repeatedly? Probably give it a second or two open so it can crate all its drawables before closing it.

Comment 9

[Geoff Brown [:gbrown]]

Simply clicking on the awesome bar repeatedly, with pauses, causes OOM after 359 clicks:

I/ActivityManager( 3098): Starting activity: Intent { flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has extras) }
D/PhoneWindow( 8941): couldn't save which view has focus because the focused view android.widget.TextView@4ac8a228 has no id.
I/GeckoApp( 8941): application paused
D/GeckoAwesomeBar( 8941): creating awesomebar
I/GeckoViewsFactory( 8941): Creating custom Gecko view: CustomEditText
I/GeckoViewsFactory( 8941): Creating custom Gecko view: AwesomeBarTabs
D/GeckoAwesomeBarTabs( 8941): Creating AwesomeBarTabs
I/ActivityManager( 3098): Displayed activity org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar: 210 ms (total 210 ms)
E/AxT9IME ( 3243): WordSymbInit: 1
I/ALL_PAGES( 8941): Got cursor in 254ms
E/dalvikvm-heap( 8941): 1024-byte external allocation too large for this process.
E/GraphicsJNI( 8941): VM won't let us allocate 1024 bytes
D/skia    ( 8941): --- decoder->decode returned false
D/AndroidRuntime( 8941): Shutting down VM
W/dalvikvm( 8941): threadid=1: thread exiting with uncaught exception (group=0x4001d7d0)
E/GeckoAppShell( 8941): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 1 ("main")
E/GeckoAppShell( 8941): java.lang.OutOfMemoryError: bitmap size exceeds VM budget
E/GeckoAppShell( 8941): 	at android.graphics.BitmapFactory.nativeDecodeByteArray(Native Method)
E/GeckoAppShell( 8941): 	at android.graphics.BitmapFactory.decodeByteArray(BitmapFactory.java:495)
E/GeckoAppShell( 8941): 	at android.graphics.BitmapFactory.decodeByteArray(BitmapFactory.java:508)
E/GeckoAppShell( 8941): 	at org.mozilla.gecko.AwesomeBarTab.updateFavicon(AwesomeBarTab.java:102)
E/GeckoAppShell( 8941): 	at org.mozilla.gecko.AllPagesTab$AwesomeBarCursorAdapter.getView(AllPagesTab.java:353)
E/GeckoAppShell( 8941): 	at android.widget.AbsListView.obtainView(AbsListView.java:1431)
E/GeckoAppShell( 8941): 	at android.widget.ListView.makeAndAddView(ListView.java:1802)
E/GeckoAppShell( 8941): 	at android.widget.ListView.fillDown(ListView.java:727)
E/GeckoAppShell( 8941): 	at android.widget.ListView.fillFromTop(ListView.java:784)
E/GeckoAppShell( 8941): 	at android.widget.ListView.layoutChildren(ListView.java:1655)
E/GeckoAppShell( 8941): 	at android.widget.AbsListView.onLayout(AbsListView.java:1263)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.widget.FrameLayout.onLayout(FrameLayout.java:334)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.widget.LinearLayout.setChildFrame(LinearLayout.java:1249)
E/GeckoAppShell( 8941): 	at android.widget.LinearLayout.layoutVertical(LinearLayout.java:1125)
E/GeckoAppShell( 8941): 	at android.widget.LinearLayout.onLayout(LinearLayout.java:1042)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.widget.FrameLayout.onLayout(FrameLayout.java:334)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.widget.LinearLayout.setChildFrame(LinearLayout.java:1249)
E/GeckoAppShell( 8941): 	at android.widget.LinearLayout.layoutVertical(LinearLayout.java:1125)
E/GeckoAppShell( 8941): 	at android.widget.LinearLayout.onLayout(LinearLayout.java:1042)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.widget.FrameLayout.onLayout(FrameLayout.java:334)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.widget.FrameLayout.onLayout(FrameLayout.java:334)
E/GeckoAppShell( 8941): 	at android.view.View.layout(View.java:7088)
E/GeckoAppShell( 8941): 	at android.view.ViewRoot.performTraversals(ViewRoot.java:1056)
E/GeckoAppShell( 8941): 	at android.view.ViewRoot.handleMessage(ViewRoot.java:1752)
E/GeckoAppShell( 8941): 	at android.os.Handler.dispatchMessage(Handler.java:99)
E/GeckoAppShell( 8941): 	at android.os.Looper.loop(Looper.java:123)
E/GeckoAppShell( 8941): 	at android.app.ActivityThread.main(ActivityThread.java:4627)
E/GeckoAppShell( 8941): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/GeckoAppShell( 8941): 	at java.lang.reflect.Method.invoke(Method.java:521)
E/GeckoAppShell( 8941): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
E/GeckoAppShell( 8941): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
E/GeckoAppShell( 8941): 	at dalvik.system.NativeStart.main(Native Method)

Comment 10

[Geoff Brown [:gbrown]]

I tried removing the bitmap code in updateFavicon()...that only delayed the OOM to 390+ clicks on the awesome bar:

I/ActivityManager( 3098): Starting activity: Intent { flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has extras) }
D/PhoneWindow(10041): couldn't save which view has focus because the focused view android.widget.TextView@4ad982c0 has no id.
I/GeckoApp(10041): application paused
D/GeckoAwesomeBar(10041): creating awesomebar
I/GeckoViewsFactory(10041): Creating custom Gecko view: CustomEditText
I/GeckoViewsFactory(10041): Creating custom Gecko view: AwesomeBarTabs
D/GeckoAwesomeBarTabs(10041): Creating AwesomeBarTabs
I/ActivityManager( 3098): Displayed activity org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar: 158 ms (total 158 ms)
E/AxT9IME ( 3243): WordSymbInit: 1
D/dalvikvm( 3243): GC_EXTERNAL_ALLOC freed 1648 objects / 145200 bytes in 38ms
I/ALL_PAGES(10041): Got cursor in 281ms
W/PowerManagerService( 3098): Timer 0x7->0x3|0x0
I/PowerManagerService( 3098): Ulight 7->3|0
I/PowerManagerService( 3098): Ulight 3->7|0
V/WindowManager( 3098): Dsptch to Window{484490d8 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
V/WindowManager( 3098): Dsptch to Window{484490d8 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
I/dalvikvm-heap(10041): Clamp target GC heap from 49.720MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 4473 objects / 292048 bytes in 403ms
I/Robocop (10041): 394 INFO TEST-INFO | testLoader | GYB - i=392
I/ActivityManager( 3098): Starting activity: Intent { flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has extras) }
D/PhoneWindow(10041): couldn't save which view has focus because the focused view android.widget.TextView@4ad60b50 has no id.
I/GeckoApp(10041): application paused
D/GeckoAwesomeBar(10041): creating awesomebar
I/GeckoViewsFactory(10041): Creating custom Gecko view: CustomEditText
I/GeckoViewsFactory(10041): Creating custom Gecko view: AwesomeBarTabs
D/GeckoAwesomeBarTabs(10041): Creating AwesomeBarTabs
I/ActivityManager( 3098): Displayed activity org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar: 77 ms (total 77 ms)
E/AxT9IME ( 3243): WordSymbInit: 1
I/ALL_PAGES(10041): Got cursor in 232ms
W/PowerManagerService( 3098): Timer 0x7->0x3|0x0
I/PowerManagerService( 3098): Ulight 7->3|0
I/PowerManagerService( 3098): Ulight 3->7|0
V/WindowManager( 3098): Dsptch to Window{483099c0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
V/WindowManager( 3098): Dsptch to Window{483099c0 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
I/Robocop (10041): 395 INFO TEST-INFO | testLoader | GYB - i=393
I/ActivityManager( 3098): Starting activity: Intent { flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has extras) }
D/PhoneWindow(10041): couldn't save which view has focus because the focused view android.widget.TextView@4ad661c0 has no id.
I/GeckoApp(10041): application paused
D/GeckoAwesomeBar(10041): creating awesomebar
I/GeckoViewsFactory(10041): Creating custom Gecko view: CustomEditText
I/dalvikvm-heap(10041): Clamp target GC heap from 49.861MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 2157 objects / 144640 bytes in 379ms
I/GeckoViewsFactory(10041): Creating custom Gecko view: AwesomeBarTabs
D/GeckoAwesomeBarTabs(10041): Creating AwesomeBarTabs
I/ActivityManager( 3098): Displayed activity org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar: 486 ms (total 486 ms)
E/AxT9IME ( 3243): WordSymbInit: 1
D/dalvikvm( 3243): GC_EXTERNAL_ALLOC freed 1648 objects / 145120 bytes in 29ms
I/ALL_PAGES(10041): Got cursor in 257ms
W/PowerManagerService( 3098): Timer 0x7->0x3|0x0
I/PowerManagerService( 3098): Ulight 7->3|0
I/PowerManagerService( 3098): Ulight 3->7|0
V/WindowManager( 3098): Dsptch to Window{4832a108 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
V/WindowManager( 3098): Dsptch to Window{4832a108 org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar paused=false}
I/dalvikvm-heap(10041): Clamp target GC heap from 49.941MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 968 objects / 61304 bytes in 412ms
I/Robocop (10041): 396 INFO TEST-INFO | testLoader | GYB - i=394
I/ActivityManager( 3098): Starting activity: Intent { flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has extras) }
D/PhoneWindow(10041): couldn't save which view has focus because the focused view android.widget.TextView@481a5be0 has no id.
I/GeckoApp(10041): application paused
D/GeckoAwesomeBar(10041): creating awesomebar
I/GeckoViewsFactory(10041): Creating custom Gecko view: CustomEditText
I/dalvikvm-heap(10041): Clamp target GC heap from 49.964MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 496 objects / 36216 bytes in 350ms
I/GeckoViewsFactory(10041): Creating custom Gecko view: AwesomeBarTabs
D/GeckoAwesomeBarTabs(10041): Creating AwesomeBarTabs
I/dalvikvm-heap(10041): Clamp target GC heap from 49.992MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 76 objects / 7304 bytes in 349ms
I/dalvikvm-heap(10041): Clamp target GC heap from 49.998MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 43 objects / 1912 bytes in 351ms
I/dalvikvm-heap(10041): Clamp target GC heap from 49.999MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 7 objects / 424 bytes in 349ms
I/dalvikvm-heap(10041): Clamp target GC heap from 49.999MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 4 objects / 128 bytes in 348ms
I/dalvikvm-heap(10041): Clamp target GC heap from 49.999MB to 48.000MB
D/dalvikvm(10041): GC_FOR_MALLOC freed 2 objects / 48 bytes in 350ms
I/dalvikvm-heap(10041): Clamp target GC heap from 48.000MB to 48.000MB
I/dalvikvm-heap(10041): Grow heap (frag case) to 48.000MB for 56-byte allocation
...

Comment 11

[Geoff Brown [:gbrown]]

Same failure after approx. same number of iterations on Galaxy Nexus. Note this Strict Mode error on each iteration:

07-15 20:57:43.494 I/ActivityManager(  182): START {flg=0x40010000 cmp=org.mozilla.fennec_mozdev/org.mozilla.gecko.AwesomeBar (has e
xtras)} from pid 8038
07-15 20:57:43.588 I/GeckoApp( 8038): application paused
07-15 20:57:43.596 D/GeckoAwesomeBar( 8038): creating awesomebar
07-15 20:57:43.612 I/GeckoViewsFactory( 8038): Creating custom Gecko view: CustomEditText
07-15 20:57:43.612 I/GeckoViewsFactory( 8038): Creating custom Gecko view: AwesomeBarTabs
07-15 20:57:43.612 D/GeckoAwesomeBarTabs( 8038): Creating AwesomeBarTabs
07-15 20:57:43.643 I/ALL_PAGES( 8038): Got cursor in 7ms
07-15 20:57:43.659 I/ALL_PAGES( 8038): Got cursor in 7ms
07-15 20:57:43.659 I/ALL_PAGES( 8038): Got cursor in 7ms
07-15 20:57:43.666 I/ALL_PAGES( 8038): Got cursor in 6ms
07-15 20:57:43.846 D/OpenGLRenderer( 8038): Flushing caches (mode 0)
07-15 20:57:44.940 D/dalvikvm( 8038): GC_EXPLICIT freed 606K, 2% free 56532K/57223K, paused 7ms+97ms
07-15 20:57:44.987 E/StrictMode( 8038): class org.mozilla.gecko.AwesomeBar; instances=268; limit=3
07-15 20:57:44.987 E/StrictMode( 8038): android.os.StrictMode$InstanceCountViolation: class org.mozilla.gecko.AwesomeBar; instances=
268; limit=3
07-15 20:57:44.987 E/StrictMode( 8038): 	at android.os.StrictMode.setClassInstanceLimit(StrictMode.java:1)

(the number of reported instances increments with each click on the awesome bar).

Comment 12

[Lucas Rocha (:lucasr)]

I wonder if it would make sense to turn the Awesomebar into a singleTop activity? This means we would reuse an existing instance if it's on already top of the task stack.

Comment 13

[Geoff Brown [:gbrown]]

(In reply to Lucas Rocha (:lucasr) from comment #12)

I tried making the AwesomeBar activity singleTop, but it seems to make no difference: instances continue to increment with each click on the awesome bar. This seems odd...

Meanwhile, I noticed that the StrictMode instances error only occurs in the robocop test; if I try to re-create the test manually (manually click, press Back, click, press Back, etc.), there are no StrictMode messages.

In both cases - robocop and manual - I have verified that cancelAndFinish is called once per cycle, and also that AwesomeBar::onDestroy is called once per cycle.

Comment 14

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

This seems to imply a leak in the robocop harness.

Comment 15

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

It would be interesting to put in a finalize() method into the AwesomeBar activity class and see if that gets run when running the robocop test vs running it manually. If the finalizer runs when running the test manually but not in robocop then that would confirm the leak. (You might need to add some code that calls java.lang.System.gc() to force a garbage collection reliably).

Also could you post the test code you're using to open/close the awesomebar?

Comment 16

[Geoff Brown [:gbrown]]

Attachment: test code to demonstrate OOM

Comment 17

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

The most likely suspect for the leak is the call to inst.addMonitor in BaseTest.getActivityFromClick. The monitor is held on to in the instrumentation class and the monitor holds on to the activity. We should try calling inst.removeMonitor once we have the activity we were waiting for.

Comment 18

[Geoff Brown [:gbrown]]

(In reply to Kartikaya Gupta (:kats) from comment #17)

Great idea (removeMonitor) and likely something we should do anyway, but that doesn't fix this problem: I still see StrictMode$InstanceCountViolation with increasing AwesomeBar instances on each click.

Comment 19

[Geoff Brown [:gbrown]]

(In reply to Kartikaya Gupta (:kats) from comment #15)

Verified: AwesomeBar.finalize is called during manual test; it is *not* called during the robocop test.

Comment 20

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

Looking at the code for Instrumentation.java, it already does remove the monitor before returning from waitForMonitor. To track down the leak you can probably run the harness a few times and then grab a hprof heap dump file using ddms. Some info is at http://www.milk.com/kodebase/dalvik-docs-mirror/docs/heap-profiling.html

Comment 21

[Geoff Brown [:gbrown]]

I obtained a hprof heap dump; it shows that the AwesomeBar instances are held by Robotium. It turns out that Robotium likes to hold on to a reference of every activity it ever uses. Various Robotium classes use "waiter" objects, which use ActivityUtils, which has an ArrayList<Activity> that keeps growing as new activities are used -- and that's why every AwesomeBar activity we ever click on is never finalized.

There are various posts about Robotium holding on to activities like this and causing OOM for other applications. One suggested recourse is to call Solo.finishOpenedActivities, but there are other posts complaining that it doesn't work -- I will check into that.

The heap dump also showed that about 50% of this heap - about 20 MB - was byte[] data, of various sizes: just 4 instances around 1M, hundreds of instances between 10K and 20K. Are most of these bitmaps associated with the AwesomeBar instances?

Comment 22

[Joel Maher ( :jmaher ) (UTC -8)]

any chance they could be the bitmap byte[] from the getpaintedsurface calls?

Comment 23

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

(In reply to Geoff Brown [:gbrown] from comment #21)
> The heap dump also showed that about 50% of this heap - about 20 MB - was
> byte[] data, of various sizes: just 4 instances around 1M, hundreds of
> instances between 10K and 20K. Are most of these bitmaps associated with the
> AwesomeBar instances?

I would guess yes. It's probably not worth worrying about it until we can figure out how to free the Activity objects.

Looking at the robotium codebase it looks like this bug is fixed in the latest release (3.3). ActivityUtils now wraps its Activity objects in WeakReferences so they should be free-able. The simplest fix might just be to upgrade our robotium version.

Comment 24

[Geoff Brown [:gbrown]]

(In reply to Joel Maher (:jmaher) from comment #22)
> any chance they could be the bitmap byte[] from the getpaintedsurface calls?

Good idea, but no -- getPaintedSurface was not called in this test.

Comment 25

[Geoff Brown [:gbrown]]

I tried calling Solo.finishInactiveActivities after each click; the StrictMode warnings went away, the AwesomeBar finalizer was called, and the test was able to survive 1000 clicks without OOM or any other error.

I then removed the call to Solo.finishInactiveActivities and updated the robotium jar to version 3.3; again, the warnings went away, the AwesomeBar finalizer was called, and the test was able to survive 1000 clicks without error.

Comment 26

[Geoff Brown [:gbrown]]

There may be other memory leaks, but I am convinced that the memory leak that I reported here was caused by Robotium and is fixed by upgrading to the 3.3 Robotium jar.

Comment 27

[Ed Morley [:emorley]]

Nice work, the sheriffs thank you! :-D