Need some insight on this recurring issue, ANR keyDispatchingTimedOut
I have an app that keeps getting ANR in one specific component, and I cannot figure out what is hogging the cpu time. Lately I've been getting two kinds of ANR, a native and a wait.
DALVIK THREADS:
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4001d8c0 self=0xccc8
| sysTid=10569 nice=0 sched=0/0 cgrp=default handle=-1345017816
| schedstat=( 9041503981 6690216078 17225 )
at android.view.Surface.lockCanvasNative(Native Method)
at android.view.Surface.lockCanvas(Surface.java:314)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:773)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.Surfaceview.onTouchEvent(Surfaceview.java:322)
at android.view.View.dispatchTouchEvent(View.java:3766)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at com.android.internal.policy.impl.PhoneWindow$DecorView.superDispatchTouchEvent(PhoneWindow.java:1671)
at com.android.internal.policy.impl.PhoneWindow.superDispatchTouchEvent(PhoneWindow.java:1107)
at android.app.Activity.dispatchTouchEvent(Activity.java:2086)
at com.android.internal.policy.impl.PhoneWindow$DecorView.dispatchTouchEvent(PhoneWindow.java:1655)
at android.view.ViewRoot.handleMessage(ViewRoot.java:1785)
at android.os.Handler.dispatchMessage(Handler.java:99)
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:858)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
at dalvik.system.NativeStart.main(Native Method)
"Binder Thread #3" prio=5 tid=9 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x44821de0 self=0x2b9b78
| sysTid=10585 nice=0 sched=0/0 cgrp=default handle=2857768
| schedstat=( 726806597 708740243 2395 )
at dalvik.system.NativeStart.run(Native Method)
"Binder Thread #2" prio=5 tid=6 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4476c5e8 self=0x13cbf8
| sysTid=10574 nice=0 sched=0/0 cgrp=default handle=1213280
| schedstat=( 767669649 687500005 2512 )
at dalvik.system.NativeStart.run(Native Method)
"Binder Thread #1" prio=5 tid=5 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4476b310 self=0x126f90
| sysTid=10573 nice=0 sched=0/0 cgrp=default handle=1208144
| schedstat=( 749938913 622802748 2497 )
at dalvik.system.NativeStart.run(Native Method)
"Compiler" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x447652a0 self=0x125b80
| sysTid=10572 nice=0 sched=0/0 cgrp=default handle=1251720
| schedstat=( 999145549 669586193 5169 )
at dalvik.system.NativeStart.run(Native Method)
"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 s=N obj=0x447651e8 self=0x121988
| sysTid=10571 nice=0 sched=0/0 cgrp=default handle=1251656
| schedstat=( 16204836 16693113 8 )
at dalvik.system.NativeStart.run(Native Method)
"HeapWorker" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x431a9650 self=0x1317c0
| sysTid=10570 nice=0 sched=0/0 cgrp=default handle=1172520
| schedstat=( 28203003083 34572570617 10984 )
at dalvik.system.NativeStart.run(Native Method)
and
DALVIK THREADS:
"main" prio=5 tid=1 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4001d8c0 self=0xccc8
| sysTid=2428 nice=0 sched=0/0 cgrp=default handle=-1345017816
| schedstat=( 5054412632 4232574644 11781 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4001d950> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1535)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:317)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:790)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:823)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:764)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.Surfaceview.onTouchEvent(Surfaceview.java:319)
at android.view.View.dispatchTouchEvent(View.java:3766)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:936)
at com.android.internal.policy.impl.PhoneWindow$DecorView.superDispatchTouchEvent(PhoneWindow.java:1671)
at com.android.internal.policy.impl.PhoneWindow.superDispatchTouchEvent(PhoneWindow.java:1107)
at android.app.Activity.dispatchTouchEvent(Activity.java:2086)
at com.android.internal.policy.impl.PhoneWindow$DecorView.dispatchTouchEvent(PhoneWindow.java:1655)
at android.view.ViewRoot.handleMessage(ViewRoot.java:1785)
at android.os.Handler.dispatchMessage(Handler.java:99)
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:858)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
at dalvik.system.NativeStart.main(Native Method)
"Thread-448" prio=5 tid=16 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x447e4b40 self=0x2e5960
| sysTid=2892 nice=0 sched=0/0 cgrp=default handle=3037856
| schedstat=( 495635974 519531260 463 )
at java.lang.Object.wait(Native Method)
- waiting on <0x447eeb10> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1535)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:317)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:790)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:823)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:764)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.HUD.updateWithNewLocation(HUD.java:639)
at com.dane.hud.HUD.access$3(HUD.java:618)
at com.dane.hud.HUD$updateEverythingFromGPS.run(HUD.java:573)
"Thread-447" prio=5 tid=15 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x447fb5f0 self=0x2bd690
| sysTid=2890 nice=0 sched=0/0 cgrp=default handle=2873296
| schedstat=( 636688219 727813733 545 )
at java.lang.Object.wait(Native Method)
- waiting on <0x447fb780> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1535)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:317)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:790)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:823)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:764)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.HUD.updateWithNewLocation(HUD.java:639)
at com.dane.hud.HUD.access$3(HUD.java:618)
at com.dane.hud.HUD$updateEverythingFromGPS.run(HUD.java:573)
"Thread-446" prio=5 tid=14 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x44823a68 self=0x2ccac0
| sysTid=2889 nice=0 sched=0/0 cgrp=default handle=2874496
| schedstat=( 774780280 777496325 693 )
at java.lang.Object.wait(Native Method)
- waiting on <0x44786fe8> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1535)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:317)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:790)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:823)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:764)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.HUD.updateWithNewLocation(HUD.java:639)
at com.dane.hud.HUD.access$3(HUD.java:618)
at com.dane.hud.HUD$updateEverythingFromGPS.run(HUD.java:573)
"Thread-445" prio=5 tid=13 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x447f2288 self=0x2e2a80
| sysTid=2888 nice=0 sched=0/0 cgrp=default handle=3026032
| schedstat=( 831634516 815490735 696 )
at java.lang.Object.wait(Native Method)
- waiting on <0x447f2418> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1535)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:317)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:790)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:823)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:764)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.HUD.updateWithNewLocation(HUD.java:639)
at com.dane.hud.HUD.access$3(HUD.java:618)
at com.dane.hud.HUD$updateEverythingFromGPS.run(HUD.java:573)
"Thread-444" prio=5 tid=12 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x447c97c0 self=0x2c4910
| sysTid=2887 nice=0 sched=0/0 cgrp=default handle=2780792
| schedstat=( 1249114988 1195007328 1038 )
at java.lang.Object.wait(Native Method)
- waiting on <0x447cd918> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1535)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:317)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:790)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:823)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.SurfaceView$3.internalLockCanvas(SurfaceView.java:764)
at android.view.SurfaceView$3.lockCanvas(SurfaceView.java:756)
at com.dane.hud.Surfaceview$DrawThread.run(Surfaceview.java:776)
at com.dane.hud.HUD.updateWithNewLocation(HUD.java:639)
at com.dane.hud.HUD.access$3(HUD.java:618)
at com.dane.hud.HUD$updateEverythingFromGPS.run(HUD.java:573)
"Thread-443" prio=5 tid=11 VMWAIT JIT
| group="main" sCount=1 dsCount=0 s=Y obj=0x4480cd28 self=0x2d27b0
| sysTid=2886 nice=0 sched=0/0 cgrp=default handle=2959600
| schedstat=( 1636657703 1482391360 1374 )
at java.util.concurrent.locks.AbstractQueuedSynchronizer.addWaiter(AbstractQueuedSynchronizer.java:~562)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1153)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:185)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
at android.view.Surfa...
Any ideas? I have moved operations to new threads, and maybe I am not calling join(); on them.
Thanks for any help.
In here:
http://developer.android.com/guide/practices/design/responsiveness.html
ANR is when the main thread is blocking on something, so long operation is always advised to do it in the child thread:
TO QUOTE:
Therefore any method that runs in the main thread should do as little work as possible. In particular, Activities should do as little as possible to set up in key life-cycle methods such as onCreate() and onResume(). Potentially long running operations such as network or database operations, or computationally expensive calculations such as resizing bitmaps should be done in a child thread (or in the case of databases operations, via an asynchronous request). However, this does not mean that your main thread should block while waiting for the child thread to complete — nor should you call Thread.wait() or Thread.sleep(). Instead of blocking while waiting for a child thread to complete, your main thread should provide a Handler for child threads to post back to upon completion. Designing your application in this way will allow your main thread to remain responsive to input and thus avoid ANR dialogs caused by the 5 second input event timeout. These same practices should be followed for any other threads that display UI, as they are also subject to the same timeouts.
I understand it is not easy, but the recommendation from above is that UI should be done not in the main thread.
On the other hand, you main thread is in "WAIT" state, meaning non-async operation is used. Perhaps u want to try the async option - which should result in TIMED_WAIT state, as in the following:
Android - how do I investigate an ANR?
(whose main thread is ok).
But like discussed here:
http://groups.google.com/group/android-ndk/browse_thread/thread/84d6a9be21f4e579/b83537161b96da82?q=%22Bitmap+creation+and+composition+in+native+code%22#b83537161b96da82
your problem I suspect is because bitmap painting takes too long between lockCanvas() and unlockCanvas() - perhaps you might want to break the bitmap update into smaller pieces? And within the same discussion is also mentioned use of JNI/NDK to do the bitmap calculation - which should not be done inside the Java-based bitmap update method - if it takes too long to do the calculation.
Recommended read:
http://obviam.net/index.php/the-android-game-loop/
Thanks.
Based on the logs, the only reason I can think of that could have triggered an ANR is:
As far as i know, usually in Java every thread is associated with 2 components. One being Program counter and the other being Garbage Collector. So every thread will have a gc monitor happening throughout.
at java.lang.Object.wait(Native Method) - waiting on <0x4001d950> (a java.lang.VMThread)
VMThreads are ideally used to handle this aspect of monitoring gc, almost parallelly. So what i could think of, for your scenario, is SurfaceViewis trying to acquire a lock but is unable to because VMThread is holding the lock, unreleased yet (may be due to some major GC op), thus waiting for vmthread to release the lock.
You might want to check your main log dump which has gc activities logged, that might give you a better picture as to why gc was hogging this threads CPU time so much and then app profiling may help. Jus check.
链接地址: http://www.djcxy.com/p/61974.html