Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

ANR crash after a few seconds when stopping at breakpoint in main thread (AOSP - RK3288 box)

I have an RK3288 box, for which I am developing an app.

I'm having an issue which is causing a lot of headache to me. I can't debug anything all.
Every-time I attach the debugger, when I hit a breakpoint which is on main thread, my app crashes after a few seconds. Below is the logcat when that happens:

05-02 20:52:39.734 459-534/system_process I/InputDispatcher: Application is not responding: Window{3026b626 u0 com.kushtrim.playground/com.kushtrim.playground.MainActivity}.  It has been 5001.8ms since event, 5001.6ms since wait started.  Reason: Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 17.  Wait queue head age: 5505.1ms.
05-02 20:52:39.794 459-534/system_process I/WindowManagerService: Input event dispatching timed out sending to com.kushtrim.playground/com.kushtrim.playground.MainActivity.  Reason: Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 17.  Wait queue head age: 5505.1ms.
05-02 20:52:39.811 459-482/system_process I/Process: Sending signal. PID: 8790 SIG: 3
05-02 20:52:39.812 8790-8799/com.kushtrim.playground I/art: Thread[5,tid=8799,WaitingInMainSignalCatcherLoop,Thread*=0xb7294b58,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:39.970 459-482/system_process I/Process: Sending signal. PID: 459 SIG: 3
05-02 20:52:39.970 459-468/system_process I/art: Thread[5,tid=468,WaitingInMainSignalCatcherLoop,Thread*=0xb7113410,peer=0x12c020a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:39.970 8790-8799/com.kushtrim.playground I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:40.123 459-478/system_process E/SensorsHal: poll() failed (Interrupted system call)
05-02 20:52:40.824 459-981/system_process E/WifiHAL: Error polling socket
05-02 20:52:40.900 6611-6661/com.solaborate.hello D/Webrtc_calls: SocketIoStatus conected: true , socketId: 9U55YZnsB0EeSDcHACui
05-02 20:52:41.018 459-482/system_process I/Process: Sending signal. PID: 852 SIG: 3
05-02 20:52:41.019 852-864/com.android.phone I/art: Thread[5,tid=864,WaitingInMainSignalCatcherLoop,Thread*=0xb7113410,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:41.023 459-1442/system_process W/ActivityManagerService: Missing app error report, app = com.kushtrim.playground crashing = false notResponding = true
05-02 20:52:41.028 459-468/system_process I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:41.028 459-482/system_process I/Process: Sending signal. PID: 811 SIG: 3
05-02 20:52:41.029 811-820/com.android.inputmethod.latin I/art: Thread[5,tid=820,WaitingInMainSignalCatcherLoop,Thread*=0xb7112928,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:41.152 811-820/com.android.inputmethod.latin I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:41.152 459-482/system_process I/Process: Sending signal. PID: 628 SIG: 3
05-02 20:52:41.152 628-636/com.android.systemui I/art: Thread[5,tid=636,WaitingInMainSignalCatcherLoop,Thread*=0xb7112928,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:41.209 852-864/com.android.phone I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:41.209 459-482/system_process I/Process: Sending signal. PID: 712 SIG: 3
05-02 20:52:41.209 712-719/com.cghs.stresstest I/art: Thread[5,tid=719,WaitingInMainSignalCatcherLoop,Thread*=0xb7112a18,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:41.286 712-719/com.cghs.stresstest I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:41.286 459-482/system_process I/Process: Sending signal. PID: 591 SIG: 3
05-02 20:52:41.286 591-600/android.process.media I/art: Thread[5,tid=600,WaitingInMainSignalCatcherLoop,Thread*=0xb7112928,peer=0x12c000a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:41.313 628-636/com.android.systemui I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:41.396 591-600/android.process.media I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:41.554 459-913/system_process W/ActivityManagerService: Missing app error report, app = com.kushtrim.playground crashing = false notResponding = true
05-02 20:52:42.094 459-944/system_process W/ActivityManagerService: Missing app error report, app = com.kushtrim.playground crashing = false notResponding = true
05-02 20:52:43.304 459-1982/system_process W/ActivityManagerService: Missing app error report, app = com.kushtrim.playground crashing = false notResponding = true
05-02 20:52:43.869 459-482/system_process I/art: Explicit concurrent mark sweep GC freed 58037(3MB) AllocSpace objects, 10(257KB) LOS objects, 33% free, 19MB/28MB, paused 811us total 53.345ms
05-02 20:52:43.883 459-482/system_process W/ProcessCpuTracker: Skipping unknown process pid 9185
05-02 20:52:44.189 459-4388/system_process W/ActivityManagerService: Missing app error report, app = com.kushtrim.playground crashing = false notResponding = true
05-02 20:52:44.418 459-482/system_process I/Process: Sending signal. PID: 1155 SIG: 3
05-02 20:52:44.418 1155-1164/com.waxrain.airplaydmr I/art: Thread[5,tid=1164,WaitingInMainSignalCatcherLoop,Thread*=0xb7112928,peer=0x32c070a0,"Signal Catcher"]: reacting to signal 3
05-02 20:52:44.540 1155-1164/com.waxrain.airplaydmr I/art: Wrote stack traces to '/data/anr/traces.txt'
05-02 20:52:44.549 459-482/system_process E/ActivityManagerService: ANR in com.kushtrim.playground (com.kushtrim.playground/.MainActivity)
                                                                    PID: 8790
                                                                    Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 17.  Wait queue head age: 5505.1ms.)
                                                                    Load: 1.48 / 1.36 / 1.86
                                                                    CPU usage from 567ms to -4733ms ago:
                                                                      31% 459/system_server: 14% user + 17% kernel / faults: 6486 minor 5 major
                                                                      0% 164/debuggerd: 0% user + 0% kernel / faults: 3474 minor 5 major
                                                                      8.6% 161/surfaceflinger: 5.6% user + 3% kernel / faults: 629 minor
                                                                      0% 852/com.android.phone: 0% user + 0% kernel / faults: 2463 minor
                                                                      2.8% 8790/com.kushtrim.playground: 1.1% user + 1.7% kernel / faults: 1497 minor
                                                                      0.6% 628/com.android.systemui: 0.3% user + 0.2% kernel / faults: 1800 minor 2 major
                                                                      0% 811/com.android.inputmethod.latin: 0% user + 0% kernel / faults: 2089 minor
                                                                      2.2% 1155/com.waxrain.airplaydmr: 1.5% user + 0.7% kernel / faults: 1754 minor
                                                                      2% 174/adbd: 0.1% user + 1.8% kernel / faults: 564 minor
                                                                      0% 591/android.process.media: 0% user + 0% kernel / faults: 2149 minor 1 major
                                                                      0% 712/com.cghs.stresstest: 0% user + 0% kernel / faults: 1984 minor
                                                                      0.9% 69/cfinteractive: 0% user + 0.9% kernel
                                                                      0.5% 153/dhd_dpc: 0% user + 0.5% kernel
                                                                      0.5% 155/logd: 0.3% user + 0.1% kernel
                                                                      0.3% 68/rk-fb: 0% user + 0.3% kernel
                                                                      0.3% 152/dhd_watchdog_th: 0% user + 0.3% kernel
                                                                      0.1% 8/rcu_preempt: 0% user + 0.1% kernel
                                                                      0.1% 14/ksoftirqd/1: 0% user + 0.1% kernel
                                                                      0.1% 19/ksoftirqd/2: 0% user + 0.1% kernel
                                                                      0.1% 24/ksoftirqd/3: 0% user + 0.1% kernel
                                                                      0.1% 67/fb-vsync: 0% user + 0.1% kernel
                                                                      0.1% 110/mmcqd/0: 0% user + 0.1% kernel
                                                                      0.1% 122/irq/198-mma8452: 0% user + 0.1% kernel
                                                                      0.1% 507/mediaserver: 0% user + 0.1% kernel / faults: 12 minor
                                                                      0% 1174/com.android.settings: 0% user + 0% kernel / faults: 22 minor
                                                                      0.1% 1252/wdog2: 0% user + 0.1% kernel
                                                                      0.1% 1486/com.skype.raider: 0.1% user + 0% kernel / faults: 6 minor
                                                                      0.1% 2355/com.tencent.mm:push: 0% user + 0.1% kernel / faults: 331 minor
                                                                      0.1% 4835/wpa_supplicant: 0% user + 0.1% kernel
                                                                      0.1% 6611/com.solaborate.hello: 0.1% user + 0% kernel / faults: 12 minor
                                                                      0% 7891/kworker/2:2: 0% user + 0% kernel
                                                                      0.1% 7974/kworker/0:1: 0% user + 0.1% kernel
                                                                      0.1% 8875/logcat: 0.1% user + 0% kernel
                                                                     +0% 9168/kworker/u8:4: 0% user + 0% kernel
                                                                    19% TOTAL: 8.1% user + 11% kernel + 0.3% iowait + 0% softirq
                                                                    CPU usage from 4062ms to 4577ms later:
                                                                      7.6% 459/system_server: 3.8% user + 3.8% kernel / faults: 27 minor
                                                                        3.8% 482/ActivityManager: 1.9% user + 1.9% kernel
                                                                        1.9% 487/android.display: 1.9% user + 0% kernel
                                                                      5.7% 161/surfaceflinger: 1.9% user + 3.8% kernel / faults: 14 minor
                                                                        1.9% 161/surfaceflinger: 1.9% user + 0% kernel
                                                                        1.9% 314/DispSync: 0% user + 1.9% kernel
                                                                        1.9% 433/surfaceflinger: 0% user + 1.9% kernel
                                                                        1.9% 552/Binder_4: 1.9% user + 0% kernel
                                                                      1.3% 14/ksoftirqd/1: 0% user + 1.3% kernel
                                                                      1.3% 19/ksoftirqd/2: 0% user + 1.3% kernel
                                                                      1.4% 153/dhd_dpc: 0% user + 1.4% kernel
                                                                      1.4% 174/adbd: 0% user + 1.4% kernel / faults: 60 minor
                                                                        1.4% 174/adbd: 1.4% user + 0% kernel
                                                                      1.5% 1155/com.waxrain.airplaydmr: 1.5% user + 0% kernel
                                                                    6.4% TOTAL: 2.4% user + 3.9% kernel

Now, I did some research of my own, and found out in normal conditions ANR is triggered when there is no response to a touch event for more than 5s, which seems to be what's happening here.

While, this is OK for normal operation of the app, this shouldn't happen if I put a breakpoint on an button OnClickListener, but in my case it does.

This doesn't happen to me on any other phone, just in this board.

What can I do to fix this, and debug peacefully at last ?

I should mention that I also have the OS code (AOSP + kernel), and have compiled/installed it myself, so I can modify the OS if needed.

Here are the ANR traces if they help: https://pastebin.com/C3dh9rzK

EDIT:
It seems this is not an issue with the app, but something in OS. I was able to reproduce the crash in a brand new project, in which I just added a button and an OnClickListener. I then put a breakpoint inside the listener, attached the debugger and clicked the button. KA-BOOOM.

like image 488
Rick Sanchez Avatar asked May 02 '17 13:05

Rick Sanchez


1 Answers

Weirdest thing ever, I can't believe how I didn't find out this before. If I run the app from Android Studio using "Debug app" button which runs the app and attaches the debugger, it doesn't crash with ANR. If I run the app normally, and then attach a debugger, the issue above happens. I guess I always did the second.

Knowing that it works in the first instance, I started playing with stuff to get it to work in the second.

Calling this code ( or setting the app as debug in Developer Options ) fixed the issue:

adb shell am set-debug-app --persistent com.kushtrim.playground  

I'm not sure why in this board, setting the debug app is a must if you want to attach debugger, but it's not needed in my Pixel XL. Anyway, issue resolved.

like image 192
Rick Sanchez Avatar answered Sep 19 '22 02:09

Rick Sanchez