Closed Bug 764808 Opened 12 years ago Closed 12 years ago

Frequent ANR on Nightly

Categories

(Firefox for Android Graveyard :: General, defect)

Product:
Firefox for Android Graveyard
Component:
General
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED INVALID

People

(Reporter: snorp, Unassigned)

Details

A couple days ago I started getting constant ANRs on Nightly. This is on a Galaxy Nexus, ICS.
Cmd line: org.mozilla.fennec

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x40be4460 self=0x11af830
  | sysTid=29151 nice=0 sched=0/0 cgrp=default handle=1074717892
  | schedstat=( 0 0 0 ) utm=956 stm=296 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x40be4530> (a java.lang.VMThread) held by tid=1 (main)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:813)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:973)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1282)
  at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207)
  at org.mozilla.gecko.GeckoAppShell.geckoEventSync(GeckoAppShell.java:588)
  at org.mozilla.gecko.GeckoAppShell.sendEventToGeckoSync(GeckoAppShell.java:512)
  at org.mozilla.gecko.gfx.GeckoLayerClient.compositionPauseRequested(GeckoLayerClient.java:452)
  at org.mozilla.gecko.gfx.LayerView.surfaceDestroyed(LayerView.java:225)
  at android.view.SurfaceView.updateWindow(SurfaceView.java:517)
  at android.view.SurfaceView.onWindowVisibilityChanged(SurfaceView.java:226)
  at android.view.View.dispatchWindowVisibilityChanged(View.java:5839)
  at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:945)
  at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:945)
  at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:945)
  at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:945)
  at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:945)
  at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:945)
  at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:965)
  at android.view.ViewRootImpl.handleMessage(ViewRootImpl.java:2442)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:137)
  at android.app.ActivityThread.main(ActivityThread.java:4575)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:511)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:789)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:556)
  at dalvik.system.NativeStart.main(Native Method)

"Binder Thread #4" prio=5 tid=21 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x419ec918 self=0x1f8cda8
  | sysTid=357 nice=0 sched=0/0 cgrp=default handle=27991976
  | schedstat=( 0 0 0 ) utm=0 stm=0 core=0
  at dalvik.system.NativeStart.run(Native Method)

"AsyncTask #5" prio=5 tid=24 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x414f9ca8 self=0x1d45b88
  | sysTid=31671 nice=10 sched=0/0 cgrp=bg_non_interactive handle=30655512
  | schedstat=( 0 0 0 ) utm=40 stm=1 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x414f9e00> (a java.lang.VMThread) held by tid=24 (AsyncTask #5)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
  at java.lang.Thread.run(Thread.java:856)

"AsyncTask #4" prio=5 tid=23 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4100b650 self=0x1b13f20
  | sysTid=31668 nice=10 sched=0/0 cgrp=bg_non_interactive handle=26542040
  | schedstat=( 0 0 0 ) utm=36 stm=7 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x414cd048> (a java.lang.VMThread) held by tid=23 (AsyncTask #4)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
  at java.lang.Thread.run(Thread.java:856)

"Binder Thread #3" prio=5 tid=20 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x40ffd790 self=0x1d8f6a8
  | sysTid=31560 nice=0 sched=0/0 cgrp=default handle=27179504
  | schedstat=( 0 0 0 ) utm=0 stm=1 core=0
  at dalvik.system.NativeStart.run(Native Method)

"AsyncTask #3" prio=5 tid=19 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x410a9fb0 self=0x194a748
  | sysTid=31507 nice=10 sched=0/0 cgrp=bg_non_interactive handle=27032944
  | schedstat=( 0 0 0 ) utm=22 stm=3 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4185ba38> (a java.lang.VMThread) held by tid=19 (AsyncTask #3)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
  at java.lang.Thread.run(Thread.java:856)

"RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@410181a8" daemon prio=5 tid=18 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x40ff4ff0 self=0x193b0f0
  | sysTid=29841 nice=0 sched=0/0 cgrp=default handle=23355576
  | schedstat=( 0 0 0 ) utm=0 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x41012588> (a java.lang.ref.ReferenceQueue)
  at java.lang.Object.wait(Object.java:401)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
  at org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:102)
  at java.lang.Thread.run(Thread.java:856)

"AsyncTask #2" prio=5 tid=17 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x41024300 self=0x1923488
  | sysTid=29839 nice=10 sched=0/0 cgrp=bg_non_interactive handle=20380592
  | schedstat=( 0 0 0 ) utm=21 stm=6 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4101bef8> (a java.lang.VMThread) held by tid=17 (AsyncTask #2)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
  at java.lang.Thread.run(Thread.java:856)

"android.hardware.SensorManager$SensorThread" prio=5 tid=16 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41008258 self=0x15507f0
  | sysTid=29834 nice=-8 sched=0/0 cgrp=default handle=20439736
  | schedstat=( 0 0 0 ) utm=120 stm=32 core=1
  at android.hardware.SensorManager.sensors_data_poll(Native Method)
  at android.hardware.SensorManager$SensorThread$SensorThreadRunnable.run(SensorManager.java:498)
  at java.lang.Thread.run(Thread.java:856)

"Thread-465" prio=5 tid=15 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x412dc7d8 self=0x15942f0
  | sysTid=29822 nice=0 sched=0/0 cgrp=default handle=22626864
  | schedstat=( 0 0 0 ) utm=983 stm=324 core=1
  at dalvik.system.NativeStart.run(Native Method)

"AsyncTask #1" prio=5 tid=14 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x412cf970 self=0x1582e70
  | sysTid=29816 nice=10 sched=0/0 cgrp=bg_non_interactive handle=22535472
  | schedstat=( 0 0 0 ) utm=25 stm=2 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x412cfb08> (a java.lang.VMThread) held by tid=14 (AsyncTask #1)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
  at java.lang.Thread.run(Thread.java:856)

"GeckoInputConnection Timer" prio=5 tid=13 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4129f808 self=0x152c960
  | sysTid=29806 nice=0 sched=0/0 cgrp=default handle=20433584
  | schedstat=( 0 0 0 ) utm=0 stm=1 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4129f808> (a java.util.Timer$TimerImpl)
  at java.lang.Object.wait(Object.java:364)
  at java.util.Timer$TimerImpl.run(Timer.java:214)

"Gecko" prio=5 tid=12 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41044108 self=0x12772f0
  | sysTid=29803 nice=0 sched=0/0 cgrp=default handle=20059360
  | schedstat=( 0 0 0 ) utm=28335 stm=356 core=0
  at java.lang.StringToReal.parseDblImpl(Native Method)
  at java.lang.StringToReal.parseDouble(StringToReal.java:267)
  at java.lang.Double.parseDouble(Double.java:295)
  at java.lang.Double.valueOf(Double.java:332)
  at org.json.JSONTokener.readLiteral(JSONTokener.java:323)
  at org.json.JSONTokener.nextValue(JSONTokener.java:111)
  at org.json.JSONTokener.readObject(JSONTokener.java:385)
  at org.json.JSONTokener.nextValue(JSONTokener.java:100)
  at org.json.JSONTokener.readObject(JSONTokener.java:385)
  at org.json.JSONTokener.nextValue(JSONTokener.java:100)
  at org.json.JSONObject.<init>(JSONObject.java:154)
  at org.json.JSONObject.<init>(JSONObject.java:171)
  at org.mozilla.gecko.GeckoAppShell.handleGeckoMessage(GeckoAppShell.java:1832)
  at org.mozilla.gecko.GeckoAppShell.nativeRun(Native Method)
  at org.mozilla.gecko.GeckoAppShell.nativeRun(Native Method)
  at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:481)
  at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:82)

"GeckoBackgroundThread" prio=5 tid=11 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41023a28 self=0x13b6ac8
  | sysTid=29164 nice=0 sched=0/0 cgrp=default handle=20049304
  | schedstat=( 0 0 0 ) utm=168 stm=25 core=0
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:118)
  at android.os.Looper.loop(Looper.java:118)
  at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)

"Binder Thread #2" prio=5 tid=10 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x40fe20f8 self=0x13835f8
  | sysTid=29163 nice=0 sched=0/0 cgrp=default handle=20431488
  | schedstat=( 0 0 0 ) utm=3 stm=3 core=1
  at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #1" prio=5 tid=9 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x40fe1ec8 self=0x137be30
  | sysTid=29162 nice=0 sched=0/0 cgrp=default handle=20157384
  | schedstat=( 0 0 0 ) utm=3 stm=2 core=0
  at dalvik.system.NativeStart.run(Native Method)

"FinalizerWatchdogDaemon" daemon prio=5 tid=8 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x40fde8a8 self=0x139dc50
  | sysTid=29161 nice=0 sched=0/0 cgrp=default handle=20570272
  | schedstat=( 0 0 0 ) utm=0 stm=1 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x40bebbe0> (a java.lang.Daemons$FinalizerWatchdogDaemon)
  at java.lang.Object.wait(Object.java:364)
  at java.lang.Daemons$FinalizerWatchdogDaemon.run(Daemons.java:213)
  at java.lang.Thread.run(Thread.java:856)

"FinalizerDaemon" daemon prio=5 tid=7 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x40fde750 self=0x13a5fd0
  | sysTid=29160 nice=0 sched=0/0 cgrp=default handle=20603936
  | schedstat=( 0 0 0 ) utm=21 stm=4 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x40bda5d0> (a java.lang.ref.ReferenceQueue)
  at java.lang.Object.wait(Object.java:401)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
  at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:168)
  at java.lang.Thread.run(Thread.java:856)

"ReferenceQueueDaemon" daemon prio=5 tid=6 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x40fde5e8 self=0x135e3c8
  | sysTid=29159 nice=0 sched=0/0 cgrp=default handle=20310040
  | schedstat=( 0 0 0 ) utm=2 stm=2 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x40bda4f8> 
  at java.lang.Object.wait(Object.java:364)
  at java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:128)
  at java.lang.Thread.run(Thread.java:856)

"Compiler" daemon prio=5 tid=5 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x40fde4f8 self=0x13ba6d0
  | sysTid=29158 nice=0 sched=0/0 cgrp=default handle=20469024
  | schedstat=( 0 0 0 ) utm=118 stm=71 core=0
  at dalvik.system.NativeStart.run(Native Method)

"JDWP" daemon prio=5 tid=4 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x40fde410 self=0x137aaf8
  | sysTid=29157 nice=0 sched=0/0 cgrp=default handle=20430176
  | schedstat=( 0 0 0 ) utm=0 stm=1 core=1
  at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
  | group="system" sCount=0 dsCount=0 obj=0x40fde318 self=0x13ab8a0
  | sysTid=29156 nice=0 sched=0/0 cgrp=default handle=20709208
  | schedstat=( 0 0 0 ) utm=13 stm=16 core=1
  at dalvik.system.NativeStart.run(Native Method)

"GC" daemon prio=5 tid=2 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x40fde238 self=0x13ae5a8
  | sysTid=29152 nice=0 sched=0/0 cgrp=default handle=20737480
  | schedstat=( 0 0 0 ) utm=208 stm=9 core=1
  at dalvik.system.NativeStart.run(Native Method)

----- end 29151 -----
This one seems fishy. If it's getting into an infinite loop or something trying to parse a double that would explain this behaviour. You'd hope that sort of thing doesn't happen so often, but it has been known to occur. (see http://www.exploringbinary.com/java-hangs-when-converting-2-2250738585072012e-308/). It could also be a loop higher up in the stack, with malformed JSON borking the JSONTokener or something.

The next time it happens you should grab stack logs twice, a few seconds apart to make sure it is getting stuck in this code and not just passing through.

"Gecko" prio=5 tid=12 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41044108 self=0x12772f0
  | sysTid=29803 nice=0 sched=0/0 cgrp=default handle=20059360
  | schedstat=( 0 0 0 ) utm=28335 stm=356 core=0
  at java.lang.StringToReal.parseDblImpl(Native Method)
  at java.lang.StringToReal.parseDouble(StringToReal.java:267)
  at java.lang.Double.parseDouble(Double.java:295)
  at java.lang.Double.valueOf(Double.java:332)
  at org.json.JSONTokener.readLiteral(JSONTokener.java:323)
  at org.json.JSONTokener.nextValue(JSONTokener.java:111)
  at org.json.JSONTokener.readObject(JSONTokener.java:385)
  at org.json.JSONTokener.nextValue(JSONTokener.java:100)
  at org.json.JSONTokener.readObject(JSONTokener.java:385)
  at org.json.JSONTokener.nextValue(JSONTokener.java:100)
  at org.json.JSONObject.<init>(JSONObject.java:154)
  at org.json.JSONObject.<init>(JSONObject.java:171)
  at org.mozilla.gecko.GeckoAppShell.handleGeckoMessage(GeckoAppShell.java:1832)
  at org.mozilla.gecko.GeckoAppShell.nativeRun(Native Method)
  at org.mozilla.gecko.GeckoAppShell.nativeRun(Native Method)
  at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:481)
  at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:82)
I did grab the log several times and it was always the same. I agree that it is very strange. I've nuked my profile now and it seems to have gone away. I really wish Nightly was debuggable...
I lied. It just locked up again, same stack on the Gecko thread.
It's spinning on one CPU core, but according to DDMS method profiler there is basically zero Java activity. I think there is an infinite loop in StringToReal.parseDblImpl? What.
I got ANR after I went to earthcam.com and then to Awesomebar: https://gist.github.com/2931085

--
Firefox 16.0a1 (2012-06-14)
Device: Galaxy Nexus
OS: Android 4.0.2
The ANR :xti got there is not the same as this one (though it is still concerning).
I added some debugging to a Try build and it seems to choke on the following:

First run:

W/GeckoAppShell( 5638): SNORP: gecko message: {"gecko":{"width":720,"height":1038,"cssWidth":1024,"cssHeight":1476.2666666666667,"pageLeft":0,"pageTop":0,"pageRight":720,"pageBottom":5316.211051940918,"cssPageLeft":0,"cssPageTop":0,"cssPageRight":1024,"cssPageBottom":7560.83349609375,"zoom":0.703125,"cssX":0,"cssY":0,"x":0,"y":0,"type":"Viewport:CalculateDisplayPort"}}

Second run:

W/GeckoAppShell( 6234): SNORP: gecko message: {"gecko":{"width":720,"height":1038,"cssWidth":1024,"cssHeight":1476.2666666666667,"pageLeft":0,"pageTop":0,"pageRight":720,"pageBottom":5264.707145690918,"cssPageLeft":0,"cssPageTop":0,"cssPageRight":1024,"cssPageBottom":7487.58349609375,"zoom":0.703125,"cssX":0,"cssY":0,"x":0,"y":0,"type":"Viewport:CalculateDisplayPort"}}

*boggle*
This is reproducible even back to the 5/20 nightly. I was successfully using it back then, so apparently something changed on my phone to cause this. Weirdness.
I restored to the latest stock OTA and the problem seems to be gone. Weirdness.
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → INVALID
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.