Login/Register
ANR in random usage of application
Asked Answered
androidandroid-activitylibcandroid-anr-dialogandroid-ndk-r5
T

1

8

I have an VOIP application and the engine part is C(NDK) Level.On random usage of application i end with an ANR pointing to " at android.os.MessageQueue.nativePollOnce(Native Method)".
Using android-ndk-r5

ANR Traces:

----- pid 13735 at 2013-05-23 15:56:47 -----
Cmd line: com.myapp.voip

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41315508 self=0x413058e8
  | sysTid=13735 nice=0 sched=0/0 cgrp=apps handle=1074442032
  | schedstat=( 23115964360 3706387400 21258 ) utm=1651 stm=660 core=3
  #00  pc 0000da70  /system/lib/libc.so (epoll_wait+12)
  #01  pc 00014899  /system/lib/libutils.so (android::Looper::pollInner(int)+96)
  #02  pc 00014b01  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+104)
  #03  pc 00063443  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001de70  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004d0c3  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+394)
  #06  pc 000272a0  /system/lib/libdvm.so
  #07  pc 0002bba8  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+180)
  #08  pc 0005faf7  /system/lib/libdvm.so (dvmInvokeMethod(Object*, Method const*, ArrayObject*, ArrayObject*, ClassObject*, bool)+374)
  #09  pc 0006709d  /system/lib/libdvm.so
  #10  pc 000272a0  /system/lib/libdvm.so
  #11  pc 0002bba8  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+180)
  #12  pc 0005f831  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+272)
  #13  pc 000496b3  /system/lib/libdvm.so
  #14  pc 0004c451  /system/lib/libandroid_runtime.so
  #15  pc 0004d557  /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, char const*)+390)
  #16  pc 00000dcf  /system/bin/app_process
  #17  pc 00017123  /system/lib/libc.so (__libc_init+38)
  #18  pc 00000b34  /system/bin/app_process
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:125)
  at android.os.Looper.loop(Looper.java:124)
  at android.app.ActivityThread.main(ActivityThread.java:4898)
  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:1006)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:773)
  at dalvik.system.NativeStart.main(Native Method)

Edit on 05-06-2013 ADB Logs

05-23 15:56:27.704 E/BufferQueue( 1900): [com.myapp.voip/com.myapp.voip.SettingsActivity] dequeueBuffer: SurfaceTexture has been abandoned!

05-23 15:56:27.704 E/SurfaceTextureClient(13735): dequeueBuffer failed (No such device)
05-23 15:56:27.719 E/ViewRootImpl(13735): Could not lock surface

05-23 15:56:27.719 E/ViewRootImpl(13735): java.lang.IllegalArgumentException

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.Surface.lockCanvasNative(Native Method)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.Surface.lockCanvas(Surface.java:88)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.ViewRootImpl.drawSoftware(ViewRootImpl.java:2312)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.ViewRootImpl.draw(ViewRootImpl.java:2275)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.ViewRootImpl.performDraw(ViewRootImpl.java:2143)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:1954)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1110)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:4470)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.Choreographer$CallbackRecord.run(Choreographer.java:725)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.Choreographer.doCallbacks(Choreographer.java:555)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.Choreographer.doFrame(Choreographer.java:525)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:711)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.os.Handler.handleCallback(Handler.java:615)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.os.Handler.dispatchMessage(Handler.java:92)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.os.Looper.loop(Looper.java:137)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at android.app.ActivityThread.main(ActivityThread.java:4898)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at java.lang.reflect.Method.invokeNative(Native Method)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at java.lang.reflect.Method.invoke(Method.java:511)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1006)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:773)

05-23 15:56:27.719 E/ViewRootImpl(13735):   at dalvik.system.NativeStart.main(Native Method)

05-23 15:56:27.869 D/STATUSBAR-NetworkController( 2535): onDataActivity: direction=3

05-23 15:56:27.874 D/STATUSBAR-NetworkController( 2535): refreshSignalCluster:2

05-23 15:56:27.874 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:27.879 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:27.879 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0



05-23 15:56:45.014 D/STATUSBAR-NetworkController( 2535): onDataActivity: direction=0

05-23 15:56:45.019 D/STATUSBAR-NetworkController( 2535): refreshSignalCluster:2

05-23 15:56:45.019 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:45.024 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:45.024 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:46.024 D/STATUSBAR-NetworkController( 2535): onDataActivity: direction=2

05-23 15:56:46.029 D/STATUSBAR-NetworkController( 2535): refreshSignalCluster:2

05-23 15:56:46.029 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:46.029 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:46.029 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:46.674 I/InputReader( 2272): Touch event's action is 0x0 (deviceType=0) [pCnt=1, s=0.1171 ]

05-23 15:56:46.729 I/InputReader( 2272): Touch event's action is 0x1 (deviceType=0) [pCnt=1, s=]

05-23 15:56:46.854 I/InputReader( 2272): Touch event's action is 0x0 (deviceType=0) [pCnt=1, s=0.1172 ]

05-23 15:56:46.899 I/InputReader( 2272): Touch event's action is 0x1 (deviceType=0) [pCnt=1, s=]

05-23 15:56:47.004 I/InputReader( 2272): Touch event's action is 0x0 (deviceType=0) [pCnt=1, s=0.1173 ]

05-23 15:56:47.029 D/STATUSBAR-NetworkController( 2535): onDataActivity: direction=0

05-23 15:56:47.029 D/STATUSBAR-NetworkController( 2535): refreshSignalCluster:2

05-23 15:56:47.029 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:47.029 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:47.029 D/STATUSBAR-SignalClusterView( 2535): mSeparateMobileGroup=0

05-23 15:56:47.044 I/InputReader( 2272): Touch event's action is 0x1 (deviceType=0) [pCnt=1, s=]

05-23 15:56:47.074 I/InputDispatcher( 2272): Application is not responding. It has been 20018.8ms since event, 20018.4ms since wait started.  Reason: Waiting because there is no touchable window that can handle the event but there is focused application that may eventually add a new window when it finishes starting up.

05-23 15:56:47.149 I/Process ( 2272): Sending signal. PID: 13735 SIG: 3

05-23 15:56:47.149 I/dalvikvm(13735): threadid=3: reacting to signal 3

05-23 15:56:47.189 I/dalvikvm(13735): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:47.189 I/Process ( 2272): Sending signal. PID: 2272 SIG: 3

05-23 15:56:47.189 I/dalvikvm( 2272): threadid=3: reacting to signal 3

05-23 15:56:47.779 E/uevent.c( 2272): !@uevent_next_event: poll - nr=-1, fds.revents=0x0

05-23 15:56:47.869 E/Sensors ( 2272): poll() failed (Interrupted system call)

05-23 15:56:47.889 I/Process ( 2272): Sending signal. PID: 2719 SIG: 3

05-23 15:56:47.889 I/dalvikvm( 2719): threadid=3: reacting to signal 3

05-23 15:56:47.899 I/dalvikvm( 2272): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:47.899 I/Process ( 2272): Sending signal. PID: 2535 SIG: 3

05-23 15:56:47.899 I/dalvikvm( 2535): threadid=3: reacting to signal 3

05-23 15:56:47.984 I/dalvikvm( 2535): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:47.984 I/Process ( 2272): Sending signal. PID: 2556 SIG: 3

05-23 15:56:47.984 I/dalvikvm( 2556): threadid=3: reacting to signal 3

05-23 15:56:47.994 I/dalvikvm( 2719): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:47.994 I/Process ( 2272): Sending signal. PID: 2736 SIG: 3

05-23 15:56:47.994 I/dalvikvm( 2736): threadid=3: reacting to signal 3

05-23 15:56:48.024 I/dalvikvm( 2736): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:48.024 I/Process ( 2272): Sending signal. PID: 2751 SIG: 3

05-23 15:56:48.024 I/dalvikvm( 2751): threadid=3: reacting to signal 3

05-23 15:56:48.024 I/dalvikvm( 2556): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:48.024 I/Process ( 2272): Sending signal. PID: 2765 SIG: 3

05-23 15:56:48.024 I/dalvikvm( 2765): threadid=3: reacting to signal 3

05-23 15:56:48.049 I/dalvikvm( 2751): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:48.059 I/dalvikvm( 2765): Wrote stack traces to '/data/anr/traces.txt'

05-23 15:56:48.459 D/dalvikvm( 2272): GC_CONCURRENT freed 2075K, 7% free 94406K/100551K, paused 23ms+36ms, total 240ms

05-23 15:56:48.459 D/dalvikvm( 2272): WAIT_FOR_CONCURRENT_GC blocked 201ms

05-23 15:56:48.594 D/dalvikvm( 2272): WAIT_FOR_CONCURRENT_GC blocked 0ms

05-23 15:56:48.824 D/dalvikvm( 2272): GC_EXPLICIT freed 737K, 6% free 94612K/100551K, paused 5ms+38ms, total 227ms

05-23 15:56:49.409 W/PowerManagerService( 2272): Timer 0x3->0x3|0x0

05-23 15:56:49.409 D/PowerManagerService( 2272): setTimeoutLocked::SmartSleep : after589500

05-23 15:56:49.414 E/android.os.Debug( 2272): !@Dumpstate > dumpstate -k -t -z -d -o /data/log/dumpstate_app_anr

Not sure which thread is stuck at this point. Whats going on here?

Tophole answered 30/5, 2013 at 14:31 Comment(7)
Can you also add the logcat lines from the ActivityManager ANR report? – Delanos
Mabye you are using the same object for locking a critical sections of two threads "your running thread" and Main Thread (can be run in Runnable, onReceive in BroadcastReceiver, handleMessage in Handler). – Dachy
Can you tell me what you are trying to do with your SurfaceView? – Villalpando
@Delanos abd logs added! – Tophole
@naif.alziadna what do mean "same object"? Issue happens randomly! – Tophole
@Villalpando i just have some activities i do not do anything with SurfaceView – Tophole
The object that provides the lock. what you are doing in your onCreate/onStart of your SettingsActivity? – Dachy
E
1

I think the most possible answer to your problem is that you are doing something with the surface in native code.

Especially if you are developing some SIP video call feature.

If the native code does not handle the locking of the canvas/surface correctly, you will have this problem.

Since you might not able to show your souce code here, I can only recommend you to check if any code is accessing the surface in native or other Java thread.

Etti answered 13/8, 2013 at 16:26 Comment(1)
@ Robin as i told before i do not use surface in JAVA/NATIVE.All i use is activities ,no canvas etc. – Tophole

© 2022 - 2024 — McMap. All rights reserved.