726379 - crash java.util.concurrent.RejectedExecutionException at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1876) when migrating from XUL to Native build

Status: RESOLVED FIXED

(Firefox for Android :: General, defect, P1, critical)

Description

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

This bug was filed from the Socorro interface and is 
report bp-fb0dff99-c643-48d9-b184-dbe952120210 .
============================================================= 
java.util.concurrent.RejectedExecutionException
	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1876)
	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:774)
	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1295)
	at android.os.AsyncTask.execute(AsyncTask.java:394)
	at org.mozilla.gecko.Tab$3.run(Tab.java:363)
	at android.os.Handler.handleCallback(Handler.java:587)
	at android.os.Handler.dispatchMessage(Handler.java:92)
	at android.os.Looper.loop(Looper.java:123)
	at org.mozilla.gecko.GeckoApp$32.run(GeckoApp.java:1777)
	at android.os.Handler.handleCallback(Handler.java:587)
	at android.os.Handler.dispatchMessage(Handler.java:92)
	at android.os.Looper.loop(Looper.java:123)
	at android.app.ActivityThread.main(ActivityThread.java:4627)
	at java.lang.reflect.Method.invokeNative(Native Method)
	at java.lang.reflect.Method.invoke(Method.java:521)
	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:876)
	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:634)
	at dalvik.system.NativeStart.main(Native Method)

First appearance in build : 	20120210031150

Comment 1

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

bp-2dda163e-e0c6-4a8e-9d00-a611a2120216

Received crash when trying to migrate from XUL build 2/16/2012 to Native build 02/16/2012.  My guess is that Sync was trying to sync at the same time the migration kicked in?

Comment 2

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

Attachment: full logcat

Comment 3

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

Part of logcat:

02-16 10:53:58.960 I/GeckoApp( 3865): Startup mode: NEW_PROFILE
02-16 10:53:58.992 I/Addons  ( 3865): filestream is null
02-16 10:53:59.007 I/dalvikvm( 3865): Total arena pages for JIT: 11
02-16 10:53:59.113 D/GeckoFavicons( 3865): Creating LoadFaviconTask with URL = http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png and favicon URL = http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png?modified=1310547725
02-16 10:53:59.113 D/GeckoFavicons( 3865): Favicon URL is now: http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png?modified=1310547725
02-16 10:53:59.113 D/GeckoFavicons( 3865): Calling getFaviconUrlForPageUrl() for http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png
02-16 10:53:59.113 D/GeckoFavicons( 3865): Calling loadFavicon() with URL = http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png and favicon URL = http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png?modified=1310547725 (2)
02-16 10:53:59.117 D/GeckoFavicons( 3865): Creating LoadFaviconTask with URL = http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png and favicon URL = http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png
02-16 10:53:59.117 D/GeckoFavicons( 3865): Calling loadFavicon() with URL = http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png and favicon URL = http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png (3)
02-16 10:53:59.125 D/GeckoFavicons( 3865): Favicon URL is now: http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png
02-16 10:53:59.125 D/GeckoFavicons( 3865): Downloading favicon for URL = http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png with favicon URL = http://static-cdn.addons.mozilla.net/en-US/firefox/images/addon_icon/292493-32.png?modified=1310547725
02-16 10:53:59.125 D/GeckoFavicons( 3865): Calling getFaviconUrlForPageUrl() for http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png
02-16 10:53:59.125 D/GeckoFavicons( 3865): Downloading favicon for URL = http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png with favicon URL = http://static-cdn.addons.mozilla.net/media//img/addon-icons/security-32.png
02-16 10:53:59.511 W/GeckoGlobalHistory( 3865): Rebuilding visited link set...
02-16 10:53:59.593 D/dalvikvm( 3865): GC_CONCURRENT freed 1395K, 54% free 3472K/7495K, external 3698K/4181K, paused 4ms+6ms
02-16 10:53:59.796 D/dalvikvm( 3135): GC_EXPLICIT freed 139K, 49% free 5491K/10567K, external 5292K/8292K, paused 105ms
02-16 10:53:59.945 E/GeckoAppShell( 3865): top level exception
02-16 10:53:59.945 E/GeckoAppShell( 3865): java.util.concurrent.RejectedExecutionException: pool=128/128, queue=10/10
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1961)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:794)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1315)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.AsyncTask.execute(AsyncTask.java:394)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at org.mozilla.gecko.Tab$4.run(Tab.java:374)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.Handler.handleCallback(Handler.java:587)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.Handler.dispatchMessage(Handler.java:92)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.Looper.loop(Looper.java:123)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at org.mozilla.gecko.GeckoApp$34.run(GeckoApp.java:1820)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.Handler.handleCallback(Handler.java:587)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.Handler.dispatchMessage(Handler.java:92)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.os.Looper.loop(Looper.java:123)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at android.app.ActivityThread.main(ActivityThread.java:3647)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at java.lang.reflect.Method.invokeNative(Native Method)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at java.lang.reflect.Method.invoke(Method.java:507)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:839)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:597)
02-16 10:53:59.945 E/GeckoAppShell( 3865): 	at dalvik.system.NativeStart.main(Native Method)
02-16 10:54:01.410 D/skia    ( 3865): --- SkImageDecoder::Factory returned null
02-16 10:54:01.531 D/AndroidRuntime( 4025): 
02-16 10:54:01.531 D/AndroidRuntime( 4025): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<<
02-16 10:54:01.531 D/AndroidRuntime( 4025): CheckJNI is OFF
02-16 10:54:01.531 D/dalvikvm( 4025): creating instr width table
02-16 10:54:01.675 D/AndroidRuntime( 4025): Calling main entry com.android.commands.am.Am
02-16 10:54:01.683 E/JavaBinder( 3135): !!! FAILED BINDER TRANSACTION !!!
02-16 10:54:01.683 I/ActivityManager( 3135): Starting: Intent { act=org.mozilla.gecko.reportCrash flg=0x10000000 cmp=org.mozilla.fennec/.CrashReporter (has extras) } from pid 4025
02-16 10:54:01.687 D/AndroidRuntime( 4025): Shutting down VM

Comment 4

[Richard Newman [:rnewman]]

Nothing to do with Sync as far as I can see…

Comment 5

[Gian-Carlo Pascutto [:gcp]]

It's not in Profile Migration either (it finishes and exists before the crash).

Comment 6

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

Java crash; nom-ing for blocking fennec

Comment 7

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

Crashed on both Galaxy Nexus and Galaxy S II while doing profile migration perf testing.

Comment 8

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

Attachment: droid 2 logcat w/ timestamp

https://crash-stats.mozilla.com/report/index/bp-31003f7a-c5d2-4a50-b63a-c24052120303
Time of crash coincides with the finishing of the migration: 03-02 16:12:16.638 I/ProfMigr( 2502): Profile migration finished; odd thing is that it tried to open up the profile again : 03-02 16:13:44.615 I/ProfMigr( 2664): Opening path: /data/data/org.mozilla.fennec/files/mozilla/wpx6fbo8.default/places.sqlite

Comment 9

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

I was mistaken.  Looking closer at the log, it exists the migration, 03-02 16:12:16.638 I/ProfMigr( 2502): Profile migration finished
03-02 16:12:16.646 I/GeckoApp( 2502): Profile migration took 285790 ms
03-02 16:12:16.904 D/dalvikvm( 1235): GC_EXPLICIT freed 5745 objects / 221160 bytes in 136ms
03-02 16:12:18.169 I/GeckoApp( 2502): Startup mode: NEW_PROFILE
03-02 16:12:18.287 I/GeckoAboutHome( 2502): filestream is null
03-02 16:12:18.365 I/dalvikvm( 2502): Total arena pages for JIT: 11

and then crashes at 16:12:20.388, then relaunches the app afterwards.  Is it trying to create a new profile after migrating?

Comment 10

[Kevin Brosnan [:kbrosnan]]

Not a top crash, not blocking. Still good to fix though.

Comment 11

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

Attachment: logcat for captivate

Comment 12

[Ioana Chiorean]

Attachment: Log crash while setting profile - htc desire z

Stil reproducing at a migration from XUL build (Nightly 14.0a1 - 4/15) to Native UI build (Nightly 14.0a1 - 4/16). After approx 1m and half in the "Setting up Nightly..." the build crashes. 
Reproducible on both class 4 and class 2 SD card. 
Device: HTC Desire Z
Profile used for sync: 8.6 MB

Comment 13

[Gian-Carlo Pascutto [:gcp]]

Browsing the code a bit, we seem to create an AsyncTask for each tab times each bookmark that gets added/deleted.

This...backfires...right after bookmarks get migrated. I'm guessing Sync will trigger it too if it starts batching.

Comment 14

[Gian-Carlo Pascutto [:gcp]]

Fix accidental flags edit.

Comment 15

[Gian-Carlo Pascutto [:gcp]]

>we seem to create an AsyncTask for each tab times each bookmark that gets 
>added/deleted

Hmm, that's not entirely correct as the task is cancelled (though that might leave some internal stuff alive until GC runs). 

Do we know exact STR here? (I've never seen this)

Comment 16

[Gian-Carlo Pascutto [:gcp]]

I got a profile from kbrosnan that can reproduce this. Probably related to amount of bookmarks you have. Luckily it triggers after Profile Migration sets its finished flags, so it won't crash at the next start.

Comment 17

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

Yes, we do.  The profile I use for large profile testing (which is probably the one that kbrosnan passed to you) exhibits this all the time.

1. install XUL
2. sync with that account
3. migrate to native

Note: this account has been an account that I used Sync/Firefox 4.0 time on up + a merge with Tracy's test sync account.

Comment 18

[Kevin Brosnan [:kbrosnan]]

No, it was a personal profile. I would prefer it to only go to people who need it. Though it is good to know that the QA Sync profile can repo this.

Comment 19

[Gian-Carlo Pascutto [:gcp]]

Attachment: Patch 1. Simplify bookmark check

Adding logging, the problem indeed happens when updateBookmark is spammed rapidly. Because the AsyncTask is cancelled each time before a new one is executed, that shouldn't clog on the AsyncTask thread pool, but it still seems to do. Not sure what the reason for that is. updateBookmark itself being called concurrently so we can race between the execute and cancel?

In any case, the AsyncTask only seems to be used to do something in the background. There is also an runOnUiThread in the onPostExecute, but it's not clear to me why that is needed or what it's trying to accomplish. The only thing it access or updates are class primitives, and the only place isBookmark is queried is in GeckoApp if it pops up the menu.

Based on this, I simplified this to the utter basics: a Runnable on the background thread. Unlike AsyncTask, that has no limit on the amount of queued ops.

Comment 20

[Sriram Ramasubramanian [:sriram]]

Comment on attachment 616123 [details] [diff] [review]
Patch 1. Simplify bookmark check

This looks good to me.

Comment 21

[Gian-Carlo Pascutto [:gcp]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2d335134f808

Comment 22

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 616123 [details] [diff] [review]
Patch 1. Simplify bookmark check

[Triage comment]
Already landed to mozilla-inbound, and it's a Fennec Native bug, so you don't need the approval-mozilla-central flag here.

Comment 23

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/2d335134f808