6

I've got an ANR happening, while trying to open 2 separate activities. Very sporadic, only certain users, haven't been able to replicate on any of our test hardware. Both reports have a series of nondescript threads, and two background threads of ours rightly waiting on their notifier locks. The main thread is doing this, in both cases:

"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x41790710 self=0x41775c90
| sysTid=347 nice=0 sched=0/0 cgrp=apps handle=1074003964
| state=S schedstat=( 0 0 0 ) utm=10817 stm=2453 core=0
#00 pc 0001b6e4 /system/lib/libc.so (__ioctl+8)
#01 pc 0002be67 /system/lib/libc.so (ioctl+14)
#02 pc 0001b929 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001c0c7 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 00001451 /system/lib/libsystem_server.so (system_init+384)
#05 pc 00020b4c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#06 pc 000516ab /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
#07 pc 00029fe0 /system/lib/libdvm.so
#08 pc 0002e9a4 /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#09 pc 00063aeb /system/lib/libdvm.so (dvmInvokeMethod(Object*, Method const*, ArrayObject*, ArrayObject*, ClassObject*, bool)+350)
#10 pc 0006b80f /system/lib/libdvm.so
#11 pc 00029fe0 /system/lib/libdvm.so
#12 pc 0002e9a4 /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#13 pc 0006382d /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+292)
#14 pc 0004d27f /system/lib/libdvm.so
#15 pc 0005477b /system/lib/libandroid_runtime.so
#16 pc 00055ca3 /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, char const*)+378)
#17 pc 0000105b /system/bin/app_process
#18 pc 0000ddf7 /system/lib/libc.so (__libc_init+50)
#19 pc 00000d7c /system/bin/app_process
at com.android.server.SystemServer.init1(Native Method)
at com.android.server.SystemServer.main(SystemServer.java:2012)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:525)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1187)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1003)
at dalvik.system.NativeStart.main(Native Method)

Here is the app dump:

"AsyncTask #4" prio=5 tid=17 WAIT
| group="main" sCount=1 dsCount=0 obj=0x424f4178 self=0x5bad64c8
| sysTid=2943 nice=0 sched=0/0 cgrp=apps handle=1537449072
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x424f4298> (a java.lang.VMThread) held by tid=17 (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)

"Thread-8753" prio=5 tid=1 VMWAIT
| group="main" sCount=1 dsCount=0 obj=0x42647520 self=0x413fa188
| sysTid=2903 nice=0 sched=0/0 cgrp=apps handle=1074526288
| schedstat=( 0 0 0 ) utm=27 stm=8 core=0
#00 pc 0000dce0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 00012ef4 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 00012f50 /system/lib/libc.so (__pthread_cond_timedwait+60)
#03 pc 0004b12f /system/lib/libdvm.so
#04 pc 0004e191 /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, char const*)+416)
#05 pc 00000dcf /system/bin/app_process
#06 pc 000171d3 /system/lib/libc.so (__libc_init+38)
#07 pc 00000b34 /system/bin/app_process
at dalvik.system.NativeStart.run(Native Method)

"AsyncTask #3" prio=5 tid=15 WAIT
| group="main" sCount=1 dsCount=0 obj=0x424dc8a0 self=0x5c0252c0
| sysTid=2941 nice=0 sched=0/0 cgrp=apps handle=1516141776
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x424dc9c0> (a java.lang.VMThread) held by tid=15 (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)

"Thread-8740" prio=5 tid=10 WAIT
| group="main" sCount=1 dsCount=0 obj=0x424860c8 self=0x5a5e1d88
| sysTid=2929 nice=0 sched=0/0 cgrp=apps handle=1543661352
| schedstat=( 0 0 0 ) utm=0 stm=0 core=1
at java.lang.Object.wait(Native Method)
- waiting on <0x42486340> (a java.lang.VMThread) held by tid=10 (Thread-8740)
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 com.my_foo2.Bluetooth.ModelAccessorNew$SingleStuffProcessingThread.run(ModelAccessorNew.java:139)

"pool-1-thread-2" prio=5 tid=13 WAIT
| group="main" sCount=1 dsCount=0 obj=0x421cb830 self=0x5a5e1730
| sysTid=2927 nice=0 sched=0/0 cgrp=apps handle=1094606048
| schedstat=( 0 0 0 ) utm=11 stm=4 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x421cbd98> (a java.lang.VMThread) held by tid=13 (pool-1-thread-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)

"Thread-8735" prio=5 tid=12 WAIT
| group="main" sCount=1 dsCount=0 obj=0x4216e7f0 self=0x413e4f20
| sysTid=2926 nice=0 sched=0/0 cgrp=apps handle=1094604160
| schedstat=( 0 0 0 ) utm=0 stm=0 core=1
at java.lang.Object.wait(Native Method)
- waiting on <0x4216e918> (a java.lang.Object)
at java.lang.Object.wait(Object.java:364)
at com.my_foo2.Persistence.Factories.StuffFactory$CalculationThread.run(StuffFactory.java:97)

"pool-1-thread-1" prio=5 tid=11 WAIT
| group="main" sCount=1 dsCount=0 obj=0x42144498 self=0x413e46d0
| sysTid=2924 nice=0 sched=0/0 cgrp=apps handle=1094601544
| schedstat=( 0 0 0 ) utm=18 stm=5 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x421447e8> (a java.lang.VMThread) held by tid=11 (pool-1-thread-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)

"Binder_2" prio=5 tid=9 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x42097bd8 self=0x5183e668
| sysTid=2915 nice=0 sched=0/0 cgrp=apps handle=1538927224
| schedstat=( 0 0 0 ) utm=0 stm=0 core=1
#00 pc 0000cbd0 /system/lib/libc.so (__ioctl+8)
#01 pc 00028035 /system/lib/libc.so (ioctl+16)
#02 pc 00016b6d /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+124)
#03 pc 0001731f /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 0001af55 /system/lib/libbinder.so
#05 pc 00011087 /system/lib/libutils.so (android::Thread::_threadLoop(void*)+114)
#06 pc 0004c985 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+44)
#07 pc 00010bed /system/lib/libutils.so
#08 pc 00012eb0 /system/lib/libc.so (__thread_entry+48)
#09 pc 00012608 /system/lib/libc.so (pthread_create+172)
at dalvik.system.NativeStart.run(Native Method)

"Binder_1" prio=5 tid=8 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x420978a8 self=0x5183e010
| sysTid=2914 nice=0 sched=0/0 cgrp=apps handle=1538927416
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
#00 pc 0000cbd0 /system/lib/libc.so (__ioctl+8)
#01 pc 00028035 /system/lib/libc.so (ioctl+16)
#02 pc 00016b6d /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+124)
#03 pc 0001731f /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 0001af55 /system/lib/libbinder.so
#05 pc 00011087 /system/lib/libutils.so (android::Thread::_threadLoop(void*)+114)
#06 pc 0004c985 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+44)
#07 pc 00010bed /system/lib/libutils.so
#08 pc 00012eb0 /system/lib/libc.so (__thread_entry+48)
#09 pc 00012608 /system/lib/libc.so (pthread_create+172)
at dalvik.system.NativeStart.run(Native Method)

"FinalizerWatchdogDaemon" daemon prio=5 tid=7 WAIT
| group="system" sCount=1 dsCount=0 obj=0x420940e8 self=0x412487a8
| sysTid=2913 nice=0 sched=0/0 cgrp=apps handle=1538927528
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x41414ec8> (a java.lang.Daemons$FinalizerWatchdogDaemon)
at java.lang.Object.wait(Object.java:364)
at java.lang.Daemons$FinalizerWatchdogDaemon.run(Daemons.java:214)
at java.lang.Thread.run(Thread.java:856)

"FinalizerDaemon" daemon prio=5 tid=6 WAIT
| group="system" sCount=1 dsCount=0 obj=0x42093f90 self=0x41248358
| sysTid=2912 nice=0 sched=0/0 cgrp=apps handle=1538927616
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x41403690> (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:169)
at java.lang.Thread.run(Thread.java:856)

"ReferenceQueueDaemon" daemon prio=5 tid=5 WAIT
| group="system" sCount=1 dsCount=0 obj=0x42093e28 self=0x5bb9f218
| sysTid=2911 nice=0 sched=0/0 cgrp=apps handle=1538927752
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x414035b8> 
at java.lang.Object.wait(Object.java:364)
at java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:129)
at java.lang.Thread.run(Thread.java:856)

"Compiler" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x42093d38 self=0x400173b8
| sysTid=2910 nice=0 sched=0/0 cgrp=apps handle=1087627008
| schedstat=( 0 0 0 ) utm=9 stm=4 core=1
#00 pc 0000dce0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 00012ef4 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 00012f50 /system/lib/libc.so (__pthread_cond_timedwait+60)
#03 pc 0006e7d7 /system/lib/libdvm.so
#04 pc 0005425b /system/lib/libdvm.so
#05 pc 00012eb0 /system/lib/libc.so (__thread_entry+48)
#06 pc 00012608 /system/lib/libc.so (pthread_create+172)
at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 obj=0x42093c40 self=0x40cfa8a8
| sysTid=2909 nice=0 sched=0/0 cgrp=apps handle=1087816224
| schedstat=( 0 0 0 ) utm=1 stm=0 core=0
at dalvik.system.NativeStart.run(Native Method)

"GC" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x42093b60 self=0x40d6bdd0
| sysTid=2907 nice=0 sched=0/0 cgrp=apps handle=1538927840
| schedstat=( 0 0 0 ) utm=0 stm=0 core=0
#00 pc 0000dce0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 00012ef4 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 00012f50 /system/lib/libc.so (__pthread_cond_timedwait+60)
#03 pc 0006d5db /system/lib/libdvm.so
#04 pc 0005425b /system/lib/libdvm.so
#05 pc 00012eb0 /system/lib/libc.so (__thread_entry+48)
#06 pc 00012608 /system/lib/libc.so (pthread_create+172)
at dalvik.system.NativeStart.run(Native Method)

----- end 2903 -----

The other thing that's weird is that this is the only user code I'm seeing. I've tracked where these two threads get started and its during onCreate events of various activities, but the activities themselves aren't running, or at least not visible in the trace. Any ideas would be appreciated.

kolosy
  • 3,029
  • 3
  • 29
  • 48
  • Just brainstorming, but could this be an onCreate of a new activity in an existing process which had some threads from a previous Activity still running, and doing something that is somehow blocking the startup of the new one? The other thing I'd be curious about would be the affected systems - anything perhaps weird about those (custom rom, "lesser" vendor, or *recent* upgrade?) – Chris Stratton Dec 10 '13 at 18:11
  • Possible, but not likely. One bit of info I forgot to include is that this is happening after an auto-update through the Play store, on first launch, so the likelihood of leftover threads from a previous execution is slim. Also - for users where its repeatable, it's rock solid repeatable. Just not in the lab :-/ – kolosy Dec 10 '13 at 18:15
  • On what devices/versions? – Chris Stratton Dec 10 '13 at 18:16
  • 4.1, 4.2, 4.3 HTC One, Galaxy Nexus, Galaxy S3 – kolosy Dec 10 '13 at 18:18
  • 1
    I have the exact same problem. Will report if i have any answeres. – Yaadm Jun 19 '14 at 07:30

0 Answers0