Closed Bug 726379 Opened 8 years ago Closed 8 years ago

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

Categories

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

ARM
Android
defect

Tracking

()

RESOLVED FIXED
Firefox 14
Tracking Status
blocking-fennec1.0 --- +

People

(Reporter: nhirata, Assigned: gcp)

References

Details

(Keywords: crash, reproducible, Whiteboard: [native-crash])

Crash Data

Attachments

(5 files)

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
Whiteboard: [native-crash]
tracking-fennec: --- → ?
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?
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
Nothing to do with Sync as far as I can see…
It's not in Profile Migration either (it finishes and exists before the crash).
Priority: -- → P1
tracking-fennec: ? → ---
Java crash; nom-ing for blocking fennec
blocking-fennec1.0: --- → ?
Crash Signature: [@ java.util.concurrent.RejectedExecutionException: at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java)] → [@ java.util.concurrent.RejectedExecutionException: at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java)] [@ java.util.concurrent.RejectedExecutionException: at java.util.concurrent.ThreadPoolExecutor$AbortPol…
Crashed on both Galaxy Nexus and Galaxy S II while doing profile migration perf testing.
Crash Signature: java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] → java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] [@ java.util.concurrent.RejectedExecutionException: pool=128/128 queue=10/10 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadP…
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
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?
Not a top crash, not blocking. Still good to fix though.
blocking-fennec1.0: ? → -
Crash Signature: queue=10/10 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] → queue=10/10 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] [@ java.util.concurrent.RejectedExecutionException: pool=128/128 queue=10/10 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedEx…
Crash Signature: queue=10/10 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] → queue=10/10 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] [@ java.util.concurrent.RejectedExecutionException: pool=0/1 queue=0 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(…
Crash Signature: queue=0 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] → queue=0 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java) ] [@ java.util.concurrent.RejectedExecutionException: pool=1/1 queue=0 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Thre…
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
Blocks: 713283
blocking-fennec1.0: - → ?
Keywords: reproducible
Summary: crash java.util.concurrent.RejectedExecutionException
 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1876) → crash java.util.concurrent.RejectedExecutionException
 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1876) when migrating from XUL to Native build
Version: Firefox 13 → Trunk
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.
blocking-fennec1.0: ? → ---
Version: Trunk → Firefox 13
Fix accidental flags edit.
blocking-fennec1.0: --- → ?
Version: Firefox 13 → Trunk
>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)
blocking-fennec1.0: ? → +
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.
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.
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.
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.
Attachment #616123 - Flags: review?(sriram)
Comment on attachment 616123 [details] [diff] [review]
Patch 1. Simplify bookmark check

This looks good to me.
Attachment #616123 - Flags: review?(sriram) → review+
Attachment #616123 - Flags: approval-mozilla-central?
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.
Attachment #616123 - Flags: approval-mozilla-central?
Assignee: nobody → gpascutto
https://hg.mozilla.org/mozilla-central/rev/2d335134f808
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 14
You need to log in before you can comment on or make changes to this bug.